Merge branch 'conn-keepalive' of RLabs/xs into master

Merge of branch conn-keepalive

Makefile

@@ -1,4 +1,4 @@
-VERSION := 0.9.5.5
+VERSION := 0.9.5.6-rc
 .PHONY: lint vis clean common client server passwd\
  subpkgs install uninstall reinstall scc
  

xs/xs.go

@@ -1005,7 +1005,7 @@ func main() { //nolint: funlen, gocyclo
 	loginTimeout := time.AfterFunc(30*time.Second, func() { //nolint:gomnd
 		restoreTermState(oldState)
 		fmt.Printf(" .. [login timeout]\n")
-		exitWithStatus(xsnet.CSOLoginTimeout)
+		exitWithStatus(xsnet.CSELoginTimeout)
 	})
 
 	if authCookie == "" {
@@ -1059,13 +1059,16 @@ func main() { //nolint: funlen, gocyclo
 		fmt.Fprintln(os.Stderr, rejectUserMsg())
 		rec.SetStatus(GeneralProtocolErr)
 	} else {
+		// === Set up connection keepalive to server
+		conn.StartupKeepAlive() // goroutine, returns immediately
+		defer conn.ShutdownKeepAlive()
+
 		// === Set up chaffing to server
 		conn.SetupChaff(chaffFreqMin, chaffFreqMax, chaffBytesMax) // enable client->server chaffing
 		if chaffEnabled {
 			// #gv:s/label=\"main\$2\"/label=\"deferCloseChaff\"/
 			// TODO:.gv:main:2:deferCloseChaff
-			conn.EnableChaff() // goroutine, returns immediately
+			conn.StartupChaff() // goroutine, returns immediately
-			defer conn.DisableChaff()
 			defer conn.ShutdownChaff()
 		}
 
@@ -1148,6 +1151,5 @@ func exitWithStatus(status int) {
 			log.Fatal("could not write memory profile: ", err) //nolint:gocritic
 		}
 	}
-
 	os.Exit(status)
 }

xsd/xsd.go

@@ -17,11 +17,14 @@ import (
 	"fmt"
 	"io"
 	"log"
+	"net/http"
 	"os"
 	"os/exec"
 	"os/signal"
 	"os/user"
 	"path"
+	"runtime"
+	"runtime/pprof"
 	"strings"
 	"sync"
 	"syscall"
@@ -44,6 +47,9 @@ var (
 
 	// Log - syslog output (with no -d)
 	Log *logger.Writer
+
+	cpuprofile string
+	memprofile string
 )
 
 const (
@@ -115,10 +121,13 @@ func runClientToServerCopyAs(who, ttype string, conn *xsnet.Conn, fpath string,
 	c.Stdout = os.Stdout
 	c.Stderr = os.Stderr
 
+	// === Set up connection keepalive to client
+	conn.StartupKeepAlive() // goroutine, returns immediately
+	defer conn.ShutdownKeepAlive()
+
 	if chaffing {
-		conn.EnableChaff()
+		conn.StartupChaff()
 	}
-	defer conn.DisableChaff()
 	defer conn.ShutdownChaff()
 
 	// Start the command (no pty)
@@ -212,11 +221,14 @@ func runServerToClientCopyAs(who, ttype string, conn *xsnet.Conn, srcPath string
 	c.Stderr = stdErrBuffer
 	//c.Stderr = nil
 
+	// === Set up connection keepalive to client
+	conn.StartupKeepAlive() // goroutine, returns immediately
+	defer conn.ShutdownKeepAlive()
+
 	if chaffing {
-		conn.EnableChaff()
+		conn.StartupChaff()
 	}
 	//defer conn.Close()
-	defer conn.DisableChaff()
 	defer conn.ShutdownChaff()
 
 	// Start the command (no pty)
@@ -274,21 +286,28 @@ func runShellAs(who, hname, ttype, cmd string, interactive bool, //nolint:funlen
 
 	if interactive {
 		if useSysLogin {
-			// Use the server's login binary (post-auth, which
+			// Use the server's login binary (post-auth)
-			// is still done via our own bcrypt file)
-			//
-			// Note login will drop privs to the intended user for us
 			//
 			// Things UNIX login does, like print the 'motd',
 			// and use the shell specified by /etc/passwd, will be done
 			// automagically, at the cost of another external tool
 			// dependency.
 			//
+			// One drawback of using 'login' is that the remote side
+			// cannot give us back the shell's exit code, since it
+			// exits back to 'login', which usually returns its own
+			// 0 status back to us.
+			//
+			// Note login will drop privs to the intended user for us.
+			//
 			c = exec.Command(xs.GetTool("login"), "-f", "-p", who) //nolint:gosec
 		} else {
-			// Using our separate login via local passwd file
+			// Run shell directly (which allows nonzero exit codes back to
+			// the local system upon shell exit, whereas 'login' does not.)
 			//
-			// Note we must drop privs ourselves for the user shell
+			// Note we must drop privs ourselves for the user shell since
+			// we aren't using 'login' on the remote end which would do it
+			// for us.
 			//
 			c = exec.Command(xs.GetTool("bash"), "-i", "-l") //nolint:gosec
 			c.SysProcAttr = &syscall.SysProcAttr{}
@@ -327,6 +346,9 @@ func runShellAs(who, hname, ttype, cmd string, interactive bool, //nolint:funlen
 	defer func() { goutmp.Unput_utmp(utmpx) }()
 	goutmp.Put_lastlog_entry("xs", who, pts, hname)
 
+	conn.Pproc = c.Process.Pid
+	//fmt.Printf("[process %d started]\n", c.Process.Pid)
+
 	log.Printf("[%s]\n", cmd)
 	if err != nil {
 		log.Printf("Command finished with error: %v", err)
@@ -352,12 +374,15 @@ func runShellAs(who, hname, ttype, cmd string, interactive bool, //nolint:funlen
 			}
 		}()
 
+		// === Set up connection keepalive to client
+		conn.StartupKeepAlive() // goroutine, returns immediately
+		defer conn.ShutdownKeepAlive()
+
 		if chaffing {
-			conn.EnableChaff()
+			conn.StartupChaff()
 		}
 		// #gv:s/label=\"runShellAs\$4\"/label=\"deferChaffShutdown\"/
 		defer func() {
-			conn.DisableChaff()
 			conn.ShutdownChaff()
 		}()
 
@@ -397,7 +422,7 @@ func runShellAs(who, hname, ttype, cmd string, interactive bool, //nolint:funlen
 			}
 			conn.SetStatus(xsnet.CSOType(exitStatus))
 		} else {
-			logger.LogDebug("*** Main proc has exited. ***") //nolint:errcheck
+			logger.LogDebug(fmt.Sprintf("*** Main proc has exited (%d) ***", c.ProcessState.ExitCode())) //nolint:errcheck
 			// Background jobs still may be running; close the
 			// pty anyway, so the client can return before
 			// wg.Wait() below completes (Issue #18)
@@ -545,6 +570,9 @@ func main() { //nolint:funlen,gocyclo
       H_SHA256
       H_SHA512`)
 
+	flag.StringVar(&cpuprofile, "cpuprofile", "", "write cpu profile to <`file`>")
+	flag.StringVar(&memprofile, "memprofile", "", "write memory profile to <`file`>")
+
 	flag.Parse()
 
 	if vopt {
@@ -559,6 +587,24 @@ func main() { //nolint:funlen,gocyclo
 		}
 	}
 
+	// === Profiling instrumentation
+
+	if cpuprofile != "" {
+		f, err := os.Create(cpuprofile)
+		if err != nil {
+			log.Fatal("could not create CPU profile: ", err)
+		}
+		defer f.Close()
+		fmt.Println("StartCPUProfile()")
+		if err := pprof.StartCPUProfile(f); err != nil {
+			log.Fatal("could not start CPU profile: ", err) //nolint:gocritic
+		} else {
+			defer pprof.StopCPUProfile()
+		}
+
+		go func() { http.ListenAndServe("localhost:6060", nil) }() //nolint:errcheck,gosec
+	}
+
 	// Enforce some sane min/max vals on chaff flags
 	if chaffFreqMin < 2 { //nolint:gomnd
 		chaffFreqMin = 2
@@ -611,6 +657,9 @@ func main() { //nolint:funlen,gocyclo
 				syscall.Kill(0, syscall.SIGINT) //nolint:errcheck
 			case "hangup":
 				logger.LogNotice(fmt.Sprintf("[Got signal: %s - nop]", sig)) //nolint:errcheck
+				if cpuprofile != "" || memprofile != "" {
+					dumpProf()
+				}
 			default:
 				logger.LogNotice(fmt.Sprintf("[Got signal: %s - ignored]", sig)) //nolint:errcheck
 			}
@@ -632,6 +681,7 @@ func main() { //nolint:funlen,gocyclo
 		// Wait for a connection.
 		// Then check if client-proposed algs are allowed
 		conn, err := l.Accept()
+		//logger.LogDebug(fmt.Sprintf("l.Accept()\n"))
 		if err != nil {
 			log.Printf("Accept() got error(%v), hanging up.\n", err)
 		} else {
@@ -864,3 +914,23 @@ func main() { //nolint:funlen,gocyclo
 	} //endfor
 	//logger.LogNotice(fmt.Sprintln("[Exiting]")) //nolint:errcheck
 }
+
+func dumpProf() {
+	if cpuprofile != "" {
+		pprof.StopCPUProfile()
+	}
+
+	if memprofile != "" {
+		f, err := os.Create(memprofile)
+		if err != nil {
+			log.Fatal("could not create memory profile: ", err)
+		}
+		defer f.Close()
+		runtime.GC() // get up-to-date statistics
+		if err := pprof.WriteHeapProfile(f); err != nil {
+			log.Fatal("could not write memory profile: ", err) //nolint:gocritic
+		}
+	}
+
+	//os.Exit(status)
+}

xsnet/consts.go

@@ -52,6 +52,8 @@ const (
 	CSEKEXAlgDenied    // server rejected proposed KEX alg
 	CSECipherAlgDenied // server rejected proposed Cipher alg
 	CSEHMACAlgDenied   // server rejected proposed HMAC alg
+	CSEConnDead        // connection keepalives expired
+	CSELoginTimeout
 )
 
 // Extended (>255 UNIX exit status) codes
@@ -67,9 +69,6 @@ const (
 	CSOExitStatus         // Remote cmd exit status
 	CSOChaff              // Dummy packet, do not pass beyond decryption
 
-	// Client side errors
-	CSOLoginTimeout
-
 	// Tunnel setup/control/status
 	CSOTunSetup     // client -> server tunnel setup request (dstport)
 	CSOTunSetupAck  // server -> client tunnel setup ack
@@ -78,6 +77,7 @@ const (
 	CSOTunKeepAlive // client tunnel heartbeat
 	CSOTunDisconn   // server -> client: tunnel rport disconnected
 	CSOTunHangup    // client -> server: tunnel lport hung up
+	CSOKeepAlive    // bidir keepalive packet to monitor main connection
 )
 
 // TunEndpoint.tunCtl control values - used to control workers for client
@@ -97,7 +97,7 @@ const (
 // Channel status Op byte type (see CSONone, ... and CSENone, ...)
 type CSOType uint32
 
-//TODO: this should be small (max unfragmented packet size?)
+// TODO: this should be small (max unfragmented packet size?)
 const MAX_PAYLOAD_LEN = 2*1024*1024*1024 - 1
 
 // Session symmetric crypto algs

xsnet/net.go

@@ -39,6 +39,7 @@ import (
 	"net"
 	"strings"
 	"sync"
+	"syscall"
 	"time"
 
 	hkex "blitter.com/go/herradurakex"
@@ -64,7 +65,6 @@ type (
 	// see: https://en.wikipedia.org/wiki/chaff_(countermeasure)
 	ChaffConfig struct {
 		shutdown bool //set to inform chaffHelper to shut down
-		enabled  bool
 		msecsMin uint //msecs min interval
 		msecsMax uint //msecs max interval
 		szMax    uint // max size in bytes
@@ -87,8 +87,10 @@ type (
 		Rows       uint16
 		Cols       uint16
 
-		chaff ChaffConfig
+		keepalive uint // if this reaches zero, conn is considered dead
-		tuns  *map[uint16](*TunEndpoint)
+		Pproc     int  // proc ID of command run on this conn
+		chaff     ChaffConfig
+		tuns      *map[uint16](*TunEndpoint)
 
 		closeStat *CSOType      // close status (CSOExitStatus)
 		r         cipher.Stream //read cipherStream
@@ -971,7 +973,7 @@ func Dial(protocol string, ipport string, extensions ...string) (hc Conn, err er
 
 // Close a hkex.Conn
 func (hc *Conn) Close() (err error) {
-	hc.DisableChaff()
+	hc.ShutdownChaff()
 	s := make([]byte, 4)
 	binary.BigEndian.PutUint32(s, uint32(*hc.closeStat))
 	log.Printf("** Writing closeStat %d at Close()\n", *hc.closeStat)
@@ -1196,7 +1198,7 @@ func (hl *HKExListener) Accept() (hc Conn, err error) {
 // packet processing.
 //
 // See go doc io.Reader
-func (hc Conn) Read(b []byte) (n int, err error) {
+func (hc *Conn) Read(b []byte) (n int, err error) {
 	for {
 		if hc.dBuf.Len() > 0 {
 			break
@@ -1214,7 +1216,8 @@ 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.LogDebug(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up(1)]"))
+				//!rlm hc.SetStatus(CSENone) //FIXME: re-examine this (exit 9 w/o it - 2023-11-05)
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "ctrlStatOp", err)
@@ -1237,7 +1240,7 @@ 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.LogDebug(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up(2)]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "HMAC", err)
@@ -1253,7 +1256,7 @@ 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.LogDebug(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up(3)]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "payloadLen", err)
@@ -1276,7 +1279,7 @@ 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.LogDebug(fmt.Sprintln("[Client hung up]"))
+				logger.LogDebug(fmt.Sprintln("[Client hung up(4)]"))
 				return 0, io.EOF
 			}
 			etxt := fmt.Sprintf("** Failed read:%s (%s) **", "payloadBytes", err)
@@ -1337,6 +1340,11 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 			case CSOChaff:
 				// Throw away pkt if it's chaff (ie., caller to Read() won't see this data)
 				log.Printf("[Chaff pkt, discarded (len %d)]\n", decryptN)
+			case CSOKeepAlive:
+				//logger.LogDebug(fmt.Sprintf("[got keepAlive pkt, discarded (len %d)]\n", decryptN))
+				// payload of keepalive (2 bytes) is not currently used (0x55aa fixed)
+				_ = binary.BigEndian.Uint16(payloadBytes[0:2])
+				hc.ResetKeepAlive()
 			case CSOTermSize:
 				fmt.Sscanf(string(payloadBytes), "%d %d", &hc.Rows, &hc.Cols)
 				log.Printf("[TermSize pkt: rows %v cols %v]\n", hc.Rows, hc.Cols)
@@ -1568,18 +1576,12 @@ func (hc *Conn) WritePacket(b []byte, ctrlStatOp byte) (n int, err error) {
 	return retN, err
 }
 
-func (hc *Conn) EnableChaff() {
+func (hc *Conn) StartupChaff() {
 	hc.chaff.shutdown = false
-	hc.chaff.enabled = true
 	log.Println("Chaffing ENABLED")
 	hc.chaffHelper()
 }
 
-func (hc *Conn) DisableChaff() {
-	hc.chaff.enabled = false
-	log.Println("Chaffing DISABLED")
-}
-
 func (hc *Conn) ShutdownChaff() {
 	hc.chaff.shutdown = true
 	log.Println("Chaffing SHUTDOWN")
@@ -1594,9 +1596,10 @@ func (hc *Conn) SetupChaff(msecsMin uint, msecsMax uint, szMax uint) {
 // Helper routine to spawn a chaffing goroutine for each Conn
 func (hc *Conn) chaffHelper() {
 	go func() {
+		var nextDuration int
 		for {
-			var nextDuration int
+			//logger.LogDebug(fmt.Sprintf("[chaffHelper Loop]\n"))
-			if hc.chaff.enabled {
+			if !hc.chaff.shutdown {
 				var bufTmp []byte
 				bufTmp = make([]byte, rand.Intn(int(hc.chaff.szMax)))
 				min := int(hc.chaff.msecsMin)
@@ -1604,17 +1607,65 @@ func (hc *Conn) chaffHelper() {
 				_, _ = rand.Read(bufTmp)
 				_, err := hc.WritePacket(bufTmp, CSOChaff)
 				if err != nil {
-					log.Println("[ *** error - chaffHelper quitting *** ]")
+					log.Println("[ *** error - chaffHelper shutting down *** ]")
-					hc.chaff.enabled = false
+					hc.chaff.shutdown = true
 					break
 				}
-			}
+			} else {
-			time.Sleep(time.Duration(nextDuration) * time.Millisecond)
+				log.Println("[ *** chaffHelper shutting down *** ]")
-			if hc.chaff.shutdown {
+				break
-				log.Println("*** chaffHelper shutting down")
+			}
+			time.Sleep(time.Duration(nextDuration) * time.Millisecond)
+		}
+	}()
+}
+
+func (hc *Conn) StartupKeepAlive() {
+	hc.ResetKeepAlive()
+	log.Println("KeepAlive ENABLED")
+	hc.keepaliveHelper()
+}
+
+func (hc *Conn) ShutdownKeepAlive() {
+	log.Println("Conn SHUTDOWN")
+	hc.Close()
+}
+
+func (hc *Conn) ResetKeepAlive() {
+	hc.keepalive = 3
+	log.Println("KeepAlive RESET")
+}
+
+// Helper routine to spawn a keepalive goroutine for each Conn
+func (hc *Conn) keepaliveHelper() {
+	go func() {
+		for {
+			nextDuration := 10000
+			bufTmp := []byte{0x55, 0xaa}
+			_, err := hc.WritePacket(bufTmp, CSOKeepAlive)
+			logger.LogDebug(fmt.Sprintf("[keepalive]\n"))
+			if err != nil {
+				logger.LogDebug(fmt.Sprintf("[ *** error - keepaliveHelper quitting *** ]\n"))
+				break
+			}
+			time.Sleep(time.Duration(nextDuration) * time.Millisecond)
+			hc.keepalive -= 1
+			logger.LogDebug(fmt.Sprintf("[keepAlive is now %d]\n", hc.keepalive))
+
+			//if rand.Intn(8) == 0 {
+			//	hc.keepalive = 0
+			//}
+
+			if hc.keepalive == 0 {
+				logger.LogDebug(fmt.Sprintf("*** keepaliveHelper shutting down\n"))
+				hc.SetStatus(CSEConnDead)
+				hc.ShutdownKeepAlive()
+				if hc.Pproc != 0 {
+					//fmt.Printf("[pid %d needs to be killed]\n", hc.Pproc)
+					syscall.Kill(hc.Pproc, syscall.SIGABRT) //nolint:errcheck
+				}
 				break
 			}
-
 		}
 	}()
 }