Am I using the context correctly to keep track of the connection?

Getting Help
1

For each http request that my server receives I create a context by adding as value the pointer of a struct:

type BaseKey string
type Tracker struct{ 
	Log []string
}
[...]
ctx := context.WithValue(r.Context(), BaseKey("someUniqueKey"), *Tracker{})
r = r.WithContext(ctx)

// (Actually I use http.Server.BaseContext but
// let's put it like this for simplicity's sake)

Then every time I run a function it reads the context and gets the Tracker struct then writes in it the action to execute inside the Tracker.Log slice, that is, in the whole tree of calls needed to fulfill the request a useful string is added for debugging, when there is an error the whole Tracker.Log slice is joined and concatenated with the error and saved locally in the server log.

This sounds great but I was thinking, doesn’t this consume a lot of memory per request? Suppose I have 1000 requests and they all work and if so the Tracker.Log slice would be totally ignored as it is only needed when there is an error, then this translates into useless memory consumption.

Should I be concerned about the amount of memory to be used in the Tracker.Log slice? What other alternative do I have to achieve this?

An option that occurred to me (but honestly I see complicated to implement it), is that the Tracker.Log slice should only be written when there is an error, that is to say we would go from bottom to top and when we arrive to the starting point we would register the error.

If I did not explain well imagine this tree:

-origin
	-somefunction
		-anotherfunction
		-childfunction

If childfunction fails it will log the error in the Tracker.Log slice, then anotherfunction will know that there was an error so it will log in the slice what it was trying to do, and again it will return an error to somefunction and it will repeat the process, and so on until we get to origin where we finally close the connection and log the error in the server, this way the slice would only be filled when there is an error.

Which of the two methods is more common?, in fact is even valid the first option how I am originally doing it?, do you think that the memory consumption of the first option is not very serious?

2

Why aren’t you thinking about throwing misinformation up? Instead, error logs are recorded in context? If you’re just worried about the call stack, then you should query the call chain and put it in the error. Keeping logs in memory is obviously not a good solution, and the logs are generated and consumed rather than piled up.
Like some RPC frameworks, in the event of a panic, it recovers at the outermost layer and prints the call stack for debugging.
Either way, if you’re just thinking about logging, even if you write a log file for each request in a tmp file, it’s much better than putting it in memory.

3

Hi @Willy,

An empty Tracker value consumes 24 bytes of memory.

Every goroutine starts with a stack size of 2KB.

So, compared to the unavoidable memory cost of starting a goroutine, those 24 bytes are negligible. Even more so if your request handler does some real work that surely consumes quite some memory on the way.

Tip: If your’re on Linux and curious about actual memory usage, use top -p <PID> to monitor a running process, or /usr/bin/time -v <command> to get some stats (including memory stats, despite the name “time”) from a command that eventually exits.

For more detailed analysis, you might want to use Go’s diagnostic capabilities.

4

No, I think there’s actually going to be a lot of overhead, string slicing and storing a bunch of logs, which is predictably a big memory overhead, and this pin is not a service business feature.
I think it would be a little better to transfer the memory pressure to disk. For example, when you print a log, you can carry the UUID of the request and filter it when you query the log.

5

Sure, if you start filling the slice, there will be as much storage used as the log message needs. But @Willy’s question was about passing an empty Tracker struct that would only receive log input in rare cases:

So those 1,000 working requests allocate 2048 bytes of initial stack without the Tracker struct, and 2072 bytes with an empty Tracker struct. Not much of a difference.

I am totally with you that there might be better ways of logging than filling a slice. I have answered the question from a purely technical viewpoint, omitting any design considerations.

6

If you categorize by log level, this trace type of log is very low-level, which means that it becomes a log trash can. In fact, most developers either don’t write logs or treat them like trash, add a debug log themselves, and forget about it after a while. Project managers also often require that advanced logs don’t generate too much spam. (Worse project, maybe digging through your own debug logs in the trash)
For this reason, I think it’s a mistake to put this type of log in memory.

7

No, no, passing an empty struct doesn’t worry me, I’m worried about filling the slice of the struct.

8

But logging to disk is slow because there would be a lot of goroutines trying to write to the log file. What do you think about the second option? To log from the bottom to the top? Also note that I only want to record the track of failed requests, not everything.

9

This sounds like a chain of panic and recover triggers. This implementation is very cumbersome. Let’s imagine:
There are 5 tasks a, b, c, d, and e. When an error occurs when executing e, the developer needs to write the first 4 records, which means that each task must insert a breakpoint. A simple implementation is like this :

var err error
err=aFunc()
defer func() {
	if err!=nil{
        // todo log...
    }
}()

Defer will generate a certain amount of overhead, although it is very small, but this way of writing may lead to a large number of defers. Obviously I don’t want to see such code. For complex businesses, this will only make the reader worse. (Maybe there are other better implementations)
There is another important premise. This approach will cause the caller not to like such crazy writing. If you are providing a framework to developers, then the developers will have to use this tedious step at every step. This is obviously It does not conform to the simple development concept. (I think the caller is more happy that the framework handles this for the caller)

Let’s go back and think, why do we need to record tracking error logs? Do users care? No, only developers care. Compared to the above approach, they prefer this:

var err error
err=aFunc()
if err!=nil{
    // todo log...
}

This is very simple, like some logging frameworks, which allow you to pass some context and then output it in a unified format to facilitate log storage or filtering and querying.

However, if you want to implement task behavior records (note that I am talking about task behavior records rather than tracking logs), then encapsulating the implementation through defer and spending memory is within the scope of the business, which is acceptable. But if it is for recording and debugging, the gain outweighs the loss.

It depends on whether you classify this function as business or debugging. If it is business, then everything is reasonable; but if it is debugging, you should give priority to ensuring the performance of the business.

1 Like
10

Why don’t you wanna try a logging middleware? Then you can simply wrap errors on your tree until it gets to the middleware, where you can unwrap them and process accordingly or simply log them. In this case even atomic or lock will suffice to write them to a file.

11

I just saw that the runtime package can tell me the queue of calls that were made before the error occurred, I can write this queue along with the error in the log.

I think this is a good approach, what do you think?

12

I’m interested, can you please show me an example with code? This is the first time I’ve read what you mention.

13

Something like this.

func logger(fn http.HandlerFunc) http.HandlerFunc {
    return func(w http.ResponseWriter, r *http.Request) {
        if err := somefunc(); err != nil {
            // lock here and log
        }
    }
}

func somefunc() error {
    if err := anotherfunc(); err != nil {
        return fmt.Errorf(“another function failed doing something: %w”, err)
    }

    return nil
}

func anotherfunc() error {
    if err := childfunc(); err != nil {
        return fmt.Errorf(“childfunc failed doing something: %w”, err)
    }

    return nil
}

func childfunc() error {
    return errors.New(“oh, I failed”)
}

In this approach you can add custom errors as well. Also if you need to collect several errors inside somefunc or anotherfunc before return, you can collect them with errors.Join(…err). In this case you can check them in logger with unwrap and process errors accordingly. E.g., a switch of errors.Is / errors.As. Or simply log them all into the file. Since this also can support custom errors, you can use a struct to hold some more useful info about errors, something like:

type myError struct {
    funcName string
    err error // Can be errs []err
    trace string
    // Any other field you want…
}

func (e *myError) Error() string {
    return fmt.Sprintf(“function %q failed with: %s\nTrace: %s”, e.funcName, e.err, e.trace)
}

func (e *myError) Unwrap() error { return e.err } 
// Or if you collect errors:
// func (e *myError) Unwrap() []error { return e.errs }

Imho with this approach you can handle custom errors more efficiently. Add as many things as you need and at the same time create simple errors.New within your package, so those who is gonna use it, can handle them on their end.

14

In fact, there are already logging libraries that do this. It seems that you have never known how to obtain the previous call stack before. There are not many problems with this solution, because obtaining the call stack is a common operation. (I also have experience using this type of log library. Its advantage is that you can easily see which file the log is generated on.)

As the previous person said, the log middleware he mentioned seems to let you pass the error information. This is a very common solution. However, this does not conflict with you obtaining the call stack, such as encapsulating it into error is thrown.

15

Which libraries do you use?

16

That’s my private library at work, and it’s implemented on top of zap de-encapsulation (which doesn’t matter). I don’t know if there’s a public implementation, but this logging repository with a call stack is very easy to implement and don’t worry too much about going astray.