questions for session base logging

[chy168]

Hi,

I'm integrating seelog with my http service. I would like to debug with a 'request id' per request/session.

My concept is, once http server receive a request, it will generate a UUID as the request id for this session.
All debug log will include this UUID for identifying till the end of request.

I've read a solution at Custom receivers - Scenario 3.2: Custom receivers with context, but I still had a concern there, please advice.

The concern is, when we instance the 'logger-per-request' log in HttpHandler per request (means it might be parallel),
should I take care of the performance and any potential issue()? I list cases for example:

• create new logger with per-request-context every time might cause too many resource?
• ReplaceLogger might be called at the middle of other session, does it cause other request use the incorrect request id? (one session might call debug() many times)
• is that possible we log information via some variable in runtime?

Thank you, seelog rock! :)

[goodsign]

Hi chy168!

I think that in most cases, the scenario 3.2 should work for you. Check the App Engine integration section for an example. There is no ReplaceLogger and each logger goes as a variable (exactly what you need), so there won't be any conflicts/incorrect ids.

However, the scenario 3.2 and the AppEngine example is written this way because logging to AppEngine required passing the appengine.Context. But, if in your case you just need to output the session id, then I recommend you to think about a far more simple and convenient solution: just create your own struct, that contains seelog.LoggerInterface field and a session id field. Then you can override the Trace/Tracef, Debug/Debugf... funcs so that each of them call inner LoggerInterface.Trace/Tracef/Debug/Debugf/... with your "[sessionid]" + original string. So that your code would look like the Seelog as receiver example snippet, but with sw.inner.Debug(sessionId + ":" + s) instead of sw.inner.Debug(s) (same for other funcs). This way you could use one logger for the whole application, it would still be seelog.LoggerInterface (so, full compatibility with standard loggers), no replacing, no creation overhead.

[goodsign]

Note: in the last method above, I meant that you would still need to create your CustomLogger structs for each request (because you need to provide them Ids), but you may construct all of them, passing the same seelog logger, that's why you don't need to recreate and you can use one logger for the whole app.

So, you create:

type SomeLogger struct {
    inner seelog.LoggerInterface
    session string
}

Then you create all the LoggerInterface funcs (so that your struct can be used exactly like seelog loggers). And you just pass the calls to inner logger with minor changes you need:

func (sw *SomeLogger) Debug(s string) {
    sw.inner.Debug(sw.session + ":" + s)

}
func (sw *SomeLogger) Trace(s string) {
    sw.inner.Info(sw.session + ":" + s)
}
...

And now you can create one logger for the whole app:

...
var appLogger seelog.LoggerInterface
...
func init() {
    log, err := seelog.LoggerFromConfigAsString(
        `<seelog>...</seelog>
        `)
        ...
        appLogger = log
}

and then you can just use it per request without any kind of recreation/replacements/etc.:

func HttpHandler(rw http.ResponseWriter, req *http.Request) {
    l := &SomeLogger{appLogger, getSessionId(req)}

    l.Debugf("Test %d", 12345)
    l.Info("Test")

    // ...
}

[chy168]

Hi @goodsign

Thanks for your very detail information and example. It works perfectly.

I have a question regard of SomeLogger. For per-request based logger, we create SomeLogger to fit my usage. To keep the logger, i need to pass logger instance to the invoked function (for keeping the request-id as same). If any possible we can setup a request based logger, just like seelog a package based logger that all function can use seelog as its logger?

Another question, may I know if we could build this kind of requirement in custom formatter?
For this case, we can register a custom formatter, and set the format like:

<format id="main" format="%RequestId %MyLevel %Msg%n"/>

Thank you!

[goodsign]

Hi @chy168!

Not sure that I understood the first question. Can you give an example?

Regarding the second question, it is not possible at the moment, so the best option for you would be the recipe above, it shouldn't have any drawbacks.

[chy168]

Hi @goodsign !

Thanks for you reply, i think the first question is solved by myself via my http server arch.

One more question about i implement the request-id based logger.
I use %Func to track log info, but i cannot get the correct call depth in my SomeLogger.
My SomeLogger result in %Func part just like:

2015/06/13 01:22:50.960 [Debug] github.com/test/seelog-testing/print.func·015 1a615b6e-3891-4c25-9407-6549fe99a0a9 LOG_MESSAGE_HERE

"print.func·015" is not the correct call depth. How can I fix this?

Thank you!

[goodsign]

Check out this section.

Pay attention to the SetAdditionalStackDepth, I feel that this is exactly what you need!

[chy168]

Hi @goodsign
Actually i've tried SetAdditionalStackDepth in my logger. :(

simply my code,

var appLogger log.LoggerInterface

type ApiLogger struct {
    inner     log.LoggerInterface
    RequestId string
}

func Boot() {
    logger, log_err := log.LoggerFromConfigAsFile("logger.xml")
    if log_err != nil {
        fmt.Printf("Logger error: %v", log_err)
        panic("Cannot initialize logger from config")
    }

    appLogger = logger
    appLogger.SetAdditionalStackDepth(1)
    log.ReplaceLogger(logger)

    defer log.Flush()
}

[goodsign]

Can you attach code of full example, where you load logger, set additional stack depth and do the print and see this: 2015/06/13 01:22:50.960 [Debug] github.com/test/seelog-testing/print.func·015 1a615b6e-3891-4c25-9407-6549fe99a0a9 LOG_MESSAGE_HERE?

(Please leave only the minimal part)

[chy168]

Hi @goodsign

I create two example in my scenario.
First one is my original case, use go-json-rest integrated with seelog for request-id logger. I put the gist here: seelog + go-json-rest

If you run the sample, we can get:

14/Jun/2015:01:58:52 +0800 0 22 "GET / HTTP/1.1" - "curl/7.37.1"
2015/06/14 01:58:52.588 [Debug] main.func·001 THIS_IS_UUID I am runnnnning!

After this case, i was trying to investigate and simply this case, narrow down to the simplest code.
I found it might be the problem regard of HandlerFunc (function type).

Here is a example not use 3rd-party library that I tried to reproduce this case. the gist

package main

import (
    "fmt"
    "io"
    "net/http"

    log "github.com/cihub/seelog"
)

var appLogger log.LoggerInterface

func main() {

    logger, log_err := log.LoggerFromConfigAsString(
        `
<seelog minlevel="trace" maxlevel="error">
    <outputs formatid="main">
        <console />
    </outputs>

    <formats>
      <format id="main" format="%Date(2006/01/02 15:04:05.000) [%Level] %Func %Msg%n"/>
    </formats>
</seelog>
`)

    if log_err != nil {
        fmt.Printf("Logger error: %v", log_err)
        panic("Cannot initialize logger from config")
    }

    appLogger = logger
    appLogger.SetAdditionalStackDepth(1)
    log.ReplaceLogger(appLogger)

    defer log.Flush()

    http.HandleFunc("/", hello)
    http.ListenAndServe(":8000", nil)

}

func hello(w http.ResponseWriter, r *http.Request) {

    f := playRequest()
    f()
    io.WriteString(w, "Hello world!")
}

type HandlerFunc func()

func playRequest() HandlerFunc {
    return func() {

        request_id := "THIS_IS_UUID"

        myLogger := &ApiLogger{appLogger, request_id}
        myLogger.Debug("I am runnnnning!")
    }
}

// Customize logger with request-id
type ApiLogger struct {
    inner     log.LoggerInterface
    RequestId string
}

func (sw *ApiLogger) Debug(s string) {
    sw.inner.Debugf(sw.RequestId + " " + s)

}
func (sw *ApiLogger) Info(s string) {
    sw.inner.Info(sw.RequestId + " " + s)
}
func (sw *ApiLogger) Error(s string) {
    sw.inner.Error(sw.RequestId + " " + s)
}

func (sw *ApiLogger) Debugf(format string, params ...interface{}) {
    sw.inner.Debugf(sw.RequestId+" "+format, params...)

}

the logger output is:

2015/06/14 02:02:51.656 [Debug] main.func·001 THIS_IS_UUID I am runnnnning!

Thanks!

[goodsign]

Well, I'm not sure that it doesn't work as designed. You log from an anonymous func, which it correctly reports. Just plain seelog.Debug without any custom loggers and additional stack level would report the same in this case. It reports the func that it is called from (checks using call stack) and in your case it is called from an anonymous func that is returned by playRequest.

If you try this instead:

package main

import (
    "fmt"
    "io"
    "net/http"

    log "github.com/cihub/seelog"
)

var appLogger log.LoggerInterface

func main() {

    logger, log_err := log.LoggerFromConfigAsString(
        `
<seelog minlevel="trace" maxlevel="error">
    <outputs formatid="main">
        <console />
    </outputs>

    <formats>
      <format id="main" format="%Date(2006/01/02 15:04:05.000) [%Level] %Func %Msg%n"/>
    </formats>
</seelog>
`)

    if log_err != nil {
        fmt.Printf("Logger error: %v", log_err)
        panic("Cannot initialize logger from config")
    }

    appLogger = logger
    appLogger.SetAdditionalStackDepth(1)
    log.ReplaceLogger(appLogger)

    defer log.Flush()

    http.HandleFunc("/", hello)
    http.ListenAndServe(":8000", nil)

}

func hello(w http.ResponseWriter, r *http.Request) {

    request_id := "THIS_IS_UUID"

    myLogger := &ApiLogger{appLogger, request_id}
    myLogger.Debug("I am runnnnning!")
    io.WriteString(w, "Hello world!")
}

// Customize logger with request-id
type ApiLogger struct {
    inner     log.LoggerInterface
    RequestId string
}

func (sw *ApiLogger) Debug(s string) {
    sw.inner.Debugf(sw.RequestId + " " + s)

}
func (sw *ApiLogger) Info(s string) {
    sw.inner.Info(sw.RequestId + " " + s)
}
func (sw *ApiLogger) Error(s string) {
    sw.inner.Error(sw.RequestId + " " + s)
}

func (sw *ApiLogger) Debugf(format string, params ...interface{}) {
    sw.inner.Debugf(sw.RequestId+" "+format, params...)

}

It prints

2015/06/13 23:48:19.202 [Debug] main.hello THIS_IS_UUID I am runnnnning!

So I guess that your current problem is not connected to the original topic of our discussion. The problem is that seelog correctly reports the function it is called from, which is an anonymous func that you create, but you probably want something else.

[goodsign]

If you are 100% sure that you are going to log from some "Middleware" func and you won't need log statements outside of them (or you use different logger for that), then you may do this: appLogger.SetAdditionalStackDepth(2). It will now skip 2 frames and you'll see what you want. But, again, you must keep in mind that it will now always skip 2 frames instead of 1. So, if you now do this:

func hello(w http.ResponseWriter, r *http.Request) {
    request_id := "THIS_IS_UUID"

    myLogger := &ApiLogger{appLogger, request_id}
    myLogger.Debug("I am runnnnning!")
    io.WriteString(w, "Hello world!")
}

then you'll see this:

2015/06/13 23:56:59.720 [Debug] net/http.HandlerFunc.ServeHTTP THIS_IS_UUID I am runnnnning!

(because now it skips 2 frames: ApiLogger.Debug and hello, so it ends up in net/http.HandlerFunc)

So, basically, you have to tell seelog (or any other log library), exactly how many stack frames it must skip to find the func name that it reports. No magic here :)

[chy168]

Hi @goodsign !
Appreciate your time and very clear advices.
seelog works charming on my code now, thank you!