sollniss / ctxkey

A library to manage context keys. Additionally implements conenience functions to log the keys with slog.
MIT License
3 stars 1 forks source link

Add labels inside and outside group. #1

Open jichu20 opened 3 months ago

jichu20 commented 3 months ago

Hello, what happens if I wanted to add labels both inside and outside a group, for example

{
  "creationDate": 1721199070868524000,
  "level": "DEBUG",

  "message": "xxxxxx",
  "properties":
    {
      "verb": "POST",
      "path":"/sss/sss/ss"
    },
    "X-B3-SpanId": "867ba653-14f8-40b6-aa56-f1707d74f449",
    "X-B3-TraceId": "28a1827e-b124-4ee3-87ed-b06ed712951f"
}

keeping in mind that both the values ​​shown in properties.verb and X-B3-SpanId are values ​​stored in the context

sollniss commented 3 months ago

I don't think it's possible to accomplish that, since when the log is actually happening (the Handle function is called) you are always inside the last opened group and slog doesn't allow attaching values outside of a group. The groups are not exposed via the API.

I've played around a bit with specifying group paths for the context values:

var alwaysLog ctxkey.Key[string]
var logInGroup ctxkey.Key[string]
var logInSubGroup ctxkey.Key[string]

func main() {
    var logHandler slog.Handler = slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
        AddSource: false,
        Level:     slog.LevelDebug,
    })

    logHandler = alwaysLog.AttachToLog("attachAlways", logHandler)
    logHandler = logInGroup.AttachToLogGroup([]string{"group"}, "attachToGroup", logHandler)
    logHandler = logInSubGroup.AttachToLogGroup([]string{"group", "subGroup"}, "attachToSubGroup", logHandler)

    slog.SetDefault(slog.New(logHandler))
    logger := slog.Default()

    ctx := context.Background()
    ctx = alwaysLog.WithValue(ctx, "ok")
    ctx = logInGroup.WithValue(ctx, "ok")
    ctx = logInSubGroup.WithValue(ctx, "ok")

    logger.InfoContext(ctx, "0 layers")
    subLogger := logger.WithGroup("group")
    subLogger.InfoContext(ctx, "1 layer")

    subSubLogger := subLogger.WithGroup("subGroup")
    subSubLogger.InfoContext(ctx, "2 layers")
}

output:

{"time":"2024-07-17T19:28:44.806435125+09:00","level":"INFO","msg":"0 layers","attachAlways":"ok"}
{"time":"2024-07-17T19:28:44.806574133+09:00","level":"INFO","msg":"1 layer","group":{"attachToGroup":"ok","attachAlways":"ok"}}
{"time":"2024-07-17T19:28:44.806580305+09:00","level":"INFO","msg":"2 layers","group":{"subGroup":{"attachToSubGroup":"ok","attachToGroup":"ok","attachAlways":"ok"}}}

Notice how attachAlways is always in the last group. Also notice how in the third log, attachToGroup is also inside subGroup, since we have no way to preemptively attach it to the log record before WithGroup is called. Again, this is a limitation of the slog API.

jichu20 commented 3 months ago

Hello, thank you very much, in the end we solved it in a more traditional way.

I have generated a handler to manage my context

func SetMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {

        ctx := r.Context()
.... ..... ..... 
        // Add values to context
        ctx = context.WithValue(ctx, logger.ContextKeyXB3TraceId, xTraceId)
        ctx = context.WithValue(ctx, logger.ContextKeyXB3SpanId, xSpanId)
        ctx = context.WithValue(ctx, logger.ContextKeyXB3ParentSpanId, xParentSpanId)

        // Añadimos el valor de las cabeceras al contexto de logger
        ctx = logger.BusinessVerbContextKey.WithValue(ctx, r.Method)

        next.ServeHTTP(w, r.WithContext(ctx))

        elapsed := time.Since(start)
        diffStr := fmt.Sprintf("Request took: %v", elapsed)
        fmt.Println(diffStr)
    })
}

On the other hand, I configure my logger in the following way ...

var TraceIdContextKey ctxkey.Key[string] = "traceId"
var SpanIdContextKey ctxkey.Key[string] = "spanId"
var ParentSpanIdContextKey ctxkey.Key[string] = "parentSpanId"
var BusinessVerbContextKey ctxkey.Key[string] = "businessVerb"
var BusinessIdContextKey ctxkey.Key[string] = "businessId"
var BusinessAccountContextKey ctxkey.Key[string] = "bussinesAccount"

// var someOtherContextKey ctxkey.Key[int]
var logger slog.Logger

func Default() slog.Logger {
    return logger
}

func Configure() {

    opts := &slog.HandlerOptions{
        AddSource: true,
        Level:     getLogLevel(),
        ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {

            // check that we are handling the msg key
            if a.Key == slog.MessageKey {
                // change the key from "msg" to "message"
                a.Key = "message"
                return a
            }

            // check that we are handling the time key
            if a.Key == slog.TimeKey {
                a.Key = "creationDate"
                t := a.Value.Time().UnixNano()

                // change the value from a time.Time to a String
                // where the string has the correct time format.
                a.Value = slog.Int64Value(t)

                return a
            }

            return a

        },
    }

    var logHandler slog.Handler = slog.NewJSONHandler(os.Stderr, opts)

    // add both context keys to the log
    logHandler = TraceIdContextKey.AttachToLog("traceId", logHandler)
    logHandler = SpanIdContextKey.AttachToLog("spanId", logHandler)
    logHandler = ParentSpanIdContextKey.AttachToLog("parentSpanId", logHandler)

    // set the logger as default
    slog.SetDefault(slog.New(logHandler).With(slog.Group("properties",
        slog.Int("pid", os.Getpid()),
        slog.String("app-name", os.Getenv("SERVICE_NAME")),
    )))
    logger = *slog.Default()

    // slog.SetDefault(logger)
}

func getLogLevel() slog.Level {
    levelStr := strings.ToLower(os.Getenv("LOG_LEVEL"))

    switch levelStr {
    case "debug":
        return slog.LevelDebug
    case "info":
        return slog.LevelInfo
    case "warn":
        return slog.LevelWarn
    case "error":
        return slog.LevelError
    default:
        return slog.LevelInfo
    }
}

func DebugContext(ctx context.Context, msg string) {
    slog.DebugContext(ctx, msg, getAttrs(ctx))
}

func getAttrs(ctx context.Context) slog.Attr {
    return slog.Group("properties",
        slog.Int("pid", os.Getpid()),
        slog.String("verb", getAttr(ctx, businessVerbContextKey)),
        slog.String("businessId", getAttr(ctx, businessIdContextKey)),
        slog.String("businessAcount", getAttr(ctx, businessAccountContextKey)))
}

I can't find the methods you indicate in your message.

This generates the following result

{
  "creationDate": 1721291124909521000,
  "level": "DEBUG",
  "message": "DDUMMY",
  "properties": {
    "pid": 59892,
    "verb": "POST",
    "bussinesId": "",
    "bussinesAcount": ""
  },
  "bussinesVerb": "POST",
  "parentSpanId": "69ecb3f4-d6a6-46f6-9b2d-69a112f086af",
  "spanId": "4a917ad5-4c6c-4220-b1c3-e2c72e6739cf",
  "traceId": "0870a667-6177-47e3-a198-87b77a69fb9e"
}

Sorry for the possible errors but I'm new to golang

sollniss commented 3 months ago

I see, yea, that's probably the cleanest way to achieve what you want. I'm assuming getAttr is something like this?

func getAttr(ctx context.Context, val ctxkey.Key[string]) string {
    v, err := val.Value(ctx)
    if err != nil {
        return ""
    }
    return v
}

You could probably even strip it down to something like this, to make it more inlinable, maybe even make it generic.

func getAttr(ctx context.Context, val ctxkey.Key[string]) (v string) {
    v, _ = val.Value(ctx)
    return
}

AttachToLogGroup is something I hacked together yesterday for your usecase, to see if I can get the value attached outside of a group. I'll share the source later for anyone interested.

jichu20 commented 3 months ago

Hi

Get Attr have the next code.

func getAttr(ctx context.Context, key ctxkey.Key[string]) string {
    if ctx == nil {
        return ""
    }

    if val, ok := ctx.Value(key).(string); ok {
        return val
    }

    return ""
}

The bad thing about this implementation is having to reimplement all the logger methods (debug, error, info, ....)