Remote exit status now reflected in client->server copies

hkexnet/hkexnet.go

@@ -62,11 +62,12 @@ const (
 // const CSExtendedCode - extended (>255 UNIX exit status) codes
 // This indicate channel-related or internal errors
 const (
-	CSEBadAuth     = 1024 // Failed login password
+	CSENone        = 32 + iota
-	CSETruncCSO           // No CSOExitStatus in payload
+	CSEBadAuth     // Failed login password
-	CSEStillOpen          // Channel closed unexpectedly
+	CSETruncCSO    // No CSOExitStatus in payload
-	CSEExecFail           // cmd.Start() (exec) failed
+	CSEStillOpen   // Channel closed unexpectedly
-	CSEPtyExecFail        // pty.Start() (exec w/pty) failed
+	CSEExecFail    // cmd.Start() (exec) failed
+	CSEPtyExecFail // pty.Start() (exec w/pty) failed
 )
 
 const (
@@ -128,7 +129,6 @@ func (hc Conn) GetStatus() uint32 {
 
 func (hc *Conn) SetStatus(stat uint32) {
 	*hc.closeStat = stat
-	//fmt.Println("closeStat:", *hc.closeStat)
 	log.Println("closeStat:", *hc.closeStat)
 }
 
@@ -170,6 +170,12 @@ func (hc *Conn) SetOpts(opts uint32) {
 }
 
 func (hc *Conn) applyConnExtensions(extensions ...string) {
+	//fmt.Printf("CSENone:%d CSEBadAuth:%d CSETruncCSO:%d CSEStillOpen:%d CSEExecFail:%d CSEPtyExecFail:%d\n",
+	//	CSENone, CSEBadAuth, CSETruncCSO, CSEStillOpen, CSEExecFail, CSEPtyExecFail)
+
+	//fmt.Printf("CSONone:%d  CSOHmacInvalid:%d CSOTermSize:%d CSOExitStatus:%d CSOChaff:%d\n",
+	//	CSONone, CSOHmacInvalid, CSOTermSize, CSOExitStatus, CSOChaff)
+
 	for _, s := range extensions {
 		switch s {
 		case "KEX_HERRADURA":
@@ -320,6 +326,7 @@ func (hc *Conn) Close() (err error) {
 	hc.DisableChaff()
 	s := make([]byte, 4)
 	binary.BigEndian.PutUint32(s, *hc.closeStat)
+	log.Printf("** Writing closeStat %d at Close()\n", *hc.closeStat)
 	hc.WritePacket(s, CSOExitStatus)
 	err = hc.c.Close()
 	log.Println("[Conn Closing]")
@@ -479,12 +486,10 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 		// Normal client 'exit' from interactive session will cause
 		// (on server side) err.Error() == "<iface/addr info ...>: use of closed network connection"
 		if err != nil {
-			if !strings.HasSuffix(err.Error(), "use of closed network connection") {
+			if err == io.EOF || strings.HasSuffix(err.Error(), "use of closed network connection") {
-				//fmt.Println("[1]unexpected Read() err:", err)
-				log.Println("[1]unexpected Read() err:", err)
-			} else {
-				//fmt.Println("[Client hung up]")
 				log.Println("[Client hung up]")
+			} else {
+				log.Println(err)
 			}
 			return 0, err
 		}
@@ -527,7 +532,7 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 		decryptN, err := rs.Read(payloadBytes)
 		log.Printf("  <-ptext:\r\n%s\r\n", hex.Dump(payloadBytes[:n]))
 		if err != nil {
-			//fmt.Print(err)
+			log.Println("hkexnet.Read():", err)
 			//panic(err)
 		} else {
 
@@ -541,15 +546,11 @@ func (hc Conn) Read(b []byte) (n int, err error) {
 			} else if ctrlStatOp == CSOExitStatus {
 				if len(payloadBytes) > 0 {
 					hc.SetStatus(binary.BigEndian.Uint32(payloadBytes))
-					//!// If remote end is closing with an error, reply we're closing ours
-					//!if hc.GetStatus() != 0 {
-					//!	log.Print("CSOExitStatus:", hc.GetStatus())
-					hc.Close()
-					//!}
 				} else {
 					log.Println("[truncated payload, cannot determine CSOExitStatus]")
-					*hc.closeStat = CSETruncCSO
+					hc.SetStatus(CSETruncCSO)
 				}
+				hc.Close()
 			} else {
 				hc.dBuf.Write(payloadBytes)
 				//log.Printf("hc.dBuf: %s\n", hex.Dump(hc.dBuf.Bytes()))
@@ -597,7 +598,7 @@ func (hc *Conn) WritePacket(b []byte, op byte) (n int, err error) {
 	var payloadLen uint32
 
 	if hc.m == nil || hc.wm == nil {
-			return 0, errors.New("Secure chan not ready for writing")
+		return 0, errors.New("Secure chan not ready for writing")
 	}
 
 	// N.B. Originally this Lock() surrounded only the
@@ -609,7 +610,6 @@ func (hc *Conn) WritePacket(b []byte, op byte) (n int, err error) {
 	// Would be nice to determine if the mutex scope
 	// could be tightened.
 	hc.m.Lock()
-	//fmt.Printf("--== TOTAL payloadLen (b):%d\n", len(b))
 	payloadLen = uint32(len(b))
 	//!fmt.Printf("  --== payloadLen:%d\n", payloadLen)
 	log.Printf("  :>ptext:\r\n%s\r\n", hex.Dump(b[0:payloadLen]))

hkexsh/hkexsh.go

@@ -10,6 +10,7 @@ package main
 import (
 	"bytes"
 	"encoding/binary"
+	"errors"
 	"flag"
 	"fmt"
 	"io"
@@ -125,7 +126,6 @@ func doCopyMode(conn *hkexnet.Conn, remoteDest bool, files string, rec *hkexsh.S
 			} else {
 				cmdArgs = append(cmdArgs, "-C", dirTmp, fileTmp)
 			}
-			//cmdArgs = append(cmdArgs, v)
 		}
 
 		log.Printf("[%v %v]\n", cmdName, cmdArgs)
@@ -142,9 +142,24 @@ func doCopyMode(conn *hkexnet.Conn, remoteDest bool, files string, rec *hkexsh.S
 
 		// Start the command (no pty)
 		err = c.Start() // returns immediately
+		/////////////
+		// NOTE: There is, apparently, a bug in Go stdlib here. Start()
+		// can actually return immediately, on a command which *does*
+		// start but exits quickly, with c.Wait() error
+		// "c.Wait status: exec: not started".
+		// As in this example, attempting a client->server copy to
+		// a nonexistent remote dir (it's tar exiting right away, exitStatus
+		// 2, stderr
+		// /bin/tar -xz -C /home/someuser/nosuchdir
+		// stderr: fork/exec /bin/tar: no such file or directory
+		//
+		// In this case, c.Wait() won't give us the real
+		// exit status (is it lost?).
+		/////////////
 		if err != nil {
-			fmt.Println(err)
+			fmt.Println("cmd exited immediately. Cannot get cmd.Wait().ExitStatus()")
-			//log.Fatal(err)
+			err = errors.New("cmd exited prematurely")
+			exitStatus = uint32(2)
 		} else {
 			if err = c.Wait(); err != nil {
 				if exiterr, ok := err.(*exec.ExitError); ok {
@@ -156,17 +171,30 @@ func doCopyMode(conn *hkexnet.Conn, remoteDest bool, files string, rec *hkexsh.S
 					// an ExitStatus() method with the same signature.
 					if status, ok := exiterr.Sys().(syscall.WaitStatus); ok {
 						exitStatus = uint32(status.ExitStatus())
-						log.Printf("Exit Status: %d", exitStatus) //#
 						fmt.Print(stdErrBuffer)
+						fmt.Printf("Exit Status: %d\n", exitStatus) //#
 					}
 				}
 			}
-			//fmt.Println("*** client->server cp finished ***")
+			// send CSOExitStatus to inform remote (server) end cp is done
-			// Signal other end transfer is complete
+			log.Println("Sending local exitStatus:", exitStatus)
+			r := make([]byte, 4)
+			binary.BigEndian.PutUint32(r, exitStatus)
+			conn.WritePacket(r, hkexnet.CSOExitStatus)
+
+			// Do a final read for remote's exit status
 			s := make([]byte, 4)
-			binary.BigEndian.PutUint32(s, rec.Status())
+			_, remErr := conn.Read(s)
-			conn.WritePacket(s, hkexnet.CSOExitStatus)
+			if remErr != io.EOF && !strings.Contains(remErr.Error(), "use of closed network") {
-			_, _ = conn.Read(nil /*ackByte*/)
+				fmt.Printf("*** remote status Read() failed: %v\n", remErr)
+			}
+
+			// If local side status was OK, use remote side's status
+			if exitStatus == 0 {
+				exitStatus = conn.GetStatus()
+				log.Println("Received remote exitStatus:", exitStatus)
+			}
+			log.Printf("*** client->server cp finished , status %d ***\n", conn.GetStatus())
 		}
 	} else {
 		log.Println("remote filepath:", string(rec.Cmd()), "local files:", files)
@@ -215,7 +243,7 @@ func doCopyMode(conn *hkexnet.Conn, remoteDest bool, files string, rec *hkexsh.S
 			if exitStatus == 0 {
 				exitStatus = uint32(conn.GetStatus())
 			}
-			//fmt.Println("*** server->client cp finished ***")
+			fmt.Printf("*** server->client cp finished, status %d ***\n", conn.GetStatus())
 		}
 	}
 	return
@@ -320,7 +348,6 @@ func rejectUserMsg() string {
 func main() {
 	version := "0.2pre (NO WARRANTY)"
 	var vopt bool
-	var aopt bool //login using authToken
 	var gopt bool //login via password, asking server to generate authToken
 	var dbg bool
 	var shellMode bool // if true act as shell, else file copier
@@ -359,7 +386,6 @@ func main() {
 		// hkexsh accepts a command (-x) but not
 		// a srcpath (-r) or dstpath (-t)
 		flag.StringVar(&cmdStr, "x", "", "`command` to run (if not specified run interactive shell)")
-		flag.BoolVar(&aopt, "a", false, "login using auth token")
 		flag.BoolVar(&gopt, "g", false, "ask server to generate authtoken")
 		shellMode = true
 		flag.Usage = UsageShell
@@ -447,13 +473,6 @@ func main() {
 		log.SetOutput(ioutil.Discard)
 	}
 
-	if aopt && gopt {
-		fmt.Fprintln(os.Stderr,
-			"Error: use -g first to generate an authtoken,",
-			" then -a to login using it.")
-		os.Exit(1)
-	}
-
 	if !gopt {
 		// See if we can log in via an auth token
 		u, _ := user.Current()
@@ -469,8 +488,8 @@ func main() {
 			}
 			entries := strings.SplitN(string(ab), "\n", -1)
 			//if len(entries) > 0 {
-				fmt.Println("entries[0]:", entries[0])
+			//fmt.Println("entries[0]:", entries[0])
-				authCookie = strings.TrimSpace(entries[0])
+			authCookie = strings.TrimSpace(entries[0])
 			//} else {
 			//	fmt.Fprintln(os.Stderr, "ERROR: no matching authtoken")
 			//	os.Exit(1)
@@ -597,7 +616,7 @@ func main() {
 		}
 
 		if rec.Status() != 0 {
-			fmt.Fprintln(os.Stderr, "Remote end exited with status:", rec.Status())
+			fmt.Fprintln(os.Stderr, "Session exited with status:", rec.Status())
 		}
 	}
 

hkexshd/hkexshd.go

@@ -92,9 +92,25 @@ func runClientToServerCopyAs(who, ttype string, conn hkexnet.Conn, fpath string,
 	// Start the command (no pty)
 	log.Printf("[%v %v]\n", cmdName, cmdArgs)
 	err = c.Start() // returns immediately
+	/////////////
+	// NOTE: There is, apparently, a bug in Go stdlib here. Start()
+	// can actually return immediately, on a command which *does*
+	// start but exits quickly, with c.Wait() error
+	// "c.Wait status: exec: not started".
+	// As in this example, attempting a client->server copy to
+	// a nonexistent remote dir (it's tar exiting right away, exitStatus
+	// 2, stderr
+	// /bin/tar -xz -C /home/someuser/nosuchdir
+	// stderr: fork/exec /bin/tar: no such file or directory
+	//
+	// In this case, c.Wait() won't give us the real
+	// exit status (is it lost?).
+	/////////////
 	if err != nil {
-		log.Printf("Command finished with error: %v", err)
+		log.Println("cmd exited immediately. Cannot get cmd.Wait().ExitStatus()")
-		return err, hkexnet.CSEExecFail // !?
+		err = errors.New("cmd exited prematurely")
+		//exitStatus = uint32(254)
+		exitStatus = hkexnet.CSEExecFail
 	} else {
 		if err := c.Wait(); err != nil {
 			//fmt.Println("*** c.Wait() done ***")
@@ -108,13 +124,13 @@ func runClientToServerCopyAs(who, ttype string, conn hkexnet.Conn, fpath string,
 				if status, ok := exiterr.Sys().(syscall.WaitStatus); ok {
 					exitStatus = uint32(status.ExitStatus())
 					err = errors.New("cmd returned nonzero status")
-					fmt.Printf("Exit Status: %d\n", exitStatus)
+					log.Printf("Exit Status: %d\n", exitStatus)
 				}
 			}
 		}
-		//fmt.Println("*** client->server cp finished ***")
+		log.Println("*** client->server cp finished ***")
-		return
 	}
+	return
 }
 
 // Perform a server->client copy
@@ -259,7 +275,7 @@ func runShellAs(who, ttype string, cmd string, interactive bool, conn hkexnet.Co
 				log.Printf("[Setting term size to: %v %v]\n", sz.Rows, sz.Cols)
 				pty.Setsize(ptmx, &pty.Winsize{Rows: sz.Rows, Cols: sz.Cols})
 			}
-			fmt.Println("*** WinCh goroutine done ***")
+			log.Println("*** WinCh goroutine done ***")
 		}()
 
 		// Copy stdin to the pty.. (bgnd goroutine)
@@ -416,7 +432,6 @@ func main() {
 					log.Println("[Bad hkexsh.Session fmt]")
 					return err
 				}
-				//fmt.Printf("  lens:%d %d %d %d %d %d\n", len1, len2, len3, len4, len5, len6)
 
 				tmp := make([]byte, len1, len1)
 				_, err = io.ReadFull(hc, tmp)
@@ -560,8 +575,13 @@ func main() {
 					} else {
 						log.Printf("[Command completed for %s@%s, status %d]\n", rec.Who(), hname, cmdStatus)
 					}
-					fmt.Println("cmdStatus:", cmdStatus)
 					hc.SetStatus(cmdStatus)
+
+					// Send CSOExitStatus *before* client closes channel
+					s := make([]byte, 4)
+					binary.BigEndian.PutUint32(s, cmdStatus)
+					log.Printf("** cp writing closeStat %d at Close()\n", cmdStatus)
+					hc.WritePacket(s, hkexnet.CSOExitStatus)
 				} else if rec.Op()[0] == 'S' {
 					// File copy (src) operation - server copy to client
 					log.Printf("[Server->Client copy]\n")
@@ -569,7 +589,6 @@ func main() {
 					hname := strings.Split(addr.String(), ":")[0]
 					log.Printf("[Running copy for [%s@%s]]\n", rec.Who(), hname)
 					runErr, cmdStatus := runServerToClientCopyAs(string(rec.Who()), string(rec.TermType()), hc, string(rec.Cmd()), chaffEnabled)
-					//fmt.Print("ServerToClient cmdStatus:", cmdStatus)
 					// Returned hopefully via an EOF or exit/logout;
 					// Clear current op so user can enter next, or EOF
 					rec.SetOp([]byte{0})
@@ -579,12 +598,8 @@ func main() {
 						log.Printf("[Command completed for %s@%s, status %d]\n", rec.Who(), hname, cmdStatus)
 					}
 					hc.SetStatus(cmdStatus)
-					// Signal other end transfer is complete
-					s := make([]byte, 4)
-					binary.BigEndian.PutUint32(s, cmdStatus)
-					hc.WritePacket(s, hkexnet.CSOExitStatus)
 					//fmt.Println("Waiting for EOF from other end.")
-					_, _ = hc.Read(nil /*ackByte*/)
+					//_, _ = hc.Read(nil /*ackByte*/)
 					//fmt.Println("Got remote end ack.")
 				} else {
 					log.Println("[Bad hkexsh.Session]")