diff --git a/gateway/nginx/conf.d/shellhub.conf b/gateway/nginx/conf.d/shellhub.conf index fd8b68c0970..1c4b58bcca4 100644 --- a/gateway/nginx/conf.d/shellhub.conf +++ b/gateway/nginx/conf.d/shellhub.conf @@ -258,6 +258,7 @@ server { {{ end -}} proxy_set_header X-Device-UID $device_uid; proxy_set_header X-Tenant-ID $tenant_id; + proxy_set_header X-Request-ID $request_id; proxy_http_version 1.1; proxy_cache_bypass $http_upgrade; proxy_redirect off; diff --git a/pkg/connman/connman.go b/pkg/connman/connman.go index fbc6c8a799d..bf30e5faae2 100644 --- a/pkg/connman/connman.go +++ b/pkg/connman/connman.go @@ -4,10 +4,12 @@ import ( "context" "errors" "net" + "os" + "strings" "github.com/shellhub-io/shellhub/pkg/revdial" "github.com/shellhub-io/shellhub/pkg/wsconnadapter" - "github.com/sirupsen/logrus" + log "github.com/sirupsen/logrus" ) var ErrNoConnection = errors.New("no connection") @@ -27,12 +29,23 @@ func New() *ConnectionManager { } func (m *ConnectionManager) Set(key string, conn *wsconnadapter.Adapter, connPath string) { - dialer := revdial.NewDialer(conn, connPath) + parts := strings.Split(key, ":") + logger := (&log.Logger{ + Out: os.Stderr, + Formatter: log.StandardLogger().Formatter, + Hooks: log.StandardLogger().Hooks, + Level: log.StandardLogger().Level, + }).WithFields(log.Fields{ + "tenant": parts[0], + "device": parts[1], + }) + + dialer := revdial.NewDialer(logger, conn, connPath) m.dialers.Store(key, dialer) if size := m.dialers.Size(key); size > 1 { - logrus.WithFields(logrus.Fields{ + log.WithFields(log.Fields{ "key": key, "size": size, }).Warning("Multiple connections stored for the same identifier.") @@ -67,7 +80,7 @@ func (m *ConnectionManager) Dial(ctx context.Context, key string) (net.Conn, err } if size := m.dialers.Size(key); size > 1 { - logrus.WithFields(logrus.Fields{ + log.WithFields(log.Fields{ "key": key, "size": size, }).Warning("Multiple connections found for the same identifier during reverse tunnel dialing.") diff --git a/pkg/httptunnel/httptunnel.go b/pkg/httptunnel/httptunnel.go index a597bfaafa5..af2996c98cc 100644 --- a/pkg/httptunnel/httptunnel.go +++ b/pkg/httptunnel/httptunnel.go @@ -6,12 +6,14 @@ import ( "io" "net" "net/http" + "strings" "github.com/gorilla/websocket" "github.com/labstack/echo/v4" "github.com/shellhub-io/shellhub/pkg/connman" "github.com/shellhub-io/shellhub/pkg/revdial" "github.com/shellhub-io/shellhub/pkg/wsconnadapter" + log "github.com/sirupsen/logrus" ) var upgrader = websocket.Upgrader{ @@ -75,14 +77,21 @@ func (t *Tunnel) Router() http.Handler { return c.String(http.StatusInternalServerError, err.Error()) } - id, err := t.ConnectionHandler(c.Request()) + key, err := t.ConnectionHandler(c.Request()) if err != nil { conn.Close() return c.String(http.StatusBadRequest, err.Error()) } - t.connman.Set(id, wsconnadapter.New(conn), t.DialerPath) + parts := strings.Split(key, ":") + log.WithFields(log.Fields{ + "request-id": c.Request().Header.Get("X-Request-ID"), + "tenant": parts[0], + "device": parts[1], + }).Debug("new ssh connection") + + t.connman.Set(key, wsconnadapter.New(conn), t.DialerPath) return nil }) diff --git a/pkg/revdial/revdial.go b/pkg/revdial/revdial.go index 39fe0911194..41277e00adf 100644 --- a/pkg/revdial/revdial.go +++ b/pkg/revdial/revdial.go @@ -24,7 +24,6 @@ import ( "encoding/json" "errors" "fmt" - "log" "net" "net/http" "strings" @@ -34,11 +33,13 @@ import ( "github.com/gorilla/websocket" "github.com/shellhub-io/shellhub/pkg/clock" "github.com/shellhub-io/shellhub/pkg/wsconnadapter" - "github.com/sirupsen/logrus" + log "github.com/sirupsen/logrus" ) -var ErrDialerClosed = errors.New("revdial.Dialer closed") -var ErrDialerTimedout = errors.New("revdial.Dialer timedout") +var ( + ErrDialerClosed = errors.New("revdial.Dialer closed") + ErrDialerTimedout = errors.New("revdial.Dialer timedout") +) // dialerUniqParam is the parameter name of the GET URL form value // containing the Dialer's random unique ID. @@ -59,11 +60,10 @@ type Dialer struct { connReady chan bool donec chan struct{} closeOnce sync.Once + logger *log.Entry } -var ( - dialers = sync.Map{} -) +var dialers = sync.Map{} // NewDialer returns the side of the connection which will initiate // new connections. This will typically be the side which did the HTTP @@ -71,7 +71,7 @@ var ( // connection. The connPath is the HTTP path and optional query (but // without scheme or host) on the dialer where the ConnHandler is // mounted. -func NewDialer(c net.Conn, connPath string) *Dialer { +func NewDialer(logger *log.Entry, c net.Conn, connPath string) *Dialer { d := &Dialer{ path: connPath, uniqID: newUniqID(), @@ -80,6 +80,7 @@ func NewDialer(c net.Conn, connPath string) *Dialer { connReady: make(chan bool), incomingConn: make(chan net.Conn), pickupFailed: make(chan error), + logger: logger, } join := "?" @@ -121,6 +122,8 @@ func (d *Dialer) Close() error { } func (d *Dialer) close() { + d.logger.Debug("dialer connection closed") + d.unregister() d.conn.Close() d.donec <- struct{}{} @@ -165,21 +168,24 @@ func (d *Dialer) serve() error { go func() { defer d.Close() + defer d.logger.Debug("dialer serve done due reader error") br := bufio.NewReader(d.conn) for { line, err := br.ReadSlice('\n') if err != nil { + d.logger.WithError(err).Debug("failed to read the agent's command") + unexpectedError := websocket.IsUnexpectedCloseError(err, websocket.CloseGoingAway, websocket.CloseAbnormalClosure) if !errors.Is(err, net.ErrClosed) && unexpectedError { - logrus.WithError(err).Error("revdial.Dialer failed to read") + d.logger.WithError(err).Error("revdial.Dialer failed to read") } return } var msg controlMsg if err := json.Unmarshal(line, &msg); err != nil { - log.Printf("revdial.Dialer read invalid JSON: %q: %v", line, err) + d.logger.Printf("revdial.Dialer read invalid JSON: %q: %v", line, err) return } @@ -190,16 +196,21 @@ func (d *Dialer) serve() error { select { case d.pickupFailed <- err: case <-d.donec: + d.logger.WithError(err).Debug("failed to pick-up connection") + return } case "keep-alive": default: // Ignore unknown messages + log.WithField("message", msg.Command).Debug("unknown message received") } } }() for { if err := d.sendMessage(controlMsg{Command: "keep-alive"}); err != nil { + d.logger.WithError(err).Debug("failed to send keep-alive message to device") + return err } @@ -213,6 +224,8 @@ func (d *Dialer) serve() error { Command: "conn-ready", ConnPath: d.pickupPath, }); err != nil { + d.logger.WithError(err).Debug("failed to send conn-ready message to device") + return err } case <-d.donec: @@ -225,6 +238,8 @@ func (d *Dialer) serve() error { func (d *Dialer) sendMessage(m controlMsg) error { if err := d.conn.SetWriteDeadline(clock.Now().Add(10 * time.Second)); err != nil { + d.logger.WithError(err).Debug("failed to set the write dead line to device") + return err } @@ -232,6 +247,8 @@ func (d *Dialer) sendMessage(m controlMsg) error { j = append(j, '\n') if _, err := d.conn.Write(j); err != nil { + d.logger.WithError(err).Debug("failed to write on the connection") + return err } diff --git a/pkg/wsconnadapter/wsconnadapter.go b/pkg/wsconnadapter/wsconnadapter.go index 19ab06b57ca..0b9a0d2605c 100644 --- a/pkg/wsconnadapter/wsconnadapter.go +++ b/pkg/wsconnadapter/wsconnadapter.go @@ -8,7 +8,7 @@ import ( "time" "github.com/gorilla/websocket" - "github.com/sirupsen/logrus" + log "github.com/sirupsen/logrus" ) // an adapter for representing WebSocket connection as a net.Conn @@ -71,9 +71,11 @@ func (a *Adapter) Ping() chan bool { select { case <-ticker.C: if err := a.conn.WriteControl(websocket.PingMessage, []byte{}, time.Now().Add(5*time.Second)); err != nil { - logrus.WithError(err).Error("Failed to write ping message") + log.WithError(err).Error("Failed to write ping message") } case <-a.stopPingCh: + log.Debug("Stop ping message received") + return } }