You are doing logging in .NET wrong. Let’s fix it. - Nick Chapsas - NDC Oslo 2023
2023 ж. 28 Мау.
88 634 Рет қаралды
Logging is a vital part of every application that runs in production. It is in place to tell a story about the lifecycle of its runtime and make it easy for developers to debug a system and identify what failed and how when things go wrong. It is, however, extremely easy to get it wrong, and the problems caused can stay hidden for years. In this session, I will talk you through all the possible issues that logging can cause and show you how you can fix every single one of them.
More of Nick Chapsas here:
@nickchapsas
Check out our new channel:
NDC Clips:
@ndcclips
Check out more of our featured speakers and talks at
ndcconferences.com/
ndcoslo.com/
To those complaining about the drinking: I had a throat inflammation and I had to keep drinking water so I could talk. Do you think I had 100 sardines and then decided to give a talk?
Hey man! Great talk. Don't worry about internet comments. People who strive for knowledge don't get distracted by such minor things. Kudos.👍
I don't know why people are so bothered by it 😂 Thank you for the talk Nick, congrats on the 200k too!
Thanks, Nick, for making this video possible. ❤
Dear Nick, next time you might want to tell the audience in advance that I'm sorry, I have a sore throat and I have to sip a lot of water to speak, and not because I'm a rude guy. That politely takes care of the rest. Because you don't have to assume that everyone is aware of everything. Because then this presentation would be pointless if we assume everyone knows everything. Anyway, the presentation itself was good and funny.👍
I don't know why anyone is bothered by it. When talking for a long period of time, it's totally normal to require a drink. Throat inflammation or not. Thanks for the session. Very interesting.
@nickchapsas, great talk, but want to clarify one point for you from 31:00 : "None" has to be at the end of the enumeration because it isn't actually used to log messages. It's used as a value for a provider's minimum level to effectively disable it. Having it at the end optimizes the IsEnabled check so that there is only one single comparison to make to determine both if the provider is enabled and if the message should be logged. That only works if None is higher than the highest value used by actual messages. It was absolutely done on purpose and not because "they forgot" and had to tack it on at the end.
Yep this occurred to me as well. It could be done using the null approach, but then it's ambiguous as to meaning log everything out log nothing.
Nick, which I value a lot, misses a few important things. 1. When you have structured logs, you can filter for you preferred level >= warning 2. to fix complex bugs, you usually need all log levels, not only the warning „something went wrong“. And to raise the log level afterwards is often to late, because the problem already happenp but you have too less info to fix it, because you only logged >= warning. 3. structured logs can be condensed, for example: older than one day: delete everything below warning With this you get the best of both worlds.
So just to answer your points because some of them were actually covered. 1. I'm assuming you're referring to the filtering that you can do after the fact once everything has been pushed to the provider. That's where the problem is. You are wasting resourcing collecting and writing those logs that, if you instrument you application correctly, will never need. 2. Incorrect. You need proper metrics and tracing in place but not all log levels. 3. Any type of logging can be truncated
@@nickchapsas Firstly, I didn't even notice the drinking ... KZhead commentors can be such jerks! 🙂 Regarding the reply to #2 - "incorrect". Have you ever maintained a production system? Yes, there is a limit to how much you should log but @fr3ddyfr3sh wins the argument here. Your thinking also violates key long-standing, unrefuted dev principles: "People time is much more important than machine time" and "I/O is where perf problems are". Also consider - "use boring technology" and "use as few dependencies as possible (e.g., don't use a logging library)". And even though you mention "early optimization is the root of all evil", please research how your counterargument about ignoring it is widely refuted. It's true that more logging costs more money. But once it takes a dev 30 extra minutes to debug a problem, you've paid for a LOT of compute and storage. And you still have the tech debt of that logging library. Also, from fr3ddyfr3sh point #1, "instrument the application correctly". Yes since you and I have had 10+ years of experience, spending a lot of extra effort might make this a correct statement, if every section of code were written by a senior dev. I don't know about you, but we couldn't get even 50% of our devs at that level IF we COULD afford to hire them (which we can't). And now those junior devs who can barely grasp the business requirements, have to learn my favorite logging library (to which the app is now strongly coupled), and they have to learn source generators. OR there's magic in the config to hide this, and when it breaks in 5 years, who fixes it? Sorry to be such a jerk about this, but if you are going to say, "you are doing it wrong", don't say wrong things!! I wasn't going to mention it, but, log4j anybody? See what 12-factor apps has to say about logging if you are looking for a highly credentialed 'KISS' opinion which avoids all these problems. Bottom line: *it's not worth the cost of taking a dependency on any external logging library. Use text logs. Log enough without guilt, and push it to prod.* Tag things you want to query in splunk (etc). e.g., $" PaymentID:{pid}"
From an ITIL perspective, Nick is right. Let me explain 🙂 An incident is something that happens once and when it is solved we forget about it. When an incident occurs more than once, it can become a problem, and at that moment we can change the log level to debug or info if needed. There is no point of wasting resources for an eventual incident that will only happen once. If it comes back, you can turn the log for specific parts of your services where it is needed. If you chase every incident you have in production, you will spend most of your time doing that... And don't forget that business also wants to have new features. In french, we have a say that goes something like "best is the ennemu of good".
@@albud6687 This is terrible advice. The 30 minutes you claim to lose debugging a problem because you don't have enough logs (which isn't accurate) is just going to be lost trying to query text logs that are so verbose you can't get to the root of the problem quickly.
@@DestDroid Everything you mentioned is completely against what I've seen and experienced for many years. It's 30 minutes many times. And who would spend even 10 minutes searching a log? And you never manually look at a log, even a text log use notepad++, find all in doc, and copy and search those results and you don't even need structured logs (which at least won't leave you missing valuable data). And there are many better ways. It's not the 90s anymore. Storage is cheap. You can buy gigs for that 30 minutes.
Nick, I like the way you describe and implement ideas. I started to watch your videos from 2019 and you really gave me so much information. You are one of the creators I'm really interested in any video you publish... thanks alot...
Thanks, Nick, for making this video possible. ❤
Logging Rules by Nixk 1. Message is actually the message template and should be treated as such, dont use string interpolation or concetatnation or formatting 2. Use structured logging and use good parameter names for better search and debugging experience 3. Prevent boxing for inactive log levels, avoid passing objects use value types where possible 4. Consider using source generated loggers ( Maybe? you probably won't need it ) 5. Use log levels appropriately, do not over log, logs are just one tool, use other tools to monitor your systems health. 6. Use Warning as the default log level 7. Log what is necessary to tell a good story, Logs dont need to be verbose, they can be short and consice and yet provide enough information to debug and understand system behavior
Excellent talk!
Hey! Nice talk, thank you very much :)
It's an interesting, fun, and useful presentation. Well done Nick.
Thanks Nick Listening you is also amazing along with learning. Enjoyed your session and learnt meaningful
Hi Nick, At the 35:55 mark in your slide at the bottom should read logger.LogPaymentFailed(id, status) you have Error in the method name not matching the slide. 👍
Great talk! I think staying hydrated was a major part of why it was great. 🙃
Nick, thanks for the talk. Would be cool to see a follow-up video on having proper metrics and tracing to troubleshoot complex situations. For now my team has to rely on info logs to tell the full story.
Removing performance from the equation, I generally only log what will actually be looked at (which in some cases can be nothing), and use structured logging so you can investigate it easier later. Doing anything else is a waste. This doesn't mean that some scenarios won't require full logging, but only if it's going to be looked at and is useful later on (i.e full traceability on financial apps may be warranted).
42:07 if we default to warning ⚠️, when that happens, we will probably need info ℹ️ or lower to understand what is wrong 🤔 Great content, thanks!!
Amazing talk
Thanks to what you called clickbait got my attention while learning .Net concepts on KZhead a few months back. From that date till today, I've never stopped learning and have taught me what I couldn't learn in 5 years of my career. Keep those videos coming. You're doing god's work! Thanks a lot man!
Interesting Video. I did not understand very much. Being just a Newbie writing some (Windows) PowerShell Scripts doing very basic file operations. I recently discovered "log4net" and do stuff like $Log.Information(("Delete File {0}" -f $PSItem.FullName)) or $Log.Error((Out-String -InputObject $Error[0])) but maybe I will one day come back to this video if I understand more. :P
Yup, that's how logs were written for years. Structured logging is the evolution of that, especially so that you can have logs running for high volume enterprise applications. Once request are more than a handful an hour, you want to work efficiently. Trying to parse strings to get answers is how it was done. Structured logging can allow you to have a console or file provider and generate the same thing as what you see now, but structured logging gives you all the hidden details when you are trying to investigate. On top of that, since you aren't necessarily resolving the objects to a string, the work of deconstructing can be pushed out to the provider, which can queue batches of messages to process or if you are saving all that information to a database or other store, you can do that on a different system altogether. 🌳🫥 It is a performance benefit, but performance isn't the reason to do it.
Good luck on your journey!
Such a humble title
Good talk Nick! 1 question about log params. To ensure that the properties are named the same across the whole source, could precompile switches be used just for the property tags to avoid memory issues with the message templates?
Rule 7 is bollocks, oftentimes the only way to find out what went wrong is to trace earlier info log messages.
...and did you ever had a client that wants "translated" log messages based on the user session locale? Loooool!
Lmao insane
@@desertfish74 The problem is that... somebody implemented it... ROFLMAO...
@@desertfish74 The problem is that... somebody implemented it... ROFLMAO...
@@stefanotorelli3688not that difficult to implement and could be more efficient than "standard" logging - log message id and params, could be in binary form, and then make a tool to translate on demand when reading
I just happened to mouse over an ILogger.LogTrace in my code and Visual Studio prompted me to see "GitHub Examples and Documentation" over 9 out 10 examples it showed were wrong, from string interpolation in the template, to wrapping the LogTrace with their own custom LogTrace method that did nothing but call ILogger.LogTrace.
There's a guy at work who adds the most useless logs ever known to man. They provide enough information to know the logging was executed. No more, no less.
bro is logging the logs :D
You keep saying that it's not a performance talk, but so much of what you talk about is ONLY important when performance is in question. Boxing, for example, has absolutely nothing to do with how logs are collected, stored, or queried. It's ONLY a concern if I'm trying to optimize memory usage in my application. This feels way more like a talk that should have been titled "Your logging is too slow (sometimes)".
The "it's not a performance talk" is obviously a joke. It is both a logging and performance talk, but the fact that you get free performance by doing this right, doesn't mean that the talk is not a logging talk. It's both
@@nickchapsas I don't know, man. You didn't really sell that as a joke. Also, saying "when you do it right" implies that doing it any other way is objectively wrong, and when you're measuring on orthogonal axes (logging effective and useful information is completely independent of the way those logs are pushed out the door), that becomes much less cut and dry. If doing what you say is the "right" thing with regards to (for example) boxing allocations results in code that is harder to read or maintain (because now it blends both logging and implementation-specific information about the platform), I would argue that you've actually made things worse, especially if the logging isn't in a hot path. Long story short, this reads like a talk about logging performance in most places, and I would be genuinely shocked if logging was a critical performance concern in the vast majority of cases.
@@doom-child Oh it is. We went from using the exact same same hardware to run 8 containers per service to run 11 just by fixing logging due to the memory management. It largely depends on your scale and throughput but it can have a very notisable impact
@@nickchapsas I think that also probably has a lot to do with what you log and how often as well.
At least in Java, there is young generation garbage collection. It works like a disposable table cloth. You pick just the valuable items off the table and then clear the whole table right into the dustbin. I am sure the same would apply to C# as well. Only long-living matured objects need a Old Generation GC which is problematic. In fact, for young generation, the more the garbage the better because the system can copy fewer elements to YG2 and drop YG1. "Create and Dispose" in GC languages is faster than malloc languages.
It's the same in C#, in fact that's where Java got the concept from since the JVM didn't have it originally. It is cheap, but it doesn't mean that it's free and with strings being able to be really long, it can be very problematic
@@nickchapsas Cool.. I didn't know that history! For the garbage, the CEO of Azul has a talk (available on KZhead) saying garbage faster is better for Young Generation. Modern tooling, modern methods like Streams all throw garbage like nobody's business. And, its the new normal. I would agree on one thing - if it is a monolith with 16GB VM memory, it may be bad because YG itself could be in GBs. But, especially for Microservices, we don't even take instant garbage into account any more. But, even in case of 16GB VM with 1GB YG, the more the garbage, the lesser you have to copy from YG1 to YG2 before you dispose YG1. Quick turnover of garbage makes the stop-the-world GC operations shorter and done often. I prefer a 1 second pause once in 30 seconds rather than a 30 second pause once in 10 minutes. The long pause can cause some clients to timeout etc.
"I like to stab myself in the foot once per day rather than use a shotgun at the end of the week. Ammo is much cheaper that way!"
KZhead seems to have some voice recognition. When Nick says "Take out your phones and subscribe" the actual Subscribe button on YT started to glow...
Lol 43:45 🤣
Title for the next presentation (found this on reddit): "The goddamn mouth noises on TED and TEDx events!!!!"
all that just to learn I'm actually doing it right.... o_O
tfw you inherit a codebase that home-rolled its logging system and it violates all 8 rules.
tldr; just use serilog
Nick always has 6 and 9 in his videos wtf
meee meeeeh
Lost me at 25:26
He shows the structures logs - there are a few default values but one can see the PaymentId and PaymentStatus -> so you can actually filter your logs on these criteria
@@tofu1687 half the presentation is about how to prevent trashing the memory with strings you don't want logged. And at that point we see not just logs, but even more data. So you actually don't care about trashing memory, because you've just 10x-ed your memory usage. Not that it's not useful, it is, but why don't we focus on just logging?
@@FlorinBalanescu well he explains how to avoid the majority of heap allocation Anyway the additional data one sees in AppInsight are present whatever log you insert, there are not a consequence of structure logging
I really dislike sarcasm in presentations because it is misleading. This talk is about performance, you're not doing anything wrong. It's more about how to log efficiently.
There is no “right way” or “wrong way”
Nick, too much clownism
Ой подпишитесь это бесплатно, да никому это не интересно!
The lecture is interesting but please refrain from drinking or eating, as it may bother some people.
Everything bothers people these days. Why should I stop drinking water because of others? What if he has a medical condition that requires him to drink that often?
Yeah thanks for the tip, I’ll just die instead. I had a throat inflammation and I had to drink so I can speak.
I have misophonia and even I think this is such an entitled comment. Have you ever tried talking for a long period in a high stress situation? If anything, conference organizers should enable speakers to mute themselves temporarily, but even that's a nice to have.
Yea the water bottle drinking sound was super annoying. Otherwise always love his videos.
Jerks all over the comment section being bothered by nick drinking
Meh. I prefer when you make videos…