One way I've seen this going awry is when real functionality starts being built as event listeners. Data that would ideally be propagated back up the call stack instead just get consumed via published events because then the core logic doesn't have to be touched. It's like setting up an observatory with a parabolic antenna pointed at the mysterious legacy core, recording & processing its emissions to reconstruct the inner workings.
(2) Not all kinds of software can afford to depend on an event-publishing infrastructure. One obvious example is the event-publishing infrastructure itself. Less obviously, all of its transitive dependencies down to storage, networking, and operating systems.
(3) After dismissing logging and explaining a more complex event model, the author says in their own project he stripped away a lot of that infrastructure and ... reinvented logging. Similarly, they admit that AST-rewriting magic is a "footgun" and then recommends it. Why keep arguing for one thing and then doing the opposite?
(4) Tagging everything you don't like with buzzwords like "code smell" is a bit of a writing smell. It's "considered harmful" for millennials.
(5) The swipe at log4j seems to be just a misguided attempt to make the author's opinions seem more topical. The recent log4j vulnerability was not a problem with logging itself, but with a particular implementation that embedded some rather crazy functionality. That functionality could just as easily have been embedded in an event-oriented system, and I'll bet someone somewhere has already done exactly that.
I'm not sure this article does a good enough job of explaining why it's a code smell. Aside from the event bus code looking slightly better, I don't see any big advantages. One disadvantage is that if you have a big class with lots of different events, you now have to import all of your events rather than just importing the singular logger.
Typically I only resort to logging in situations where I don't want to propagate an error but I do want to log that an error happened. I also sometimes get lazy and debug using logs. I'm trying to avoid this as much as possible and instead debug by attaching to a process and using breakpoints. However this article doesn't touch on either of these scenarios.
Also, log4j's vulnerability had nothing to do with the actual concept of logging. AFAIK the vulnerability came from log4j's JNDI lookup functionality, which was not doing any kind of input sanitization which allowed attackers to perform remote code execution.
I was really looking forward to a post on logging as a code smell, mostly geared towards inexperienced developers. Pretty disappointed with the actual post.
Agreed. In a perfect world all production bugs can be reproduced on a test instance, but that's often not the case in the real world. Also, I've seen plenty of timing sensitive bugs that get covered up by the delay introduced by the attached debugger. The much feared "Heisenbug".
So who has access, if at all ? If nobody has access, how is deployment done or setup ? Can you imagine the "deployer" person ... learning or being replaced by a developer ?
This is an organisational weakness not to have figured out a way to make the people responsible for production, also responsible for reproduction and bug fixing.
I've seen companies with a full team of developers who never add new features but only reproduce and fix the errors of the other feature teams, companies with read-only access to obfuscated informations good enough to reproduce without any client reference, companies who localize enough people in each jurisdiction the production is regulated in rather than have everyone out and unable to reach it.
It's an organisational problem, fix it instead of saying it's impossible to be creative with it. And if my experience if anything to go by, regulators and auditors are either misunderstood in wayyy too conservative ways or are themselves misunderstanding in conservative ways their own rules: there always are ways to explain that it's more risky not to maintain production rather than let if rot slowly because "I can't ssh to the box".
While it's always easier to be conservative with vague rules, it's also always possible to be clear faced with absurdity and it's rare people embrace the absurdity: usually they tell you: "I'll lose my job if I don't follow the rule X put in place 20 years ago" and not "I want the production to be offline the entire day during heavy traffic because I think clients prefer when they can't use our software". So, easy: "20 years ago, X. made a mistake - let's show him", and the answer from X is almost always "Why the fuck are you even asking me, ofc exceptions are possible, fix now we do the process after". And "doing the process" is often to can the old rule, or make it change so much it loses all fear factor and start being actually useful.
Lets's say you run a company and buy a piece of software. The business you're in is regulated and deals with people's personal information.
Would you let a random coder come in an attach their laptop to your network and start digging around for a problem in their software? Especially if it's your ass on the line if any regulated data is seen by the wrong pair of eyes?
Or would you just ship them the logs from their own software and tell them to figure it out.
Didn't say that "nobody has access" - only explicitly authorised people do. In addition log data is often stored and indexed in a central location. Access to that data also requires authorization.
Just a bit of color to other replies here. Financial industries of course have audits and those audits require controls to be written. Controls can have human / organizational solutions as well as technical solutions and they'll ask for proof that these controls are followed.
Figure out how to write a control and prove it to the auditors that it's followed and adheres to both of these, then I guess you're golden. Probably easier said than done.
FFIEC audit handbook excerpts for "Segregation of Duties" [1] and "Principle of least privilege" [2]
It's easier to tell the customers to send the logs from the relevant timeframe and narrow down the problem. Maybe instruct them to up the log level a bit and see if the problem surfaces again.
Always log enough to see where the bug is just by looking at the logs. Getting permission to deploy a new version with additional logging might be a bit of a pain.
Logs are useful because they give an idea of what was going on when a particular failure happened. More context than a call stack.
> Pretty disappointed with the actual post.
I am as well. What the author describes isn't new or novel, it's been in Windows in the form of ETW since the early 90's. And Windows wasn't the first OS to get it. Had the author taken a serious System/OS class he would have known.
You can't build high performance applications without using some scheme similar to what the author describe.
It sounds like the thing you're missing is the concept of "context" not "logging". If you frame the question as what information do I need to diagnose a problem with this code if (and only if) it fails, and likewise what info when it succeeds do you end up with logging as the best solution? Probably not - events seem to be a better perspective on this.
>Had the author taken a serious System/OS class he would have known.
I'm guessing the author probably did so - this comes across as fairly ascerbic btw.
userRoles.addMember( p );
RoleAssignedEvent.publish( p, roleName );
Seems to have the exact same risk of divergence.
Depending on the language you can (and I have) used decorators/higher order functions to log the invocation of a function with its name and arguments. Zero risk of divergence there, but it was still logging not some kind of event system. The problem of divergence seems to me to be orthogonal.
You can do this in C without all the enterprisey ceremony. All you need is a way to send messages to a queue and have them dispatched to registered listeners. The "message" can be nothing more than an encoded integer or something more complex. This lets you have a decoupled interface between interacting subsystems.
That event bus exists whether you call it one or not — print is just a buffered serialized stream of events consumed by the kernel and rendered to strings.
when my code is not working how i expect it to, i print a ton of equal signs, then the value on a knew line, then a new row of equal signs. never used loggin before.
I think you are taking the comment rather out of context and just took the chance to be snarky.
The gentleman I was replying to is clearly new to the gig and he should try out a debugger, it will change his workflow immensely and likely make him a much better developer.
Yes, you still want logs (or events or traces, etc) in production to identify when edge cases or heisenbugs have occurred.
A debugger doesn't replace those but it does replace 'println` style debugging when developing new code.
> it will change his workflow immensely and likely make him a much better developer
Frankly the best developers I have met did not rely on debuggers, or logs for that matter. Using neither forces them to keep the program flow in their head and completely understand the code and system before pressing run.
For debugging production systems of course logs are useful.
In an ideal world, we wouldn't use logging to debug things after-the-fact. We would use traces, monitoring, and yes, events. But we don't always live in an ideal world, and logs are a simple and easy way to determine the sequence of events that happened after-the-fact, especially if there's something going on in a single application (which... happens to be a pretty big chunk of cases).
And at the end of the day, few things are more versatile than a big wall of text with timestamps and request ids attached. Saying that logging is a code smell is a little like saying all tech debt is bad.
I think the author is on the cusp of the right idea but misses it with the new implementation — the only meaningful change is switching fixed strings interpolated with data to fixed classes parametrized with data. It’s not nothing, but it’s basically a funny way to do structured logging. Logging systems are already event streams with the ability for consumers modify, add supplementary data, and route output with strategies, formatters, etc etc.
What I would rather see is a new keyword that generalizes the concept of logging in it’s entirety — “emit $object.”
For discrete events it would be emit ThingHappened(), for logs it would be emit Log(), and for traces it would be emit OpenSpan() and emit CloseSpan(). You could collapse whole classes of libraries into a few emit calls and a single listener.
Logging is one of many ways to debug and capture behavior in large systems. Logging is not inherently bad and isn’t an event bus just another layer or two of indirection of a logger? This post just demonstrated a logger abstraction that is still capturing and logging activities. Sort of anyway. Code smell is when your logs aren’t helpful
Debugging complex systems in production is much easier, if you can rely on certain things. Thus, simple logging to files using known configuration eliminates one variable to debug. With an event bus, there’s always the question of “did the event not happen or did some upfckery prevent the message from getting where I can see it?”.
While I do agree with the need to simplify code, moving to an event bus transfers the complexity to where we don’t necessarily want it - to system level. Now there’s one more moving thing to be deployed, monitored, scaled, networked. And, by the way, that moving thing is mission critical, as without it you are flying blind, including in terms of infosec. Is it worth it? Maybe in some scenarios. But definitely not to the level of a code smell, that should be something to be avoided universally.
Logging is a code-smell. Some logging is needed, naturally. What you want is a good tracing system, like DTrace and the function boundary and user-space static probe providers.
I remember using the SciTE editor with AutoIT a long time ago. You could toggle a key and it would "add trace lines" between every single line of code. Yeah, I'd consider that a code smell for sure if you committed that.
The real code smell here is importing a third-party library into all of your application classes.
Wrap it in a class of your own so the logger (or whatever) can be easily swapped out if you want to use a different logging system, events, or whatever.
Logging is something you do for some future purpose. If I write a string in a log message, the future purpose is usually for me to read it later.
The reasons in the post did not convince me on why my log messages should be structured. For example, why would I want to internationalize those messages?
The event bus in all these examples looks an awful lot like just a different name for a log, and adding an event bus has some minor downsides in that it requires more complex setup (with additional points of failure and points of difference between local and production deployment) and you would need to use special tooling to get the actual messages recorded somewhere and your hands on the contents of the messages when you need to debug. On the flipside the event bus messages may be useful for more than just human debugging.
It's a shame the author didn't actually look at logging as a code smell. For example, is a high density of logging statements in code an indication of places which are brittle and hard to figure out and therefore candidates for reworking? That would be an interesting topic I think.
It's a good point but I think the author sort of drove past the key insight. This is called structured logging. Having some kind of consistent schema of log messages is much better than plain strings for analysis later. It's just building a loose schema of events/log types, and picking a serialization format for said schema. JSON is popular because it remains human readable as well. I agree though, it really is very useful, not much harder than logging strings, and it's easy to evolve an existing system to gradually add structure to logs.
TL;DR: Log impure actions. If you minimize and group side effects, you don't need to log as much. Pure functions can be recomputed any time if you know their inputs.
Event buses can be useful, but it's hard to look at an event being published and know what it does and whether it's important. Whereas the importance of a logger call is usually pretty clear. Logs are rarely load-bearing, but an event can mean anything.
One big argument in favour of that approach is the oft-forgotten (or at least ignored) fact that logging is, pretty much by definition, a side effect itself.
The author is severely confused. What he's calling logs are actually debug traces. You don't want to use events for those.
> eases the transition to internationalized log messages
You don't internationalize debug traces any more than you internationalize your function names or programming language words. You barely even fix spelling mistakes in trace messages. Often, you build software without them at all: "compile them out".
One excellent reason not to use events for trace messages is that you may sometimes want every last trace message leading up to a crash to be recorded, which won't happen if they go through an event system where they sit in a queue which is no longer being serviced since everything died.
Oh, and your shiny event system could have issues, debugging which could benefit from trace messages.
> sLogger.debug( "Not marking nodes down due to local pause" );
vs
> NodeMarkingInactiveEvent.publish( localPause );
The second statement is totally not logging because it doesn't have the word "logging" in it. ;-)
That being said... conceptually, I do like the generality of publishing an event that describes internal system state, rather than logging a string on some level. OTOH the logging is supposed to be human, rather than machine-readable. But it's also gotta be a heap more work to do it this way and, maybe you'll never know if the error occurred cause the service lost network for some period of time (because it can't write to the event bus either!)
53 comments
[ 3.5 ms ] story [ 112 ms ] thread(2) Not all kinds of software can afford to depend on an event-publishing infrastructure. One obvious example is the event-publishing infrastructure itself. Less obviously, all of its transitive dependencies down to storage, networking, and operating systems.
(3) After dismissing logging and explaining a more complex event model, the author says in their own project he stripped away a lot of that infrastructure and ... reinvented logging. Similarly, they admit that AST-rewriting magic is a "footgun" and then recommends it. Why keep arguing for one thing and then doing the opposite?
(4) Tagging everything you don't like with buzzwords like "code smell" is a bit of a writing smell. It's "considered harmful" for millennials.
(5) The swipe at log4j seems to be just a misguided attempt to make the author's opinions seem more topical. The recent log4j vulnerability was not a problem with logging itself, but with a particular implementation that embedded some rather crazy functionality. That functionality could just as easily have been embedded in an event-oriented system, and I'll bet someone somewhere has already done exactly that.
Typically I only resort to logging in situations where I don't want to propagate an error but I do want to log that an error happened. I also sometimes get lazy and debug using logs. I'm trying to avoid this as much as possible and instead debug by attaching to a process and using breakpoints. However this article doesn't touch on either of these scenarios.
Also, log4j's vulnerability had nothing to do with the actual concept of logging. AFAIK the vulnerability came from log4j's JNDI lookup functionality, which was not doing any kind of input sanitization which allowed attackers to perform remote code execution.
I was really looking forward to a post on logging as a code smell, mostly geared towards inexperienced developers. Pretty disappointed with the actual post.
Not a problem but rather a fact of life.
This is an organisational weakness not to have figured out a way to make the people responsible for production, also responsible for reproduction and bug fixing.
I've seen companies with a full team of developers who never add new features but only reproduce and fix the errors of the other feature teams, companies with read-only access to obfuscated informations good enough to reproduce without any client reference, companies who localize enough people in each jurisdiction the production is regulated in rather than have everyone out and unable to reach it.
It's an organisational problem, fix it instead of saying it's impossible to be creative with it. And if my experience if anything to go by, regulators and auditors are either misunderstood in wayyy too conservative ways or are themselves misunderstanding in conservative ways their own rules: there always are ways to explain that it's more risky not to maintain production rather than let if rot slowly because "I can't ssh to the box".
While it's always easier to be conservative with vague rules, it's also always possible to be clear faced with absurdity and it's rare people embrace the absurdity: usually they tell you: "I'll lose my job if I don't follow the rule X put in place 20 years ago" and not "I want the production to be offline the entire day during heavy traffic because I think clients prefer when they can't use our software". So, easy: "20 years ago, X. made a mistake - let's show him", and the answer from X is almost always "Why the fuck are you even asking me, ofc exceptions are possible, fix now we do the process after". And "doing the process" is often to can the old rule, or make it change so much it loses all fear factor and start being actually useful.
Give up and rot, give feedback and soar :)
Would you let a random coder come in an attach their laptop to your network and start digging around for a problem in their software? Especially if it's your ass on the line if any regulated data is seen by the wrong pair of eyes?
Or would you just ship them the logs from their own software and tell them to figure it out.
No. But I would a proper Engineer. The same way I don’t go seek treatment in a mall, but rather in a legitimate medical clinic by real MDs.
Does this clarifies things?
Figure out how to write a control and prove it to the auditors that it's followed and adheres to both of these, then I guess you're golden. Probably easier said than done.
FFIEC audit handbook excerpts for "Segregation of Duties" [1] and "Principle of least privilege" [2]
[1] https://ithandbook.ffiec.gov/it-booklets/information-securit...
[2] https://ithandbook.ffiec.gov/it-booklets/information-securit...
It's easier to tell the customers to send the logs from the relevant timeframe and narrow down the problem. Maybe instruct them to up the log level a bit and see if the problem surfaces again.
Always log enough to see where the bug is just by looking at the logs. Getting permission to deploy a new version with additional logging might be a bit of a pain.
> Pretty disappointed with the actual post.
I am as well. What the author describes isn't new or novel, it's been in Windows in the form of ETW since the early 90's. And Windows wasn't the first OS to get it. Had the author taken a serious System/OS class he would have known.
You can't build high performance applications without using some scheme similar to what the author describe.
>Had the author taken a serious System/OS class he would have known.
I'm guessing the author probably did so - this comes across as fairly ascerbic btw.
Is it? What am I missing here?
(1) Some code that does a thing
(2) Another line of code that logs that the thing happened
And, like in-lined documentation, the code can diverge from the text that says what it does.
userRoles.addMember( p ); RoleAssignedEvent.publish( p, roleName );
Seems to have the exact same risk of divergence.
Depending on the language you can (and I have) used decorators/higher order functions to log the invocation of a function with its name and arguments. Zero risk of divergence there, but it was still logging not some kind of event system. The problem of divergence seems to me to be orthogonal.
(1) Some code that does a thing
(2) Another line of code that sends an event that the thing happened
Wish there was effort to establish a pattern for this in C.
Replies extremely heavy on POSIX api and threads. All the cool functionality is with sockets. There is an inproc:// but it doesn’t do much.
Lighter to just work it out using RTOS objects like queues and streams.
I go even lower though. Just
print(“XXXXXXXXXXX”)
print(“XXXXXXXXXXX”)
print(amount)
So is a sewer though, and I wouldn’t call that an event bus either.
Yes, you still want logs (or events or traces, etc) in production to identify when edge cases or heisenbugs have occurred. A debugger doesn't replace those but it does replace 'println` style debugging when developing new code.
Frankly the best developers I have met did not rely on debuggers, or logs for that matter. Using neither forces them to keep the program flow in their head and completely understand the code and system before pressing run.
For debugging production systems of course logs are useful.
And at the end of the day, few things are more versatile than a big wall of text with timestamps and request ids attached. Saying that logging is a code smell is a little like saying all tech debt is bad.
What I would rather see is a new keyword that generalizes the concept of logging in it’s entirety — “emit $object.”
For discrete events it would be emit ThingHappened(), for logs it would be emit Log(), and for traces it would be emit OpenSpan() and emit CloseSpan(). You could collapse whole classes of libraries into a few emit calls and a single listener.
While I do agree with the need to simplify code, moving to an event bus transfers the complexity to where we don’t necessarily want it - to system level. Now there’s one more moving thing to be deployed, monitored, scaled, networked. And, by the way, that moving thing is mission critical, as without it you are flying blind, including in terms of infosec. Is it worth it? Maybe in some scenarios. But definitely not to the level of a code smell, that should be something to be avoided universally.
In Java that would be BTrace.
Wrap it in a class of your own so the logger (or whatever) can be easily swapped out if you want to use a different logging system, events, or whatever.
The reasons in the post did not convince me on why my log messages should be structured. For example, why would I want to internationalize those messages?
It's a shame the author didn't actually look at logging as a code smell. For example, is a high density of logging statements in code an indication of places which are brittle and hard to figure out and therefore candidates for reworking? That would be an interesting topic I think.
TL;DR: Log impure actions. If you minimize and group side effects, you don't need to log as much. Pure functions can be recomputed any time if you know their inputs.
Event buses can be useful, but it's hard to look at an event being published and know what it does and whether it's important. Whereas the importance of a logger call is usually pretty clear. Logs are rarely load-bearing, but an event can mean anything.
> eases the transition to internationalized log messages
You don't internationalize debug traces any more than you internationalize your function names or programming language words. You barely even fix spelling mistakes in trace messages. Often, you build software without them at all: "compile them out".
One excellent reason not to use events for trace messages is that you may sometimes want every last trace message leading up to a crash to be recorded, which won't happen if they go through an event system where they sit in a queue which is no longer being serviced since everything died.
Oh, and your shiny event system could have issues, debugging which could benefit from trace messages.
vs
> NodeMarkingInactiveEvent.publish( localPause );
The second statement is totally not logging because it doesn't have the word "logging" in it. ;-)
That being said... conceptually, I do like the generality of publishing an event that describes internal system state, rather than logging a string on some level. OTOH the logging is supposed to be human, rather than machine-readable. But it's also gotta be a heap more work to do it this way and, maybe you'll never know if the error occurred cause the service lost network for some period of time (because it can't write to the event bus either!)