From 63ebc0b3e5c9b2f09d009bafd81a47d68750573d Mon Sep 17 00:00:00 2001 From: Peter Portante Date: Wed, 26 Apr 2023 11:47:10 -0400 Subject: [PATCH] Add log entries with req headers to aid debugging The new published log entries in both the client and server contain the the original payload headers, and for the server the request ID, allowing one to track down behaviors from know sources (e.g. GitHub posts a list of events it sent to a web hook with the headers used). --- gosmee/client.go | 49 +++++++++++++++++++++++++++++++++++-------- gosmee/client_test.go | 5 +++-- gosmee/server.go | 10 +++++---- 3 files changed, 49 insertions(+), 15 deletions(-) diff --git a/gosmee/client.go b/gosmee/client.go index 081ec15..e925da7 100644 --- a/gosmee/client.go +++ b/gosmee/client.go @@ -36,6 +36,8 @@ const defaultTimeout = 5 const smeeChannel = "messages" +const tsFormat = "2006-01-02T15.04.01.000" + type goSmee struct { saveDir, smeeURL, targetURL string decorate, noReplay bool @@ -65,7 +67,8 @@ func title(source string) string { return cases.Title(language.Und, cases.NoLower).String(source) } -func (c goSmee) parse(data []byte) (payloadMsg, error) { +func (c goSmee) parse(now time.Time, data []byte) (payloadMsg, error) { + dt := now pm := payloadMsg{ headers: make(map[string]string), } @@ -127,7 +130,6 @@ func (c goSmee) parse(data []byte) (payloadMsg, error) { pm.contentType = pv } case "timestamp": - dt := time.Now().UTC() if pv, ok := payloadValue.(string); ok { // timestamp payload value is in milliseconds since the Epoch tsInt, err := strconv.ParseInt(pv, 10, 64) @@ -137,10 +139,11 @@ func (c goSmee) parse(data []byte) (payloadMsg, error) { dt = time.Unix(tsInt/int64(1000), (tsInt%int64(1000))*int64(1000000)).UTC() } } - pm.timestamp = dt.Format("2006-01-02T15.04.01.000") } } + pm.timestamp = dt.Format(tsFormat) + if len(c.ignoreEvents) > 0 && pm.eventType != "" { for _, v := range c.ignoreEvents { if v == pm.eventType { @@ -181,7 +184,7 @@ func (c goSmee) saveData(pm payloadMsg) error { return err } defer f.Close() - // // write data + // write data _, err = f.Write(pm.body) if err != nil { return err @@ -273,33 +276,61 @@ func (c goSmee) clientSetup() error { channel = smeeChannel } err := client.Subscribe(channel, func(msg *sse.Event) { + now := time.Now().UTC() + nowStr := now.Format(tsFormat) + if string(msg.Event) == "ready" || string(msg.Data) == "ready" { fmt.Fprintf(os.Stdout, - "%sForwarding %s to %s\n", c.emoji("✓", "yellow+b"), ansi.Color(c.smeeURL, "green+u"), + "%s %sForwarding %s to %s\n", + nowStr, + c.emoji("✓", "yellow+b"), + ansi.Color(c.smeeURL, "green+u"), ansi.Color(c.targetURL, "green+u")) return } - pm, err := c.parse(msg.Data) + pm, err := c.parse(now, msg.Data) if err != nil { - fmt.Fprintf(os.Stdout, "%s Parsing %s\n", ansi.Color("ERROR", "red+b"), err.Error()) + fmt.Fprintf(os.Stdout, + "%s %s parsing message %s\n", + nowStr, + ansi.Color("ERROR", "red+b"), + err.Error()) return } if len(pm.headers) == 0 { + fmt.Fprintf(os.Stdout, + "%s %s no headers found in message\n", + nowStr, + ansi.Color("ERROR", "red+b")) return } + headers := "" + for k, v := range pm.headers { + headers += fmt.Sprintf("%s=%s ", k, v) + } if string(msg.Data) != "{}" { if c.saveDir != "" { err := c.saveData(pm) if err != nil { - fmt.Fprintf(os.Stdout, "%s Saving %s\n", ansi.Color("ERROR", "red+b"), err.Error()) + fmt.Fprintf(os.Stdout, + "%s %s saving message with headers '%s' - %s\n", + nowStr, + ansi.Color("ERROR", "red+b"), + headers, + err.Error()) return } } if !c.noReplay { if err := c.replayData(pm); err != nil { - fmt.Fprintf(os.Stdout, "%s Forwarding %s\n", ansi.Color("ERROR", "red+b"), err.Error()) + fmt.Fprintf(os.Stdout, + "%s %s forwarding message with headers '%s' - %s\n", + nowStr, + ansi.Color("ERROR", "red+b"), + headers, + err.Error()) return } } diff --git a/gosmee/client_test.go b/gosmee/client_test.go index 61c0cde..dfd9c14 100644 --- a/gosmee/client_test.go +++ b/gosmee/client_test.go @@ -3,6 +3,7 @@ package gosmee import ( "strings" "testing" + "time" "gotest.tools/v3/assert" ) @@ -20,7 +21,7 @@ var simpleJSON = `{ func TestGoSmeeGood(t *testing.T) { p := goSmee{} - m, err := p.parse([]byte(simpleJSON)) + m, err := p.parse(time.Now().UTC(), []byte(simpleJSON)) assert.NilError(t, err) assert.Equal(t, m.headers["X-Foo"], "bar") assert.Equal(t, m.headers["User-Agent"], "gosmee") @@ -34,6 +35,6 @@ func TestGoSmeeGood(t *testing.T) { func TestGoSmeeBad(t *testing.T) { p := goSmee{} - pm, _ := p.parse([]byte(`xxxXXXxx`)) + pm, _ := p.parse(time.Now().UTC(), []byte(`xxxXXXxx`)) assert.Equal(t, string(pm.body), "") } diff --git a/gosmee/server.go b/gosmee/server.go index 5b4da76..3096992 100644 --- a/gosmee/server.go +++ b/gosmee/server.go @@ -37,7 +37,6 @@ func serve(c *cli.Context) error { publicURL := c.String("public-url") footer := c.String("footer") router := chi.NewRouter() - router.Use(middleware.Logger) router.Use(middleware.RequestID) router.Use(middleware.RealIP) router.Use(middleware.Logger) @@ -97,7 +96,7 @@ func serve(c *cli.Context) error { }) router.Post("/{channel:[a-zA-Z0-9]{12,}}", func(w http.ResponseWriter, r *http.Request) { // grab current time stamp before we take any further actions - timestamp := time.Now().UTC().UnixMilli() + now := time.Now().UTC() // check if we have content-type json if !strings.Contains(r.Header.Get("Content-Type"), "application/json") { errorIt(w, r, http.StatusBadRequest, fmt.Errorf("content-type must be application/json")) @@ -115,13 +114,15 @@ func serve(c *cli.Context) error { errorIt(w, r, http.StatusBadRequest, err) return } - // convert headers to map[string]string + // convert headers to map[string]string and accumlate for log entry + headers := "" payload := map[string]interface{}{} for k, v := range r.Header { + headers += fmt.Sprintf(" %s=%s", k, v) payload[strings.ToLower(k)] = v[0] } // easier with base64 for server instead of string - payload["timestamp"] = fmt.Sprintf("%d", timestamp) + payload["timestamp"] = fmt.Sprintf("%d", now.UnixMilli()) payload["bodyB"] = base64.StdEncoding.EncodeToString(body) reencoded, err := json.Marshal(payload) if err != nil { @@ -135,6 +136,7 @@ func serve(c *cli.Context) error { w.WriteHeader(http.StatusAccepted) fmt.Fprintf(w, "{\"status\": %d, \"channel\": \"%s\", \"message\": \"ok\"}\n", http.StatusAccepted, channel) + fmt.Fprintf(os.Stdout, "%s Published %s%s on channel %s\n", now.Format("2006-01-02T15.04.01.000"), middleware.GetReqID(r.Context()), headers, channel) }) config := goSmee{}