Add custom set of variables to the Unit (error) log

[CthulhuDen]

Is it possible to specify error log format? I'm using unit with php application and have troubles determining what URL handler triggerred some errors which can not be reliably caught in PHP itself (like memory limit exceeded), and logs currently do not include any details of the request.

I would like to be able to specify format for error log similarly to the access_log.format to include one or many of the variables representing the request context.

[lcrilly]

Hello!

determining what URL handler triggerred some errors

Do you mean something like this? #758

We're working on this right now, with an early-stage PR at #824
With --debug enabled, it produces diagnostic output such as:

2023/01/23 16:03:09.586 [notice] 18771#11186630 *29 http request line: "GET / HTTP/1.1"
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 h1p request body read -1 te:0
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 http route handler: "routes/tls"
2023/01/23 16:03:09.586 [diag] 18771#11186630 *29 evaluating: "routes/tls/0"
2023/01/23 16:03:09.586 [diag] 18771#11186630 *29 selected: "routes/tls/0/action"
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 http static handler
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 http static: "/var/www/html$uri", index: "index.html"

Question 1: would this meet your needs?

Question 2: why would you need custom variables in the error log when they are available in the access log?
2a: Are there variables representing the request context that aren't available to you?
2b: Would it be useful to be able to log the final routing decision in the access log?

You may also find that the [debug] logs produced when unitd is compiled with the --debug option are useful.

[CthulhuDen]

Let me start with Q.2 probably. I don't belive I can match records in error log to access log currently, at least not in access log's default format. If the new routing log provides some sort of request ID which is also in error log, than it probably solves the case at hand. Still, it would be much more convinient if we could have all the relevant info in our error log records directly, and custom error log format would would make sure everyone would have been able to add the details they need.

And surely you do not suggest that this software must be compiled in debug mode to be run on production environment, where currently there is not enough observability (cannot match error to request).

[lcrilly]

Thank you for the point about correlation between error/access logs.

So what you're asking for is to specify a set of variables that you care about, and for every error log entry to include that set of variables. Obviously this would only happen when such data was available. Is that correct?

And no, I'm not telling you what to do in your production environment. Simply sharing as much information as I can :)

[CthulhuDen]

Yes, this is it. Define what to include alongside with error message, via format string or otherwise - that is not important.

[alejandro-colomar]

@lcrilly wrote:

Do you mean something like this? #758

We're working on this right now, with an early-stage PR at #824 With --debug enabled, it produces diagnostic output such as:

2023/01/23 16:03:09.586 [notice] 18771#11186630 *29 http request line: "GET / HTTP/1.1"

I just realized that the above hasn't been updated to use [diag]. I'll fix that. Otherwise, we'd get by default 1 [notice] log line per request, which is still a lot.

2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 h1p request body read -1 te:0
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 http route handler: "routes/tls"
2023/01/23 16:03:09.586 [diag] 18771#11186630 *29 evaluating: "routes/tls/0"
2023/01/23 16:03:09.586 [diag] 18771#11186630 *29 selected: "routes/tls/0/action"
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 http static handler
2023/01/23 16:03:09.586 [debug] 18771#11186630 *29 http static: "/var/www/html$uri", index: "index.html"

Question 1: would this meet your needs?

Question 2: why would you need custom variables in the error log when they are available in the access log? 2a: Are there variables representing the request context that aren't available to you? 2b: Would it be useful to be able to log the final routing decision in the access log?

---

@CthulhuDen wrote:

Let me start with Q.2 probably. I don't belive I can match records in error log to access log currently, at least not in access log's default format.

Maybe we can add the connection ID (the 29) that we print in the error log to the access log as a variable? @lcrilly , what do you think about this? Maybe we need to also log a request ID in the error log: we could print something like *29/123 *29/124.

If the new routing log provides some sort of request ID which is also in error log, than it probably solves the case at hand. Still, it would be much more convinient if we could have all the relevant info in our error log records directly, and custom error log format would would make sure everyone would have been able to add the details they need.

Yeah, I had been thinking of why we have separate access log and error log, and if we could merge both into a single log (the benefit would be that it would be easier to correlate them). I'll float this idea around for some experiments. Or maybe have the option to use the same file for both (maybe we can already do this by specifying they're the same file? I don't know), or different ones, depending on what you want.

And surely you do not suggest that this software must be compiled in debug mode to be run on production environment, where currently there is not enough observability (cannot match error to request).

The idea that we're implementing is that the log level of the error log will be configurable in the control API. You'll be able to change the log level that you want (except for debug, which isn't compiled on non-debug builds), so you'll be able to enable the [diag] messages that you see above at run time.

[okpoxa]

I support it, there is really little data in the log for debugging.