oss/miniflux-v2
oss/miniflux-v2
1
0
Fork 0
mirror of https://github.com/miniflux/v2.git synced 2025-08-01 17:38:37 +00:00
Code Wiki Activity

Implement structured logging using log/slog package

Browse source
This commit is contained in:
Frédéric Guillot 2023-09-24 16:32:09 -07:00
parent 54cb8fa028
commit c0e954f19d
77 changed files with 1868 additions and 892 deletions
Download patch file Download diff file Expand all files Collapse all files

126
internal/http/client/client.go
View file

@ -7,19 +7,16 @@ import (
"bytes"
"crypto/tls"
"crypto/x509"
"encoding/json"
"fmt"
"io"
"log/slog"
"net"
"net/http"
"net/url"
"strings"
"time"
"miniflux.app/v2/internal/config"
"miniflux.app/v2/internal/errors"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/timer"
)
const (
@ -74,28 +71,6 @@ func NewClientWithConfig(url string, opts *config.Options) *Client {
}
}
func (c *Client) String() string {
etagHeader := c.requestEtagHeader
if c.requestEtagHeader == "" {
etagHeader = "None"
}
lastModifiedHeader := c.requestLastModifiedHeader
if c.requestLastModifiedHeader == "" {
lastModifiedHeader = "None"
}
return fmt.Sprintf(
`InputURL=%q ETag=%s LastMod=%s Auth=%v UserAgent=%q Verify=%v`,
c.inputURL,
etagHeader,
lastModifiedHeader,
c.requestAuthorizationHeader != "" || (c.requestUsername != "" && c.requestPassword != ""),
c.requestUserAgent,
!c.AllowSelfSignedCertificates,
)
}
// WithCredentials defines the username/password for HTTP Basic authentication.
func (c *Client) WithCredentials(username, password string) *Client {
if username != "" && password != "" {
@ -105,12 +80,6 @@ func (c *Client) WithCredentials(username, password string) *Client {
return c
}
// WithAuthorization defines the authorization HTTP header value.
func (c *Client) WithAuthorization(authorization string) *Client {
c.requestAuthorizationHeader = authorization
return c
}
// WithCustomHeaders defines custom HTTP headers.
func (c *Client) WithCustomHeaders(customHeaders map[string]string) *Client {
c.customHeaders = customHeaders
@ -162,55 +131,21 @@ func (c *Client) Get() (*Response, error) {
return c.executeRequest(request)
}
// PostForm performs a POST HTTP request with form encoded values.
func (c *Client) PostForm(values url.Values) (*Response, error) {
request, err := c.buildRequest(http.MethodPost, strings.NewReader(values.Encode()))
if err != nil {
return nil, err
}
request.Header.Add("Content-Type", "application/x-www-form-urlencoded")
return c.executeRequest(request)
}
// PostJSON performs a POST HTTP request with a JSON payload.
func (c *Client) PostJSON(data interface{}) (*Response, error) {
b, err := json.Marshal(data)
if err != nil {
return nil, err
}
request, err := c.buildRequest(http.MethodPost, bytes.NewReader(b))
if err != nil {
return nil, err
}
request.Header.Add("Content-Type", "application/json")
return c.executeRequest(request)
}
// PatchJSON performs a Patch HTTP request with a JSON payload.
func (c *Client) PatchJSON(data interface{}) (*Response, error) {
b, err := json.Marshal(data)
if err != nil {
return nil, err
}
request, err := c.buildRequest(http.MethodPatch, bytes.NewReader(b))
if err != nil {
return nil, err
}
request.Header.Add("Content-Type", "application/json")
return c.executeRequest(request)
}
func (c *Client) executeRequest(request *http.Request) (*Response, error) {
defer timer.ExecutionTime(time.Now(), fmt.Sprintf("[HttpClient] inputURL=%s", c.inputURL))
startTime := time.Now()
logger.Debug("[HttpClient:Before] Method=%s %s",
request.Method,
c.String(),
slog.Debug("Executing outgoing HTTP request",
slog.Group("request",
slog.String("method", request.Method),
slog.String("url", request.URL.String()),
slog.String("user_agent", request.UserAgent()),
slog.Bool("is_authenticated", c.requestAuthorizationHeader != "" || (c.requestUsername != "" && c.requestPassword != "")),
slog.Bool("has_cookie", c.requestCookie != ""),
slog.Bool("with_redirects", !c.doNotFollowRedirects),
slog.Bool("with_proxy", c.useProxy),
slog.String("proxy_url", c.ClientProxyURL),
slog.Bool("with_caching_headers", c.requestEtagHeader != "" || c.requestLastModifiedHeader != ""),
),
)
client := c.buildClient()
@ -257,15 +192,32 @@ func (c *Client) executeRequest(request *http.Request) (*Response, error) {
ContentLength: resp.ContentLength,
}
logger.Debug("[HttpClient:After] Method=%s %s; Response => %s",
request.Method,
c.String(),
response,
slog.Debug("Completed outgoing HTTP request",
slog.Duration("duration", time.Since(startTime)),
slog.Group("request",
slog.String("method", request.Method),
slog.String("url", request.URL.String()),
slog.String("user_agent", request.UserAgent()),
slog.Bool("is_authenticated", c.requestAuthorizationHeader != "" || (c.requestUsername != "" && c.requestPassword != "")),
slog.Bool("has_cookie", c.requestCookie != ""),
slog.Bool("with_redirects", !c.doNotFollowRedirects),
slog.Bool("with_proxy", c.useProxy),
slog.String("proxy_url", c.ClientProxyURL),
slog.Bool("with_caching_headers", c.requestEtagHeader != "" || c.requestLastModifiedHeader != ""),
),
slog.Group("response",
slog.Int("status_code", response.StatusCode),
slog.String("effective_url", response.EffectiveURL),
slog.String("content_type", response.ContentType),
slog.Int64("content_length", response.ContentLength),
slog.String("last_modified", response.LastModified),
slog.String("etag", response.ETag),
slog.String("expires", response.Expires),
),
)
// Ignore caching headers for feeds that do not want any cache.
if resp.Header.Get("Expires") == "0" {
logger.Debug("[HttpClient] Ignore caching headers for %q", response.EffectiveURL)
response.ETag = ""
response.LastModified = ""
}
@ -323,9 +275,11 @@ func (c *Client) buildClient() http.Client {
if c.useProxy && c.ClientProxyURL != "" {
proxyURL, err := url.Parse(c.ClientProxyURL)
if err != nil {
logger.Error("[HttpClient] Proxy URL error: %v", err)
slog.Error("Unable to parse proxy URL",
slog.String("proxy_url", c.ClientProxyURL),
slog.Any("error", err),
)
} else {
logger.Debug("[HttpClient] Use proxy: %s", proxyURL)
transport.Proxy = http.ProxyURL(proxyURL)
}
}

5
internal/http/response/builder.go
View file

@ -8,11 +8,10 @@ import (
"compress/gzip"
"fmt"
"io"
"log/slog"
"net/http"
"strings"
"time"
"miniflux.app/v2/internal/logger"
)
const compressionThreshold = 1024
@ -91,7 +90,7 @@ func (b *Builder) Write() {
b.writeHeaders()
_, err := io.Copy(b.w, v)
if err != nil {
logger.Error("%v", err)
slog.Error("Unable to write response body", slog.Any("error", err))
}
}
}

65
internal/http/response/html/html.go
View file

@ -4,10 +4,11 @@
package html // import "miniflux.app/v2/internal/http/response/html"
import (
"log/slog"
"net/http"
"miniflux.app/v2/internal/http/request"
"miniflux.app/v2/internal/http/response"
"miniflux.app/v2/internal/logger"
)
// OK creates a new HTML response with a 200 status code.
@ -21,7 +22,18 @@ func OK(w http.ResponseWriter, r *http.Request, body interface{}) {
// ServerError sends an internal error to the client.
func ServerError(w http.ResponseWriter, r *http.Request, err error) {
logger.Error("[HTTP:Internal Server Error] %s => %v", r.URL, err)
slog.Error(http.StatusText(http.StatusInternalServerError),
slog.Any("error", err),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusInternalServerError),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusInternalServerError)
@ -34,7 +46,18 @@ func ServerError(w http.ResponseWriter, r *http.Request, err error) {
// BadRequest sends a bad request error to the client.
func BadRequest(w http.ResponseWriter, r *http.Request, err error) {
logger.Error("[HTTP:Bad Request] %s => %v", r.URL, err)
slog.Warn(http.StatusText(http.StatusBadRequest),
slog.Any("error", err),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusBadRequest),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusBadRequest)
@ -47,7 +70,17 @@ func BadRequest(w http.ResponseWriter, r *http.Request, err error) {
// Forbidden sends a forbidden error to the client.
func Forbidden(w http.ResponseWriter, r *http.Request) {
logger.Error("[HTTP:Forbidden] %s", r.URL)
slog.Warn(http.StatusText(http.StatusForbidden),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusForbidden),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusForbidden)
@ -59,7 +92,17 @@ func Forbidden(w http.ResponseWriter, r *http.Request) {
// NotFound sends a page not found error to the client.
func NotFound(w http.ResponseWriter, r *http.Request) {
logger.Error("[HTTP:Not Found] %s", r.URL)
slog.Warn(http.StatusText(http.StatusNotFound),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusNotFound),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusNotFound)
@ -76,7 +119,17 @@ func Redirect(w http.ResponseWriter, r *http.Request, uri string) {
// RequestedRangeNotSatisfiable sends a range not satisfiable error to the client.
func RequestedRangeNotSatisfiable(w http.ResponseWriter, r *http.Request, contentRange string) {
logger.Error("[HTTP:Range Not Satisfiable] %s", r.URL)
slog.Warn(http.StatusText(http.StatusRequestedRangeNotSatisfiable),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusRequestedRangeNotSatisfiable),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusRequestedRangeNotSatisfiable)

67
internal/http/response/json/json.go
View file

@ -6,10 +6,11 @@ package json // import "miniflux.app/v2/internal/http/response/json"
import (
"encoding/json"
"errors"
"log/slog"
"net/http"
"miniflux.app/v2/internal/http/request"
"miniflux.app/v2/internal/http/response"
"miniflux.app/v2/internal/logger"
)
const contentTypeHeader = `application/json`
@ -48,7 +49,18 @@ func Accepted(w http.ResponseWriter, r *http.Request) {
// ServerError sends an internal error to the client.
func ServerError(w http.ResponseWriter, r *http.Request, err error) {
logger.Error("[HTTP:Internal Server Error] %s => %v", r.URL, err)
slog.Error(http.StatusText(http.StatusInternalServerError),
slog.Any("error", err),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusInternalServerError),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusInternalServerError)
@ -59,7 +71,18 @@ func ServerError(w http.ResponseWriter, r *http.Request, err error) {
// BadRequest sends a bad request error to the client.
func BadRequest(w http.ResponseWriter, r *http.Request, err error) {
logger.Error("[HTTP:Bad Request] %s => %v", r.URL, err)
slog.Warn(http.StatusText(http.StatusBadRequest),
slog.Any("error", err),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusBadRequest),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusBadRequest)
@ -70,7 +93,17 @@ func BadRequest(w http.ResponseWriter, r *http.Request, err error) {
// Unauthorized sends a not authorized error to the client.
func Unauthorized(w http.ResponseWriter, r *http.Request) {
logger.Error("[HTTP:Unauthorized] %s", r.URL)
slog.Warn(http.StatusText(http.StatusUnauthorized),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusUnauthorized),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusUnauthorized)
@ -81,7 +114,17 @@ func Unauthorized(w http.ResponseWriter, r *http.Request) {
// Forbidden sends a forbidden error to the client.
func Forbidden(w http.ResponseWriter, r *http.Request) {
logger.Error("[HTTP:Forbidden] %s", r.URL)
slog.Warn(http.StatusText(http.StatusForbidden),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusForbidden),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusForbidden)
@ -92,7 +135,17 @@ func Forbidden(w http.ResponseWriter, r *http.Request) {
// NotFound sends a page not found error to the client.
func NotFound(w http.ResponseWriter, r *http.Request) {
logger.Error("[HTTP:Not Found] %s", r.URL)
slog.Warn(http.StatusText(http.StatusNotFound),
slog.String("client_ip", request.ClientIP(r)),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("user_agent", r.UserAgent()),
),
slog.Group("response",
slog.Int("status_code", http.StatusNotFound),
),
)
builder := response.New(w, r)
builder.WithStatus(http.StatusNotFound)
@ -112,7 +165,7 @@ func toJSONError(err error) []byte {
func toJSON(v interface{}) []byte {
b, err := json.Marshal(v)
if err != nil {
logger.Error("[HTTP:JSON] %v", err)
slog.Error("Unable to marshal JSON response", slog.Any("error", err))
return []byte("")
}

7
internal/http/route/route.go
View file

@ -7,14 +7,13 @@ import (
"strconv"
"github.com/gorilla/mux"
"miniflux.app/v2/internal/logger"
)
// Path returns the defined route based on given arguments.
func Path(router *mux.Router, name string, args ...interface{}) string {
func Path(router *mux.Router, name string, args ...any) string {
route := router.Get(name)
if route == nil {
logger.Fatal("[Route] Route not found: %s", name)
panic("route not found: " + name)
}
var pairs []string
@ -29,7 +28,7 @@ func Path(router *mux.Router, name string, args ...interface{}) string {
result, err := route.URLPath(pairs...)
if err != nil {
logger.Fatal("[Route] %v", err)
panic(err)
}
return result.String()

84
internal/http/server/httpd.go
View file

@ -5,6 +5,8 @@ package httpd // import "miniflux.app/v2/internal/http/server"
import (
"crypto/tls"
"fmt"
"log/slog"
"net"
"net/http"
"os"
@ -17,7 +19,6 @@ import (
"miniflux.app/v2/internal/fever"
"miniflux.app/v2/internal/googlereader"
"miniflux.app/v2/internal/http/request"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/storage"
"miniflux.app/v2/internal/ui"
"miniflux.app/v2/internal/version"
@ -66,12 +67,12 @@ func startSystemdSocketServer(server *http.Server) {
f := os.NewFile(3, "systemd socket")
listener, err := net.FileListener(f)
if err != nil {
logger.Fatal(`Unable to create listener from systemd socket: %v`, err)
printErrorAndExit(`Unable to create listener from systemd socket: %v`, err)
}
logger.Info(`Listening on systemd socket`)
slog.Info(`Starting server using systemd socket`)
if err := server.Serve(listener); err != http.ErrServerClosed {
logger.Fatal(`Server failed to start: %v`, err)
printErrorAndExit(`Server failed to start: %v`, err)
}
}()
}
@ -82,17 +83,17 @@ func startUnixSocketServer(server *http.Server, socketFile string) {
go func(sock string) {
listener, err := net.Listen("unix", sock)
if err != nil {
logger.Fatal(`Server failed to start: %v`, err)
printErrorAndExit(`Server failed to start: %v`, err)
}
defer listener.Close()
if err := os.Chmod(sock, 0666); err != nil {
logger.Fatal(`Unable to change socket permission: %v`, err)
printErrorAndExit(`Unable to change socket permission: %v`, err)
}
logger.Info(`Listening on Unix socket %q`, sock)
slog.Info("Starting server using a Unix socket", slog.String("socket", sock))
if err := server.Serve(listener); err != http.ErrServerClosed {
logger.Fatal(`Server failed to start: %v`, err)
printErrorAndExit(`Server failed to start: %v`, err)
}
}(socketFile)
}
@ -137,9 +138,12 @@ func startAutoCertTLSServer(server *http.Server, certDomain string, store *stora
go s.ListenAndServe()
go func() {
logger.Info(`Listening on %q by using auto-configured certificate for %q`, server.Addr, certDomain)
slog.Info("Starting TLS server using automatic certificate management",
slog.String("listen_address", server.Addr),
slog.String("domain", certDomain),
)
if err := server.ListenAndServeTLS("", ""); err != http.ErrServerClosed {
logger.Fatal(`Server failed to start: %v`, err)
printErrorAndExit(`Server failed to start: %v`, err)
}
}()
}
@ -147,18 +151,24 @@ func startAutoCertTLSServer(server *http.Server, certDomain string, store *stora
func startTLSServer(server *http.Server, certFile, keyFile string) {
server.TLSConfig = tlsConfig()
go func() {
logger.Info(`Listening on %q by using certificate %q and key %q`, server.Addr, certFile, keyFile)
slog.Info("Starting TLS server using a certificate",
slog.String("listen_address", server.Addr),
slog.String("cert_file", certFile),
slog.String("key_file", keyFile),
)
if err := server.ListenAndServeTLS(certFile, keyFile); err != http.ErrServerClosed {
logger.Fatal(`Server failed to start: %v`, err)
printErrorAndExit(`Server failed to start: %v`, err)
}
}()
}
func startHTTPServer(server *http.Server) {
go func() {
logger.Info(`Listening on %q without TLS`, server.Addr)
slog.Info("Starting HTTP server",
slog.String("listen_address", server.Addr),
)
if err := server.ListenAndServe(); err != http.ErrServerClosed {
logger.Fatal(`Server failed to start: %v`, err)
printErrorAndExit(`Server failed to start: %v`, err)
}
}()
}
@ -206,7 +216,11 @@ func setupHandler(store *storage.Storage, pool *worker.Pool) *mux.Router {
// Returns a 404 if the client is not authorized to access the metrics endpoint.
if route.GetName() == "metrics" && !isAllowedToAccessMetricsEndpoint(r) {
logger.Error(`[Metrics] [ClientIP=%s] Client not allowed (%s)`, request.ClientIP(r), r.RemoteAddr)
slog.Warn("Authentication failed while accessing the metrics endpoint",
slog.String("client_ip", request.ClientIP(r)),
slog.String("client_user_agent", r.UserAgent()),
slog.String("client_remote_addr", r.RemoteAddr),
)
http.NotFound(w, r)
return
}
@ -220,21 +234,37 @@ func setupHandler(store *storage.Storage, pool *worker.Pool) *mux.Router {
}
func isAllowedToAccessMetricsEndpoint(r *http.Request) bool {
clientIP := request.ClientIP(r)
if config.Opts.MetricsUsername() != "" && config.Opts.MetricsPassword() != "" {
clientIP := request.ClientIP(r)
username, password, authOK := r.BasicAuth()
if !authOK {
logger.Info("[Metrics] [ClientIP=%s] No authentication header sent", clientIP)
slog.Warn("Metrics endpoint accessed without authentication header",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("client_user_agent", r.UserAgent()),
slog.String("client_remote_addr", r.RemoteAddr),
)
return false
}
if username == "" || password == "" {
logger.Info("[Metrics] [ClientIP=%s] Empty username or password", clientIP)
slog.Warn("Metrics endpoint accessed with empty username or password",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("client_user_agent", r.UserAgent()),
slog.String("client_remote_addr", r.RemoteAddr),
)
return false
}
if username != config.Opts.MetricsUsername() || password != config.Opts.MetricsPassword() {
logger.Error("[Metrics] [ClientIP=%s] Invalid username or password", clientIP)
slog.Warn("Metrics endpoint accessed with invalid username or password",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("client_user_agent", r.UserAgent()),
slog.String("client_remote_addr", r.RemoteAddr),
)
return false
}
}
@ -242,7 +272,14 @@ func isAllowedToAccessMetricsEndpoint(r *http.Request) bool {
for _, cidr := range config.Opts.MetricsAllowedNetworks() {
_, network, err := net.ParseCIDR(cidr)
if err != nil {
logger.Fatal(`[Metrics] Unable to parse CIDR %v`, err)
slog.Error("Metrics endpoint accessed with invalid CIDR",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("client_user_agent", r.UserAgent()),
slog.String("client_remote_addr", r.RemoteAddr),
slog.String("cidr", cidr),
)
return false
}
// We use r.RemoteAddr in this case because HTTP headers like X-Forwarded-For can be easily spoofed.
@ -254,3 +291,10 @@ func isAllowedToAccessMetricsEndpoint(r *http.Request) bool {
return false
}
func printErrorAndExit(format string, a ...any) {
message := fmt.Sprintf(format, a...)
slog.Error(message)
fmt.Fprintf(os.Stderr, "%v\n", message)
os.Exit(1)
}

21
internal/http/server/middleware.go
View file

@ -5,11 +5,12 @@ package httpd // import "miniflux.app/v2/internal/http/server"
import (
"context"
"log/slog"
"net/http"
"time"
"miniflux.app/v2/internal/config"
"miniflux.app/v2/internal/http/request"
"miniflux.app/v2/internal/logger"
)
func middleware(next http.Handler) http.Handler {
@ -22,12 +23,18 @@ func middleware(next http.Handler) http.Handler {
config.Opts.HTTPS = true
}
protocol := "HTTP"
if config.Opts.HTTPS {
protocol = "HTTPS"
}
logger.Debug("[%s] %s %s %s", protocol, clientIP, r.Method, r.RequestURI)
t1 := time.Now()
defer func() {
slog.Debug("Incoming request",
slog.String("client_ip", clientIP),
slog.Group("request",
slog.String("method", r.Method),
slog.String("uri", r.RequestURI),
slog.String("protocol", r.Proto),
slog.Duration("execution_time", time.Since(t1)),
),
)
}()
if config.Opts.HTTPS && config.Opts.HasHSTS() {
w.Header().Set("Strict-Transport-Security", "max-age=31536000")