Expanded debug logging, fix deprecations (antoniomika#240)

* Add debug messages for aborted requests

* Don't use %s for Println

* Fix deprecated ioutil calls

* Fix incorrect leading spaces for comment

* Add debug-interval option

* Align debug logging syntax with existing error logging

* Fix linting errors, fix status logging

* Ensure debug-interval is not zero

README.md

@@ -341,6 +341,7 @@ Flags:
       --cleanup-unbound-timeout duration                        Duration to wait before cleaning up an unbound (unforwarded) connection (default 5s)
   -c, --config string                                           Config file (default "config.yml")
       --debug                                                   Enable debugging information
+      --debug-interval duration                                 The duration to wait between each debug loop output if debug is true (default 2s)
   -d, --domain string                                           The root domain for HTTP(S) multiplexing that will be appended to subdomains (default "ssi.sh")
       --force-requested-aliases                                 Force the aliases used to be the one that is requested. Will fail the bind if it exists already
       --force-requested-ports                                   Force the ports used to be the one that is requested. Will fail the bind if it exists already

cmd/sish.go

@@ -131,6 +131,7 @@ func init() {
 	rootCmd.PersistentFlags().IntP("log-to-file-max-backups", "", 3, "The maxium number of rotated logs files to keep")
 	rootCmd.PersistentFlags().IntP("log-to-file-max-age", "", 28, "The maxium number of days to store log output in a file")
 
+	rootCmd.PersistentFlags().DurationP("debug-interval", "", 2*time.Second, "Duration to wait between each debug loop output if debug is true")
 	rootCmd.PersistentFlags().DurationP("idle-connection-timeout", "", 5*time.Second, "Duration to wait for activity before closing a connection for all reads and writes")
 	rootCmd.PersistentFlags().DurationP("ping-client-interval", "", 5*time.Second, "Duration representing an interval to ping a client to ensure it is up")
 	rootCmd.PersistentFlags().DurationP("ping-client-timeout", "", 5*time.Second, "Duration to wait for activity before closing a connection after sending a ping to a client")

config.example.yml

@@ -27,6 +27,7 @@ cleanup-unbound: false
 cleanup-unbound-timeout: 5s
 config: config.yml
 debug: false
+debug-interval: 2s
 domain: ssi.sh
 force-requested-aliases: false
 force-requested-ports: false

httpmuxer/httpmuxer.go

@@ -7,7 +7,7 @@ import (
 	"bytes"
 	"encoding/base64"
 	"fmt"
-	"io/ioutil"
+	"io"
 	"log"
 	"net"
 	"net/http"
@@ -49,8 +49,22 @@ func Start(state *utils.State) {
 
 		// Here is where we check whether or not an IP is blocked.
 		clientIPAddr, _, err := net.SplitHostPort(c.Request.RemoteAddr)
-		if state.IPFilter.Blocked(c.ClientIP()) || state.IPFilter.Blocked(clientIPAddr) || err != nil {
-			c.AbortWithStatus(http.StatusForbidden)
+		clientIPAddrBlocked := state.IPFilter.Blocked(clientIPAddr)
+		cClientIP := c.ClientIP()
+		cClientIPBlocked := state.IPFilter.Blocked(cClientIP)
+
+		if clientIPAddrBlocked || cClientIPBlocked || err != nil {
+			status := http.StatusForbidden
+			c.AbortWithStatus(status)
+			if viper.GetBool("debug") {
+				log.Println("Aborting with status", status)
+				if clientIPAddrBlocked {
+					log.Println("Blocked:", clientIPAddr)
+				}
+				if cClientIPBlocked {
+					log.Println("Blocked:", cClientIP)
+				}
+			}
 			return
 		}
 		c.Next()
@@ -165,7 +179,11 @@ func Start(state *utils.State) {
 				return
 			}
 
-			c.AbortWithStatus(http.StatusNotFound)
+			status := http.StatusNotFound
+			c.AbortWithStatus(status)
+			if viper.GetBool("debug") {
+				log.Println("Aborting with status", status)
+			}
 			return
 		}
 
@@ -181,7 +199,11 @@ func Start(state *utils.State) {
 
 		if authNeeded {
 			c.Header("WWW-Authenticate", "Basic realm=\"sish\"")
-			c.AbortWithStatus(http.StatusUnauthorized)
+			status := http.StatusUnauthorized
+			c.AbortWithStatus(status)
+			if viper.GetBool("debug") {
+				log.Println("Aborting with status", status)
+			}
 			return
 		}
 
@@ -234,13 +256,13 @@ func Start(state *utils.State) {
 			return
 		}
 
-		reqBody, err := ioutil.ReadAll(c.Request.Body)
+		reqBody, err := io.ReadAll(c.Request.Body)
 		if err != nil {
 			log.Println("Error reading request body:", err)
 			return
 		}
 
-		c.Request.Body = ioutil.NopCloser(bytes.NewBuffer(reqBody))
+		c.Request.Body = io.NopCloser(bytes.NewBuffer(reqBody))
 
 		err = forward.ResponseModifier(ResponseModifier(state, hostname, reqBody, c, currentListener))(currentListener.Forward)
 		if err != nil {

httpmuxer/proxy.go

@@ -6,7 +6,7 @@ import (
 	"crypto/tls"
 	"encoding/base64"
 	"encoding/json"
-	"io/ioutil"
+	"io"
 	"log"
 	"net"
 	"net/http"
@@ -46,12 +46,12 @@ func RoundTripper() *http.Transport {
 func ResponseModifier(state *utils.State, hostname string, reqBody []byte, c *gin.Context, currentListener *utils.HTTPHolder) func(*http.Response) error {
 	return func(response *http.Response) error {
 		if viper.GetBool("admin-console") || viper.GetBool("service-console") {
-			resBody, err := ioutil.ReadAll(response.Body)
+			resBody, err := io.ReadAll(response.Body)
 			if err != nil {
 				log.Println("Error reading response for webconsole:", err)
 			}
 
-			response.Body = ioutil.NopCloser(bytes.NewBuffer(resBody))
+			response.Body = io.NopCloser(bytes.NewBuffer(resBody))
 
 			startTime := c.GetTime("startTime")
 			currentTime := time.Now()
@@ -69,7 +69,7 @@ func ResponseModifier(state *utils.State, hostname string, reqBody []byte, c *gi
 					log.Println("Error reading gzip data:", err)
 				}
 
-				resBody, err = ioutil.ReadAll(gzReader)
+				resBody, err = io.ReadAll(gzReader)
 				if err != nil {
 					log.Println("Error reading gzip data:", err)
 				}

sshmuxer/handle.go

@@ -81,7 +81,7 @@ func handleChannels(chans <-chan ssh.NewChannel, sshConn *utils.SSHConnection, s
 	}
 }
 
-//  handleChannel handles a SSH connection's channel request.
+// handleChannel handles a SSH connection's channel request.
 func handleChannel(newChannel ssh.NewChannel, sshConn *utils.SSHConnection, state *utils.State) {
 	switch channel := newChannel.ChannelType(); channel {
 	case "session":

sshmuxer/requests.go

@@ -2,7 +2,6 @@ package sshmuxer
 
 import (
 	"fmt"
-	"io/ioutil"
 	"log"
 	"net"
 	"os"
@@ -92,7 +91,7 @@ func handleRemoteForward(newRequest *ssh.Request, sshConn *utils.SSHConnection,
 		}
 	}
 
-	tmpfile, err := ioutil.TempFile("", strings.ReplaceAll(sshConn.SSHConn.RemoteAddr().String()+":"+stringPort, ":", "_"))
+	tmpfile, err := os.CreateTemp("", strings.ReplaceAll(sshConn.SSHConn.RemoteAddr().String()+":"+stringPort, ":", "_"))
 	if err != nil {
 		log.Println("Error creating temporary file:", err)
 

sshmuxer/sshmuxer.go

@@ -66,7 +66,9 @@ func Start() {
 
 	go httpmuxer.Start(state)
 
-	if viper.GetBool("debug") {
+	debugInterval := viper.GetDuration("debug-interval")
+
+	if viper.GetBool("debug") && debugInterval > 0 {
 		go func() {
 			for {
 				log.Println("=======Start=========")
@@ -138,7 +140,7 @@ func Start() {
 				})
 				log.Print("========End==========\n")
 
-				time.Sleep(2 * time.Second)
+				time.Sleep(debugInterval)
 			}
 		}()
 	}

utils/utils.go

@@ -12,7 +12,6 @@ import (
 	"fmt"
 	"io"
 	"io/fs"
-	"io/ioutil"
 	"log"
 	mathrand "math/rand"
 	"net"
@@ -271,7 +270,7 @@ func loadPrivateKeys(config *ssh.ServerConfig) {
 			return nil
 		}
 
-		i, e := ioutil.ReadFile(path)
+		i, e := os.ReadFile(path)
 		if e != nil {
 			log.Printf("Can't read file %s as private key: %s\n", d.Name(), err)
 			return nil
@@ -418,7 +417,7 @@ func loadKeys() {
 			return nil
 		}
 
-		i, e := ioutil.ReadFile(path)
+		i, e := os.ReadFile(path)
 		if e != nil {
 			log.Printf("Can't read file %s as public key: %s\n", d.Name(), err)
 			return nil
@@ -519,7 +518,7 @@ func generatePrivateKey(passphrase string) []byte {
 		pemData = pem.EncodeToMemory(pemBlock)
 	}
 
-	err = ioutil.WriteFile(filepath.Join(viper.GetString("private-keys-directory"), "ssh_key"), pemData, 0600)
+	err = os.WriteFile(filepath.Join(viper.GetString("private-keys-directory"), "ssh_key"), pemData, 0600)
 	if err != nil {
 		log.Println("Error writing to file:", err)
 	}
@@ -532,7 +531,7 @@ func generatePrivateKey(passphrase string) []byte {
 func loadPrivateKey(passphrase string) ssh.Signer {
 	var signer ssh.Signer
 
-	pk, err := ioutil.ReadFile(filepath.Join(viper.GetString("private-keys-directory"), "ssh_key"))
+	pk, err := os.ReadFile(filepath.Join(viper.GetString("private-keys-directory"), "ssh_key"))
 	if err != nil {
 		log.Println("Error loading private key, generating a new one:", err)
 		pk = generatePrivateKey(passphrase)