Tunnels working again to basic level w/o re-connect or re-dial

hkexnet/hkexnet.go

@@ -532,7 +532,7 @@ func (hc *Conn) Close() (err error) {
 	log.Printf("** Writing closeStat %d at Close()\n", *hc.closeStat)
 	hc.WritePacket(s, CSOExitStatus)
 	err = (*hc.c).Close()
-	logger.LogNotice(fmt.Sprintln("[Conn Closing]"))
+	logger.LogDebug(fmt.Sprintln("[Conn Closing]"))
 	return
 }
 
@@ -602,7 +602,7 @@ func Listen(protocol string, ipport string) (hl HKExListener, e error) {
 	if err != nil {
 		return HKExListener{nil}, err
 	}
-	logger.LogNotice(fmt.Sprintf("[Listening on %s]\n", ipport))
+	logger.LogDebug(fmt.Sprintf("[Listening on %s]\n", ipport))
 	hl.l = l
 	return
 }
@@ -612,7 +612,7 @@ func Listen(protocol string, ipport string) (hl HKExListener, e error) {
 //
 // See go doc net.Listener.Close
 func (hl HKExListener) Close() error {
-	logger.LogNotice(fmt.Sprintln("[Listener Closed]"))
+	logger.LogDebug(fmt.Sprintln("[Listener Closed]"))
 	return hl.l.Close()
 }
 
@@ -632,7 +632,7 @@ func (hl *HKExListener) Accept() (hc Conn, err error) {
 	if err != nil {
 		return Conn{}, err
 	}
-	logger.LogNotice(fmt.Sprintln("[net.Listener Accepted]"))
+	logger.LogDebug(fmt.Sprintln("[net.Listener Accepted]"))
 
 	// Read KEx alg proposed by client
 	var kexAlg KEXAlg
@@ -701,11 +701,11 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 				return 0, io.EOF
 			}
 			if strings.HasSuffix(err.Error(), "use of closed network connection") {
-				logger.LogNotice(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "ctrlStatOp", err)
-			logger.LogErr(etxt)
+			logger.LogDebug(etxt)
 			return 0, errors.New(etxt)
 		}
 		log.Printf("[ctrlStatOp: %v]\n", ctrlStatOp)
@@ -722,11 +722,11 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 				return 0, io.EOF
 			}
 			if strings.HasSuffix(err.Error(), "use of closed network connection") {
-				logger.LogNotice(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "HMAC", err)
-			logger.LogErr(etxt)
+			logger.LogDebug(etxt)
 			return 0, errors.New(etxt)
 		}
 
@@ -736,16 +736,16 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 				return 0, io.EOF
 			}
 			if strings.HasSuffix(err.Error(), "use of closed network connection") {
-				logger.LogNotice(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "payloadLen", err)
-			logger.LogErr(etxt)
+			logger.LogDebug(etxt)
 			return 0, errors.New(etxt)
 		}
 
 		if payloadLen > MAX_PAYLOAD_LEN {
-			logger.LogErr(fmt.Sprintf("[Insane payloadLen:%v]\n", payloadLen))
+			logger.LogDebug(fmt.Sprintf("[Insane payloadLen:%v]\n", payloadLen))
 			hc.Close()
 			return 1, errors.New("Insane payloadLen")
 		}
@@ -757,11 +757,11 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 				return 0, io.EOF
 			}
 			if strings.HasSuffix(err.Error(), "use of closed network connection") {
-				logger.LogNotice(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "payloadBytes", err)
-			logger.LogErr(etxt)
+			logger.LogDebug(etxt)
 			return 0, errors.New(etxt)
 		}
 
@@ -806,45 +806,57 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 				if len(payloadBytes) > 0 {
 					hc.SetStatus(CSOType(binary.BigEndian.Uint32(payloadBytes)))
 				} else {
-					logger.LogErr(fmt.Sprintln("[truncated payload, cannot determine CSOExitStatus]"))
+					logger.LogDebug(fmt.Sprintln("[truncated payload, cannot determine CSOExitStatus]"))
 					hc.SetStatus(CSETruncCSO)
 				}
 				hc.Close()
 			} else if ctrlStatOp == CSOTunSetup {
 				// server side tunnel setup in response to client
-				lport := binary.BigEndian.Uint16(payloadBytes)
+				lport := binary.BigEndian.Uint16(payloadBytes[0:2])
 				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
-				log.Printf("Tunnel setup [%d:%d]\r\n", lport, rport)
+				logger.LogDebug(fmt.Sprintf("Read(): Tunnel setup [%d:%d]", lport, rport))
-				StartServerTunnel(&hc, lport, rport)
+				hc.StartServerTunnel(lport, rport)
 			} else if ctrlStatOp == CSOTunSetupAck {
-				// client side has received ack from server
+				lport := binary.BigEndian.Uint16(payloadBytes[0:2])
-				lport := binary.BigEndian.Uint16(payloadBytes)
 				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
-				log.Printf("Tunnel ack [%d:%d]\r\n", lport, rport)
+				logger.LogDebug(fmt.Sprintf("Read(): Tunnel setup ack [%d:%d]", lport, rport))
-			} else if ctrlStatOp == CSOTunData {
-				lport := binary.BigEndian.Uint16(payloadBytes)
-				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
-				_ = lport
-				//fmt.Printf("[Got CSOTunData: [lport %d:rport %d] data:%v\n", lport, rport, payloadBytes[4:])
-				if hc.tuns[rport] == nil {
-					fmt.Printf("[Invalid rport:%d]\r\n", rport)
-				} else {
-					hc.tuns[rport].Data <- payloadBytes[4:]
-				}
-			} else {
 				hc.dBuf.Write(payloadBytes)
-				//log.Printf("hc.dBuf: %s\n", hex.Dump(hc.dBuf.Bytes()))
+			} else if ctrlStatOp == CSOTunRefused {
+				// client side has been told nothing is listening on rport
+				lport := binary.BigEndian.Uint16(payloadBytes[0:2])
+				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
+				logger.LogDebug(fmt.Sprintf("Read(): Tunnel refused [%d:%d]", lport, rport))
+			} else if ctrlStatOp == CSOTunDisconn {
+				// server side's rport has disconnected (server lost)
+				lport := binary.BigEndian.Uint16(payloadBytes[0:2])
+				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
+				logger.LogDebug(fmt.Sprintf("Read(): Tunnel server disconnected [%d:%d]", lport, rport))
+			} else if ctrlStatOp == CSOTunHangup {
+				// client side's lport has hung up
+				lport := binary.BigEndian.Uint16(payloadBytes[0:2])
+				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
+				logger.LogDebug(fmt.Sprintf("Read(): Tunnel client hung up [%d:%d]", lport, rport))
+			} else if ctrlStatOp == CSOTunData {
+				lport := binary.BigEndian.Uint16(payloadBytes[0:2])
+				rport := binary.BigEndian.Uint16(payloadBytes[2:4])
+				//fmt.Printf("[Got CSOTunData: [lport %d:rport %d] data:%v\n", lport, rport, payloadBytes[4:])
+				logger.LogDebug(fmt.Sprintf("[Writing data to rport [%d:%d] %v", lport, rport, payloadBytes[4:]))
+				hc.tuns[rport].Data <- payloadBytes[4:]
+			} else if ctrlStatOp == CSONone {
+				hc.dBuf.Write(payloadBytes)
+			} else {
+				logger.LogDebug(fmt.Sprintf("[Unknown CSOType:%d]", ctrlStatOp))
 			}
 
 			hTmp := hc.rm.Sum(nil)[0:HMAC_CHK_SZ]
 			log.Printf("<%04x) HMAC:(i)%s (c)%02x\r\n", decryptN, hex.EncodeToString([]byte(hmacIn[0:])), hTmp)
 
 			if *hc.closeStat == CSETruncCSO {
-				logger.LogErr(fmt.Sprintln("[cannot verify HMAC]"))
+				logger.LogDebug(fmt.Sprintln("[cannot verify HMAC]"))
 			} else {
 				// Log alert if hmac didn't match, corrupted channel
 				if !bytes.Equal(hTmp, []byte(hmacIn[0:])) /*|| hmacIn[0] > 0xf8*/ {
-					logger.LogErr(fmt.Sprintln("** ALERT - detected HMAC mismatch, possible channel tampering **"))
+					logger.LogDebug(fmt.Sprintln("** ALERT - detected HMAC mismatch, possible channel tampering **"))
 					_, _ = (*hc.c).Write([]byte{CSOHmacInvalid})
 				}
 			}
@@ -881,25 +893,6 @@ func (hc *Conn) WritePacket(b []byte, ctrlStatOp byte) (n int, err error) {
 		return 0, errors.New("Secure chan not ready for writing")
 	}
 
-	if ctrlStatOp == CSOTunSetup {
-		// Client-side tunnel setup
-		lport := binary.BigEndian.Uint16(b)
-		rport := binary.BigEndian.Uint16(b[2:4])
-		// spawn workers to listen for data and tunnel events
-		// via channel comms to hc.tuns[rport].tunCtl
-		StartClientTunnel(hc, lport, rport)
-		// CSOTunSetup is written through to server side,
-		// see hc.Read()
-	} else if ctrlStatOp == CSOTunSetupAck {
-		lport := binary.BigEndian.Uint16(b)
-		rport := binary.BigEndian.Uint16(b[2:4])
-		if lport == 0 || rport == 0 {
-			log.Printf("Responded with tunnel setup nak [%d:%d]\r\n", lport, rport)
-		} else {
-			log.Printf("Responded with tunnel setup ack [%d:%d]\r\n", lport, rport)
-		}
-	}
-
 	//Padding prior to encryption
 	padSz := (rand.Intn(PAD_SZ) / 2) + (PAD_SZ / 2)
 	padLen := padSz - ((len(b) + padSz) % padSz)

hkexnet/hkextun.go

@@ -11,11 +11,11 @@ package hkexnet
 import (
 	"bytes"
 	"encoding/binary"
-	//"fmt"
+	"fmt"
-	//"io"
+	"io"
-	//"log"
 	"net"
-	//"blitter.com/go/hkexsh/logger"
+
+	"blitter.com/go/hkexsh/logger"
 )
 
 type (
@@ -39,203 +39,205 @@ type (
 
 	// TunEndpoint [securePort:peer:dataPort]
 	TunEndpoint struct {
-		Rport uint16      // Names are from client's perspective
+		Rport  uint16      // Names are from client's perspective
-		Lport uint16      // ... ie., RPort is on server, LPort is on client
+		Lport  uint16      // ... ie., RPort is on server, LPort is on client
-		Peer  string      //net.Addr
+		Peer   string      //net.Addr
-		Ctl   chan<- rune //See TunCtl_* consts
+		//Status byte        //Last status of tunnel (eg., CSOTunSetupAck)
-		Data  chan []byte
+		Ctl    chan<- rune //See TunCtl_* consts
+		Data   chan []byte
 	}
 
-	TunPacket struct {
+	//TunPacket struct {
-		n    uint32
+	//	n    uint32
-		data []byte
+	//	data []byte
-	}
+	//}
 )
 
-func StartClientTunnel(hc *Conn, lport, rport uint16) {
+func (hc *Conn) InitTunEndpoint(lp uint16, p string /* net.Addr */, rp uint16) {
 	if hc.tuns == nil {
 		hc.tuns = make(map[uint16]*TunEndpoint)
 	}
-	if hc.tuns[rport] == nil {
+	if hc.tuns[rp] == nil {
-		addrs, _ := net.InterfaceAddrs()
+		var addrs []net.Addr
-		hc.tuns[rport] = &TunEndpoint{Peer: addrs[0].String(),
+		if p == "" {
-			Lport: lport, Rport: rport, Ctl: make(chan<- rune)}
+			addrs, _ = net.InterfaceAddrs()
+			p = addrs[0].String()
+		}
+		hc.tuns[rp] = &TunEndpoint{/*Status: CSOTunSetup,*/ Peer: p,
+				Lport: lp, Rport: rp, Data: make(chan[]byte, 32), Ctl: make(chan<- rune)}
+		logger.LogDebug(fmt.Sprintf("InitTunEndpoint [%d:%s:%d]\n", lp, p, rp))
 	}
+	return
+}
 
-	/*
+//func (hc *Conn) GetTunStatus(rp uint16) byte {
-			 go func() {
+//	return hc.tuns[rp].Status
+//}
 
-			l, e := net.Listen("tcp", fmt.Sprintf(":%d", lport))
+func (hc *Conn) StartClientTunnel(lport, rport uint16) {
-			if e != nil {
+	hc.InitTunEndpoint(lport, "", rport)
-				fmt.Printf("[Could not get lport %d! (%s)\n", lport, e)
+	t := hc.tuns[rport] // for convenience
-			} else {
-				defer l.Close()
-				for {
-					c, e := l.Accept()
 
-					defer func() {
+	go func() {
-						//if hc.tuns[rport] != nil {
+
-						//	close(hc.tuns[rport])
+		logger.LogDebug(fmt.Sprintf("Listening for client tunnel port %d", lport))
-						//	hc.tuns[rport] = nil
+		l, e := net.Listen("tcp", fmt.Sprintf(":%d", lport))
-						//}
+		if e != nil {
-						c.Close()
+			logger.LogDebug(fmt.Sprintf("[Could not get lport %d! (%s)", lport, e))
+		} else {
+			defer l.Close()
+			for {
+				c, e := l.Accept()
+
+				defer func() {
+					//if hc.tuns[rport] != nil {
+					//	close(hc.tuns[rport])
+					//	hc.tuns[rport] = nil
+					//}
+					c.Close()
+				}()
+
+				if e != nil {
+					logger.LogDebug(fmt.Sprintf("Accept() got error(%v), hanging up.", e))
+					break
+					//log.Fatal(err)
+				} else {
+					logger.LogDebug(fmt.Sprintln("Accepted tunnel client"))
+
+					// outside client -> tunnel lport
+					go func() {
+						var tunDst bytes.Buffer
+						binary.Write(&tunDst, binary.BigEndian, lport)
+						binary.Write(&tunDst, binary.BigEndian, rport)
+						for {
+							rBuf := make([]byte, 1024)
+							//Read data from c, encrypt/write via hc to client(lport)
+							n, e := c.Read(rBuf)
+							if e != nil {
+								if e == io.EOF {
+									logger.LogDebug(fmt.Sprintf("lport Disconnected: shutting down tunnel [%d:%d]", lport, rport))
+								} else {
+									logger.LogDebug(fmt.Sprintf("Read error from lport of tun [%d:%d]\n%s", lport, rport, e))
+								}
+								hc.WritePacket(tunDst.Bytes(), CSOTunHangup)
+								break
+							}
+							if n > 0 {
+								rBuf = append(tunDst.Bytes(), rBuf[:n]...)
+								//logger.LogDebug(fmt.Sprintf("Got lport data:%v", tunDst.Bytes()))
+								hc.WritePacket(rBuf[:n+4], CSOTunData)
+							}
+						}
 					}()
 
-					if e != nil {
+					// tunnel lport -> outside client (c)
-						log.Printf("Accept() got error(%v), hanging up.\n", e)
+					go func() {
-						break
+						defer func() {
-						//log.Fatal(err)
+							//if hc.tuns[rport] != nil {
+							//	close(hc.tuns[rport])
+							//	hc.tuns[rport] = nil
+							//}
+							c.Close()
+						}()
+
+						for {
+							//fmt.Printf("Reading from client hc.tuns[%d]\n", lport)
+							bytes, ok := <-t.Data
+							if ok {
+								//fmt.Printf("[Got this through tunnel:%v]\n", bytes)
+								c.Write(bytes)
+							} else {
+								logger.LogDebug(fmt.Sprintf("[Channel closed?]\n"))
+								//break
+							}
+						}
+					}()
+
+				}
+			}
+		}
+	}()
+}
+
+func (hc *Conn) StartServerTunnel(lport, rport uint16) {
+	hc.InitTunEndpoint(lport, "", rport)
+	t := hc.tuns[rport] // for convenience
+
+	logger.LogDebug("Server dialling...")
+	c, err := net.Dial("tcp", fmt.Sprintf(":%d", rport))
+	if err != nil {
+		logger.LogDebug(fmt.Sprintf("Nothing is serving at rport :%d!", rport))
+		var resp bytes.Buffer
+		binary.Write(&resp, binary.BigEndian, lport)
+		binary.Write(&resp, binary.BigEndian, rport)
+		hc.WritePacket(resp.Bytes(), CSOTunRefused)
+	} else {
+		logger.LogDebug(fmt.Sprintf("[Tunnel Opened - %d:%s:%d]", lport, t.Peer, rport))
+		var resp bytes.Buffer
+		binary.Write(&resp, binary.BigEndian, lport)
+		binary.Write(&resp, binary.BigEndian, rport)
+		logger.LogDebug(fmt.Sprintf("[Writing CSOTunSetupAck[%d:%d]", lport, rport))
+		hc.WritePacket(resp.Bytes(), CSOTunSetupAck)
+
+		//
+		// worker to read data from the rport (to encrypt & send to client)
+		//
+		go func() {
+			defer func() {
+				//if hc.tuns[rport] != nil {
+				//	close(hc.tuns[rport])
+				//	hc.tuns[rport] = nil
+				//}
+				c.Close()
+			}()
+
+			var tunDst bytes.Buffer
+			binary.Write(&tunDst, binary.BigEndian, t.Lport)
+			binary.Write(&tunDst, binary.BigEndian, t.Rport)
+			for {
+				rBuf := make([]byte, 1024)
+				// Read data from c, encrypt/write via hc to client(lport)
+				n, e := c.Read(rBuf)
+				if e != nil {
+					if e == io.EOF {
+						logger.LogDebug(fmt.Sprintf("rport Disconnected: shutting down tunnel %v\n", t))
 					} else {
-						log.Println("Accepted client")
+						logger.LogDebug(fmt.Sprintf("Read error from rport of tun %v\n%s", t, e))
-
-						// outside client -> tunnel lport
-						go func() {
-							var tunDst bytes.Buffer
-							binary.Write(&tunDst, binary.BigEndian, lport)
-							binary.Write(&tunDst, binary.BigEndian, rport)
-							for {
-								rBuf := make([]byte, 1024)
-								//Read data from c, encrypt/write via hc to client(lport)
-								n, e := c.Read(rBuf)
-								if e != nil {
-									if e == io.EOF {
-										logger.LogNotice(fmt.Sprintf("lport Disconnected: shutting down tunnel [%d:%d]\n", lport, rport))
-									} else {
-										logger.LogErr(fmt.Sprintf("Read error from lport of tun [%d:%d]\n%s", lport, rport, e))
-									}
-									hc.WritePacket(tunDst.Bytes(), CSOTunClose)
-									break
-								}
-								if n > 0 {
-									rBuf = append(tunDst.Bytes(), rBuf[:n]...)
-									logger.LogNotice(fmt.Sprintf("Got lport data:%v\n", tunDst.Bytes()))
-									hc.WritePacket(rBuf[:n+4], CSOTunData)
-								}
-							}
-						}()
-
-						// tunnel lport -> outside client (c)
-						go func() {
-							defer func() {
-								//if hc.tuns[rport] != nil {
-								//	close(hc.tuns[rport])
-								//	hc.tuns[rport] = nil
-								//}
-								c.Close()
-							}()
-
-							for {
-								//fmt.Printf("Reading from client hc.tuns[%d]\n", lport)
-								bytes, ok := <-hc.tuns[rport]
-								if ok {
-									//fmt.Printf("[Got this through tunnel:%v]\n", bytes)
-									c.Write(bytes)
-								} else {
-									fmt.Printf("[Channel closed?]\n")
-									//break
-								}
-							}
-						}()
-
 					}
+					var resp bytes.Buffer
+					binary.Write(&resp, binary.BigEndian, lport)
+					binary.Write(&resp, binary.BigEndian, rport)
+					hc.WritePacket(resp.Bytes(), CSOTunDisconn)
+					logger.LogDebug(fmt.Sprintf("Closing server rport %d net.Dial()", t.Rport))
+					break
+				}
+				if n > 0 {
+					rBuf = append(tunDst.Bytes(), rBuf[:n]...)
+					hc.WritePacket(rBuf[:n+4], CSOTunData)
 				}
 			}
 		}()
-	*/
-}
 
-func StartServerTunnel(hc *Conn, lport, rport uint16) {
+		// worker to read data from client (already decrypted) & fwd to rport
-	if hc.tuns == nil {
+		go func() {
-		hc.tuns = make(map[uint16]*TunEndpoint)
+			defer func() {
+				//if hc.tuns[rport] != nil {
+				//close(hc.tuns[rport])
+				//hc.tuns[rport] = nil
+				//}
+				c.Close()
+			}()
+
+			for {
+				rData, ok := <-t.Data
+				if ok {
+					//logger.LogDebug(fmt.Sprintf("Got client data:%v", rData))
+					c.Write(rData)
+				} else {
+					logger.LogDebug("!!! ERROR reading from hc.tuns[] channel !!!")
+					break
+				}
+			}
+		}()
 	}
-	if hc.tuns[rport] == nil {
-		addrs, _ := net.InterfaceAddrs()
-		hc.tuns[rport] = &TunEndpoint{Peer: addrs[0].String(),
-			Lport: lport, Rport: rport, Ctl: make(chan<- rune)}
-	}
-
-	// Inform client of the tunPort
-	var resp bytes.Buffer
-	binary.Write(&resp, binary.BigEndian, hc.tuns[rport].Lport)
-	binary.Write(&resp, binary.BigEndian, hc.tuns[rport].Rport)
-	hc.WritePacket(resp.Bytes(), CSOTunSetupAck)
-
-	/*
-			t := TunEndpoint{Peer: addrs[0].String(), Lport: lport, Rport: rport}
-			var resp bytes.Buffer
-			binary.Write(&resp, binary.BigEndian, t.Lport)
-
-			//var dialHangup chan<- bool
-
-			c, err := net.Dial("tcp", fmt.Sprintf(":%d", rport))
-			if err != nil {
-				logger.LogErr(fmt.Sprintf("Nothing is serving at rport :%d!", rport))
-				binary.Write(&resp, binary.BigEndian, uint16(0))
-				// Inform client of the tunPort
-				hc.WritePacket(resp.Bytes(), CSOTunRefused)
-			} else {
-				binary.Write(&resp, binary.BigEndian, t.Rport)
-				logger.LogNotice(fmt.Sprintf("[Tunnel Opened - %d:%s:%d]", t.Lport, t.Peer, t.Rport))
-
-				//
-				// worker to read data from the rport (to encrypt & send to client)
-				//
-				go func() {
-					defer func() {
-						//if hc.tuns[rport] != nil {
-						//	close(hc.tuns[rport])
-						//	hc.tuns[rport] = nil
-						//}
-						c.Close()
-					}()
-
-					var tunDst bytes.Buffer
-					binary.Write(&tunDst, binary.BigEndian, t.Lport)
-					binary.Write(&tunDst, binary.BigEndian, t.Rport)
-					for {
-						rBuf := make([]byte, 1024)
-						// Read data from c, encrypt/write via hc to client(lport)
-						n, e := c.Read(rBuf)
-						if e != nil {
-							if e == io.EOF {
-								logger.LogNotice(fmt.Sprintf("rport Disconnected: shutting down tunnel %v\n", t))
-							} else {
-								logger.LogErr(fmt.Sprintf("Read error from rport of tun %v\n%s", t, e))
-							}
-							hc.WritePacket(resp.Bytes(), CSOTunClose)
-							fmt.Printf("Closing server rport net.Dial()\n")
-							break
-						}
-						if n > 0 {
-							rBuf = append(tunDst.Bytes(), rBuf[:n]...)
-							logger.LogNotice(fmt.Sprintf("Got rport data:%v", tunDst.Bytes()))
-							hc.WritePacket(rBuf[:n+4], CSOTunData)
-						}
-					}
-				}()
-
-				// worker to read data from client (already decrypted) & fwd to rport
-				go func() {
-					defer func() {
-						//if hc.tuns[rport] != nil {
-						//close(hc.tuns[rport])
-						//hc.tuns[rport] = nil
-						//}
-						c.Close()
-					}()
-
-					for {
-						rData, ok := <-hc.tuns[rport]
-						if ok {
-							logger.LogNotice(fmt.Sprintf("Got client data:%v", rData))
-							c.Write(rData)
-						} else {
-							logger.LogErr("!!! ERROR reading from hc.tuns[] channel !!!")
-							break
-						}
-					}
-				}()
-
-		}
-	*/
 }

hkexsh/hkexsh.go

@@ -346,12 +346,47 @@ func reqTunnel(hc *hkexnet.Conn, lp uint16, p string /*net.Addr*/, rp uint16) {
 	var bTmp bytes.Buffer
 	binary.Write(&bTmp, binary.BigEndian, lp)
 	binary.Write(&bTmp, binary.BigEndian, rp)
+	fmt.Printf("bTmp:%x\n", bTmp.Bytes())
+	logger.LogDebug(fmt.Sprintln("[Client sending CSOTunSetup]"))
 	hc.WritePacket(bTmp.Bytes(), hkexnet.CSOTunSetup)
 	// hkexnet.WritePacket() handles processing of client side tun setup,
 	// calling hkexnet.StartClientTunnel()
 
 	// Server should reply immediately with CSOTunSetupAck[lport:rport]
 	// hkexnet.Read() on server side handles server side tun setup.
+
+	// CSOTun packets don't reply with acks/naks in the datastream; they
+	// record the last status (other than CSOTunData) in the TunEndpoint
+	// .Status field. We can check this here to determine how the request
+	// completed.
+	// TODO: Should be a timeout check here of course to avoid hangs...
+	hc.InitTunEndpoint(lp, p, rp)
+	resp := make([]byte, 4)
+	var lpResp, rpResp uint16
+	n, e := io.ReadFull(hc, resp)
+	if n < 4 || e != nil {
+		logger.LogErr(fmt.Sprintf("[Client tun response len %d, %s\n", n, e))
+	} else {
+		lpResp = binary.BigEndian.Uint16(resp[0:2])
+		rpResp = binary.BigEndian.Uint16(resp[2:4])
+		//var s byte
+		//for timeout := 0; timeout < 5; timeout++ {
+		//	s = hc.GetTunStatus(rp)
+		//	if s != hkexnet.CSOTunSetup {
+		//		logger.LogDebug(fmt.Sprintf("[Client tun setup result:%d\n]", s))
+		//		break
+		//	}
+		//	time.Sleep(1 * time.Second)
+		//}
+	}
+
+	if lpResp == lp && rpResp == rp {
+		logger.LogDebug("[Client got tun setup ack OK]")
+		hc.StartClientTunnel(lp, rp)
+	} else {
+		logger.LogDebug(fmt.Sprintf("[Client tun response ports [%d:%d]\n", lpResp, rpResp))
+		logger.LogDebug(fmt.Sprintln("[Client tun setup FAILED]"))
+	}
 	return
 }
 
@@ -492,8 +527,8 @@ func main() {
 	// either the shell session or copy operation.
 	_ = shellMode
 
-	Log, _ = logger.New(logger.LOG_USER|logger.LOG_DEBUG, "hkexsh")
+	Log, _ = logger.New(logger.LOG_USER|logger.LOG_DEBUG|logger.LOG_NOTICE|logger.LOG_ERR, "hkexsh")
-	hkexnet.Init(dbg, "hkexsh", logger.LOG_USER|logger.LOG_DEBUG)
+	hkexnet.Init(dbg, "hkexsh", logger.LOG_USER|logger.LOG_DEBUG|logger.LOG_NOTICE|logger.LOG_ERR)
 	if dbg {
 		log.SetOutput(Log)
 	} else {

hkexshd/hkexshd.go

@@ -387,8 +387,8 @@ func main() {
 		}
 	}
 
-	Log, _ = logger.New(logger.LOG_DAEMON|logger.LOG_DEBUG, "hkexshd")
+	Log, _ = logger.New(logger.LOG_DAEMON|logger.LOG_DEBUG|logger.LOG_NOTICE|logger.LOG_ERR, "hkexshd")
-	hkexnet.Init(dbg, "hkexshd", logger.LOG_DAEMON|logger.LOG_DEBUG)
+	hkexnet.Init(dbg, "hkexshd", logger.LOG_DAEMON|logger.LOG_DEBUG|logger.LOG_NOTICE|logger.LOG_ERR)
 	if dbg {
 		log.SetOutput(Log)
 	} else {