Skip to content

Commit 3e108df

Browse files
christophwitzkochristophwitzko
committed
feat: improve structured logging
1 parent f85ad09 commit 3e108df

File tree

5 files changed

+71
-17
lines changed

5 files changed

+71
-17
lines changed

‎cmd/plugin-registry/main.go‎

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -20,9 +20,20 @@ var version = "dev"
2020

2121
func setupLogger() *logrus.Logger {
2222
log := logrus.New()
23-
log.SetFormatter(&logrus.TextFormatter{
24-
FullTimestamp: true,
25-
})
23+
if os.Getenv("DEBUG") == "true" {
24+
log.SetFormatter(&logrus.TextFormatter{
25+
FullTimestamp: true,
26+
})
27+
} else {
28+
log.SetFormatter(&logrus.JSONFormatter{
29+
FieldMap: logrus.FieldMap{
30+
logrus.FieldKeyLevel: "severity",
31+
logrus.FieldKeyMsg: "message",
32+
logrus.FieldKeyTime: "timestamp",
33+
},
34+
})
35+
}
36+
2637
return log
2738
}
2839

‎internal/server/handler_batch.go‎

Lines changed: 8 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -81,13 +81,14 @@ func (s *Server) batchGetPlugins(w http.ResponseWriter, r *http.Request) {
8181
return
8282
}
8383

84+
reqLogger := s.requestLogger(r)
8485
batchResponse := registry.NewBatchResponse(batchRequest, pluginResponses)
8586

8687
// hash the batch request without the resolved versions
8788
batchRequestCacheKey := s.getCacheKeyWithPrefix(cacheKeyPrefixBatchRequest, hex.EncodeToString(batchResponse.Hash()))
8889
cachedBatchResponse, found := s.getFromCache(batchRequestCacheKey)
8990
if found {
90-
s.log.Infof("found cached batch response for %s", batchRequestCacheKey)
91+
reqLogger.Infof("found cached batch response for %s", batchRequestCacheKey)
9192
s.writeJSON(w, cachedBatchResponse)
9293
return
9394
}
@@ -150,7 +151,7 @@ func (s *Server) batchGetPlugins(w http.ResponseWriter, r *http.Request) {
150151
})
151152
if err == nil {
152153
// the archive already exists, return the response
153-
s.log.Infof("found cached archive %s", archiveKey)
154+
reqLogger.Infof("found cached archive %s", archiveKey)
154155
batchResponse.DownloadChecksum = headRes.Metadata["checksum"]
155156
s.setInCache(batchRequestCacheKey, batchResponse)
156157
s.writeJSON(w, batchResponse)
@@ -163,14 +164,14 @@ func (s *Server) batchGetPlugins(w http.ResponseWriter, r *http.Request) {
163164
return
164165
}
165166

166-
s.log.Infof("plugin archive %s not found, creating (%d plugins for %s)...", archiveKey, len(batchResponse.Plugins), batchResponse.GetOSArch())
167+
reqLogger.Infof("plugin archive %s not found, creating (%d plugins for %s)...", archiveKey, len(batchResponse.Plugins), batchResponse.GetOSArch())
167168
tgzFileName, tgzChecksum, err := batch.DownloadFilesAndTarGz(r.Context(), batchResponse)
168169
if err != nil {
169170
s.writeJSONError(w, r, http.StatusInternalServerError, err, "could not create plugin archive")
170171
return
171172
}
172173
batchResponse.DownloadChecksum = tgzChecksum
173-
s.log.Infof("created plugin archive %s, uploading...", tgzFileName)
174+
reqLogger.Infof("created plugin archive %s, uploading...", tgzFileName)
174175
tarFile, err := os.Open(tgzFileName)
175176
if err != nil {
176177
s.writeJSONError(w, r, http.StatusInternalServerError, err, "could not open plugin archive")
@@ -190,16 +191,16 @@ func (s *Server) batchGetPlugins(w http.ResponseWriter, r *http.Request) {
190191
},
191192
})
192193
if closeErr := tarFile.Close(); closeErr != nil {
193-
s.log.Errorf("could not close plugin archive file: %v", closeErr)
194+
reqLogger.Errorf("could not close plugin archive file: %v", closeErr)
194195
}
195196
if err != nil {
196197
s.writeJSONError(w, r, http.StatusInternalServerError, err, "could not upload plugin archive")
197198
return
198199
}
199200

200-
s.log.Infof("uploaded plugin archive.")
201+
reqLogger.Infof("uploaded plugin archive.")
201202
if rmErr := os.Remove(tgzFileName); rmErr != nil {
202-
s.log.Errorf("could not remove plugin archive file: %v", rmErr)
203+
reqLogger.Errorf("could not remove plugin archive file: %v", rmErr)
203204
}
204205

205206
s.setInCache(batchRequestCacheKey, batchResponse)

‎internal/server/handlers.go‎

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -24,9 +24,10 @@ func (s *Server) updateAllPlugins(w http.ResponseWriter, r *http.Request) {
2424
}
2525
defer s.ghSemaphore.Release(1)
2626

27-
s.log.Warn("updating all plugins...")
27+
reqLogger := s.requestLogger(r)
28+
reqLogger.Warn("updating all plugins...")
2829
for _, p := range config.Plugins {
29-
s.log.Infof("updating plugin %s", p.GetFullName())
30+
reqLogger.Infof("updating plugin %s", p.GetFullName())
3031
err := p.Update(r.Context(), s.db, s.ghClient, "")
3132
if err != nil {
3233
s.writeJSONError(w, r, http.StatusInternalServerError, err, "could not update plugin")
@@ -50,7 +51,8 @@ func (s *Server) updatePlugin(w http.ResponseWriter, r *http.Request) {
5051
s.writeJSONError(w, r, http.StatusNotFound, fmt.Errorf("plugin %s not found", pluginName))
5152
return
5253
}
53-
s.log.Infof("updating plugin %s@%s", p.GetFullName(), pluginVersion)
54+
reqLogger := s.requestLogger(r)
55+
reqLogger.Infof("updating plugin %s@%s", p.GetFullName(), pluginVersion)
5456

5557
err := s.ghSemaphore.Acquire(r.Context(), 1)
5658
if err != nil {
@@ -80,6 +82,7 @@ func (s *Server) getPlugin(w http.ResponseWriter, r *http.Request) {
8082
s.writeJSONError(w, r, http.StatusNotFound, fmt.Errorf("plugin %s not found", pluginName))
8183
return
8284
}
85+
8386
var err error
8487
var res any
8588
if pluginVersion == "" {
@@ -91,6 +94,7 @@ func (s *Server) getPlugin(w http.ResponseWriter, r *http.Request) {
9194
s.writeJSONError(w, r, http.StatusInternalServerError, err, "could not get plugin")
9295
return
9396
}
97+
9498
s.setInCache(s.getCacheKeyFromRequest(r), res)
9599
s.writeJSON(w, res)
96100
}
@@ -108,6 +112,7 @@ func (s *Server) listPluginVersions(w http.ResponseWriter, r *http.Request) {
108112
s.writeJSONError(w, r, http.StatusInternalServerError, err, "could not get plugin versions")
109113
return
110114
}
115+
111116
s.setInCache(s.getCacheKeyFromRequest(r), versions)
112117
s.writeJSON(w, versions)
113118
}

‎internal/server/helper.go‎

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"strings"
77

88
"github.com/go-chi/chi/v5/middleware"
9+
"github.com/sirupsen/logrus"
910
)
1011

1112
func (s *Server) setContentTypeJSON(w http.ResponseWriter) {
@@ -22,7 +23,14 @@ func (s *Server) writeJSON(w http.ResponseWriter, d any) {
2223

2324
func (s *Server) writeJSONError(w http.ResponseWriter, r *http.Request, statusCode int, err error, alternativeMessage ...string) {
2425
errMsg := err.Error()
25-
s.log.Errorf("[%s] error(status=%d): %s", middleware.GetReqID(r.Context()), statusCode, errMsg)
26+
s.log.WithFields(logrus.Fields{
27+
LogFieldRequestID: middleware.GetReqID(r.Context()),
28+
LogFieldHTTPRequest: map[string]any{
29+
"requestMethod": r.Method,
30+
"requestUrl": r.URL.EscapedPath(),
31+
"status": statusCode,
32+
},
33+
}).Errorf("error: %s", errMsg)
2634

2735
s.setContentTypeJSON(w)
2836
w.WriteHeader(statusCode)
@@ -32,3 +40,13 @@ func (s *Server) writeJSONError(w http.ResponseWriter, r *http.Request, statusCo
3240
}
3341
s.writeJSON(w, map[string]string{"error": errMsg})
3442
}
43+
44+
func (s *Server) requestLogger(r *http.Request) *logrus.Entry {
45+
return s.log.WithFields(logrus.Fields{
46+
LogFieldRequestID: middleware.GetReqID(r.Context()),
47+
LogFieldHTTPRequest: map[string]any{
48+
"requestMethod": r.Method,
49+
"requestUrl": r.URL.EscapedPath(),
50+
},
51+
})
52+
}

‎internal/server/middleware.go‎

Lines changed: 22 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3,8 +3,15 @@ package server
33
import (
44
"fmt"
55
"net/http"
6+
"strings"
67

78
"github.com/go-chi/chi/v5/middleware"
9+
"github.com/sirupsen/logrus"
10+
)
11+
12+
var (
13+
LogFieldRequestID = "request_id"
14+
LogFieldHTTPRequest = "httpRequest"
815
)
916

1017
func (s *Server) authMiddleware(next http.Handler) http.Handler {
@@ -14,6 +21,9 @@ func (s *Server) authMiddleware(next http.Handler) http.Handler {
1421
return
1522
}
1623
if r.Header.Get("Authorization") != s.config.AdminAccessToken {
24+
s.log.
25+
WithField(LogFieldRequestID, middleware.GetReqID(r.Context())).
26+
Warnf("invalid access token from %s", r.RemoteAddr)
1727
s.writeJSONError(w, r, http.StatusUnauthorized, fmt.Errorf("invalid access token"))
1828
return
1929
}
@@ -23,7 +33,17 @@ func (s *Server) authMiddleware(next http.Handler) http.Handler {
2333

2434
func (s *Server) logMiddleware(next http.Handler) http.Handler {
2535
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
26-
s.log.Printf("[%s] %s %s (%s)", middleware.GetReqID(r.Context()), r.Method, r.URL.EscapedPath(), r.RemoteAddr)
36+
remoteIP, _, _ := strings.Cut(r.RemoteAddr, ":")
37+
s.log.
38+
WithFields(logrus.Fields{
39+
LogFieldRequestID: middleware.GetReqID(r.Context()),
40+
LogFieldHTTPRequest: map[string]string{
41+
"requestMethod": r.Method,
42+
"requestUrl": r.URL.EscapedPath(),
43+
"remoteIp": remoteIP,
44+
},
45+
}).
46+
Infof("%s %s (%s)", r.Method, r.URL.EscapedPath(), r.RemoteAddr)
2747
next.ServeHTTP(w, r)
2848
})
2949
}
@@ -32,8 +52,7 @@ func (s *Server) recoverMiddleware(next http.Handler) http.Handler {
3252
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
3353
defer func() {
3454
if rec := recover(); rec != nil {
35-
s.log.Errorf("panic: %v", rec)
36-
s.writeJSONError(w, r, http.StatusInternalServerError, fmt.Errorf("internal server error"))
55+
s.writeJSONError(w, r, http.StatusInternalServerError, fmt.Errorf("panic: %v", rec))
3756
}
3857
}()
3958
next.ServeHTTP(w, r)

0 commit comments

Comments
 (0)