Hacker News Reader

Comment by david_allison | Hacker News Reader

> And similar for things like DEBUG or TRACE. Usually you reach for those log levels when you want to see extremely verbose information, but... That's not practical to enable in production environments, because the volume of logs you produce would be way too high. And if you can't use it in production, you probably shouldn't use it elsewhere! That's what your local debugger is for.

That's why you want DEBUG and TRACE. I'd rather have useful logs as well as a debugger when running locally.

View on HN

I agree. I found the argument against DEBUG and TRACE to be particularly weird, since it's very rare that you enable these log levels in production code.

While debugging and testing locally, though? They're extremely useful.

I think they're also useful in production code, although much more rarely. I've had a few times when a customer is having a strange problem that higher log levels helped to quickly resolve.

Being able to have them enable the higher log levels, reproduce the issue, reduce the log level to normal, and send you the logs can occasionally find an issue that would have taken forever to track down otherwise.

And that's not even to mention special processing. In the unices, anyway, the log daemon can take different actions depending on what level the log message was issued at. CRITICAL errors can result in automatic notification to a dev, for instance.

I've used DEBUG trace in a production system by capturing it into a circular buffer. If you hit an error you dump it, otherwise it's thrown away. It's gives you wonderful visibility when just when you need it: which is when the system fails. The difficulty is the run time cost. While capturing the raw data into a circular buffer is pretty cheap, formatting it the way the logging system needs is expensive. The workaround is to defer the formatting until you need to spit it out. Most logging systems don't let you defer formatting, so you end up having to roll you own. It's worthwhile to do that IMO.

As for the articles thesis you own need two debug levels: seems wrong to me. If you look at it from the perspective of target uses, there seem to be at least three levels. There is "I've died for this reason". That's CRITICAL. Then there is the user of your code, who is trying to debug it's interactions with other systems. That's INFO. Finally there is the person trying to debug the internals. That's DEBUG. In reality there seems to be a fourth useful level: I've got bad inputs or in a bad state, but I'm continuing anyway. Examples are API calls with bad parameters or a storage system running low of space. That's WARN.

This sounds extremely appealing as I either have to take the performance hit and nose through the entire debug log to get to where the error occurred, or have errors occur and not be able to reconstruct the events that drove them.

Any tips on rolling your own? My first whack would probably be treating it like a packed message, e.g.

<start_char> <n_packed_bytes> <time> <file> <line> <n_args> <arg1_type><arg1_raw_dump> ... <format_str>

with everything aside from the format string having agreed upon byte-counts, and probably have the file names getting dumped to a lookup chart. There's probably something more elegant, but I've never been good at straying too far eclectic.

Ferrous Systems made defmt[1] for Rust. The linked design page details the inner workings. One trick is that even the format string is packed into a lookup table. They're all stored in a lookup table in a special .elf section, and only the index into that table is logged. So it's more like <format string index> <[length], n packed bytes for first variable> <[length], n packed bytes for second variable>… etc. Some types don't need a length, if not needed it is omitted. There's no need to transmit the file, line, or number of args because that's all in the lookup table, indexed just like the format string!

E.g. a slice needs a length.

    defmt::error!("Data: {=[u8]}!", [0, 1, 2]);
    // on the wire: [1, 3, 0, 1, 2]
    //  string index ^  ^  ^^^^^^^ the slice data
    //   LEB128(length) ^

LEB128[2] is the same compressed integer encoding scheme used by DWARF & WASM.

The entire "Data: {=[u8]}!" format string is just one byte on the wire (assuming it's in the first 255 or fewer log statements, the index is also LEB128 compressed.)

[1] https://defmt.ferrous-systems.com/design

[2] https://en.wikipedia.org/wiki/LEB128

Came here to say exactly this. Seeing how an error came about is exceptional.

I often enable DEBUG on specific conditions when troubleshooting. It helps if I don't have to invent a complete logging layer because some person had the idea that only INFO should be in the code.

Plenty of times that we had to run scripts by hand on production with the log levels cranked up to determine how something failed the way it did. Can't do that if you haven't already annotated your tools with the logging statements.

The problem with doing this with logging is that the frameworks usually make it hard or impossible to selectively enable debug logging for just one customer, or just one in a million requests, especially if you want to do it dynamically (which you usually do). These patterns are far more useful than enabling debug logging for everything, because that just creates a spew and slows everything to a crawl. So you usually end up rolling your own sampling that you manage yourself.

Yep those messages are really handy even if you never enable them in production. Being able to scan through log lines can get point you to the source of an issue much faster than stepping through code can. From there you can set a breakpoint and dig deeper.

And while, yes, you can have your debugger stop where exceptions are thrown, that's often not very useful because the exception happens after the point where you want to start seeing what is going on.

A counter example: in nginx I’ve used debug_connection on more then one occasion on production servers with hundreds / thousands requests per second and it did provide useful hints.

Reply on news.ycombinator.com