Stop using String Interpolation when Logging in .NET
Check out my courses: dometrain.com
Become a Patreon and get source code access: / nickchapsas
Hello everybody I'm Nick and in this video I will explain why you should not be using string interpolated when logging in .NET. This applies to both the build in Microsoft.Extensions.Logging framework and also on the very popular Serilog one. Strucutred logging is extremely valuable and in this video we will see how string interpolated can remove that benefit.
Part of this video is sponsored by AWS
Timestamps
Intro - 0:00
The problem - 0:40
Visualizing logs - 7:55
A potential future solution - 13:11
Related videos
You are doing .NET logging wrong. Let's fix it - • You are doing .NET log...
High-performance logging in .NET, the proper way - • High-performance loggi...
How this NEW type changed the logging game in C# 10 - • How this NEW type chan...
How C# 10 “fixed” string interpolation - • How C# 10 “fixed” stri...
Don't forget to comment, like and subscribe :)
Social Media:
Follow me on GitHub: bit.ly/ChapsasGitHub
Follow me on Twitter: bit.ly/ChapsasTwitter
Connect on LinkedIn: bit.ly/ChapsasLinkedIn
Keep coding merch: keepcoding.shop
#csharp #dotnet #logging
I have watched all of your videos on logging and I appreciate them a lot. But one thing I have not seen (and I've done some searching on this) is a good philosophy on WHAT to log and WHEN. Do i log every function/method invocation? What should I log as INFO as opposed to DEBUG? How do I word my log message templates? Is there a resource I can look at to get guidance on this?
That's a great idea for a dedicated video. Will put that in the backlog!
Method Invocations typically get logged as "TRACE" level, as there will be many invocations throughout the application. DEBUG level is typically reserved to "useful but often too much" information (e.g. validation result before other calls, which SFTP server is a call connecting to, ..) INFO level is reserved for logs that don't happen too often and are really helpful (e.g. Whats my environment, what configuration was loaded, where's my application listenening for incoming data? What queues did my application subscribe at startup, IHostedService start/stop logs with meaningful additional data) WARNING is reserved for "oopsies" that can be worked around, just like a try catch where the catch doesn't rethrow, but gracefully handles an error, or when an "optional" file that is expected to be there is missing. ERROR is "try-catch failed, log-add info-rethrow" FATAL is "OHMYGAWD" Application should shutdown immediately and stop working. E.g. Environment.Exit(1)
And also what should be the structure to be log so is easier to query and find things
There's definitely a sweet spot between logging everything and capturing/sampling telemetry. Personally I add a lot more logging to areas of code that have some criticality (such as taking or refunding payments), and use sampling telemetry for the rest.
@@nickchapsas i will be looking forward to that
Woah 100k!! Congrats 🍾🎊 keep up the amazing work!
Good job Nick. We are doing this at my current job, and now I know why.
Excellent demonstration of industry best practices and congrats on 100K subs. Keep coding!
Thanks! great video (and great channel), easy to understand. I never knew this and have now gone and changed all my logs in my current project. App insights now looks great!
The transcript of your intro is always good for an extra smile. This time it is: "Hello everybody I'm Nikki". But I also had: "Hello everybody I'm naked".
Congrats for 100k subscriber . Another great video.
Great video Nick, Thanks. That's what I always recommend to my team members or anyone who is dealing with logs. BTW when it comes to logs, I prefer Azure it is a lot neater that AWS.
Really good video on this topic! Finally a good explanation :D
How did I never heard of this before? Awesome video!
Thanks! One of my pet peeves in pull requests.
Thank you! Clear and concise and love your presenting personality :)
This is great to know! Thank you!
Thanks Nick! Really helpful.
Thanks for sharing. Great video 👍
Really good video. The future solution is something I'd probably not use. I think it is neat, but besides the drawbacks you already mention, there is a drawback of changing the expected outcome. What you see is not what you get. It's just a personal preference. Thanks for the videos.
I honestly never thought about this.
Hi Nick. Thanks for the awesome videos! Could you maybe make a video about best practices on where to log, and where not to log. For example, if you can only get ILogger via DI, should only those classes use it, or could it be passed in as a parameter to classes that do not use DI? And is it okay to use the Log.Logger static variable in Serilog, and when is it not?
Great job! Was pretty interesting to see how you integrated it with amazon. (A comparison against azure would be interesting)
I really love these videos I have learned so much I really appreciate the videos :)
Hi Nick. Cheers for all the great video content. Normally I hate learning from videos, but I really appreciate both your chosen topics and the passion you project while you skillfully demonstrate your points. On this particular topic, I'm wondering if you are familiar with Drizin's InterpolatedLogging and whether you have any opinions towards or against using it?
One edge case I still don´t have a good alternative to is when you want a specific property in a logging statement, but you don´t want it as part of the message template. Now, this would normally be solved by wrapping the LogContext with an Enricher or simply pushing a property onto the LogContext in a specific scope. But sometimes it feels like a lot of code pollution to add an entire enricher and/or a using-statement around a logging block. Alternatively you can still simply add the property in the logging statement, but Rider will of course remind you that you aren't using the property in the message-template which leaves the code vulnerable to being changed if you happen to run an auto-clean operation.
This is awesome! Thanks Nick. My work has been using string interpolation for logging for... probably a decade, I'm not sure, I haven't been here that long, but... There's a lot of code that uses string interpolation for logging and I think it would be difficult to go back and fix it all.. I'll have to bring this idea up if we ever move toward something like AWS Cloud Watch.
Interesting comment that raises a few points. 1/ changing any code requires re testing and may lead to production bugs, both of which can be very expensive (I think this is what you referred to as 'difficult', yes it's difficult, but in terms of project management it's expensive and usually that's the most important factor). 2/ AWS isn't the only system you may move to, in fact the system you're currently using, which you didn't specify, might already benefit from the proposed approach. 3/ a minor point, and I recognise you didn't call this out as an issue, but often code that has stood the test of time for a decade was written in a bit of a hurry, and a second point, it's possible that current logging paradigms weren't available then. Coding is hard, change is hard, and this often leads to technical debt. An optimistic point 4/ good luck everybody :)
@@neekfenwick the current plan is to take our .net framework code, convert it to .net core, then host it on AWS. I think we’re about 2 years into our .net core transformation, but my assumption is that we will start look at aws integrations soon (other than just hosting our APIs anyway). I know that aws isn’t our only option, but it was the option chosen by our leadership a few years back. Personally, I’m much more comfortable with Azure and would have preferred that 😂
Wow this is cool. Thanks Nich.
man im guilty of using string interpolation everywhere i can lol... i need to change.. thanks for quality content keep coding ;)
This is an excellent video!
This makes a lot of sense. I was not expecting that. I clicked on the video expecting to be annoyed by another unnecessary programing rule.
Congrats on the 100K!
Thank you!
This is crazy. Thanks
Excellent video!
Fantastic!
Appreciate you keeping us up to date. You mentioned during the video that your computer was already authenticated against AWS, can you elaborate more on this? Not specifically to AWS but the concept in general
Nothing special here, AWS just has a method to provide authentication using for example a credential file or environment variable: docs.aws.amazon.com/cli/latest/userguide/cli-configure-files.html . If you don't specify any credentials otherwise, it will lookup the credentials from the file or env, if present.
@@PampersRockaer I see - I thought he was talking about a generic/centralized way to authenticate your computer against cloud services. (This is may be an interesting problem to solve 😊)
Hi Nick and thanks for the great videos. What is the cost of having many sinks for logs in terms of performance? For ex: File,Elastic and CloudWatch
That is really cool
I generally don’t write my programs to need bulk text logs as a necessary debug tool in a prod environment. I always choose to log ONLY the most necessary data. In my scenario, I don’t think this adds up. However for debug purposes, or for non production code, sure this seems useful.
Congrats on 100k
Hello Nick Chapsas what colors/themes are u using in rider?
I prefer to still use the Microsoft ILogger abstraction, but use the serilog provider, so adding the serilog ILogger to DI isn't required.
One other benefit is that if you have translations, templates can be translated because the placeholder stays the same, if you have strings that change because the values are part of them, it actually prevents you from translating them.
When would you translate log lines?
how amazing are you thanks man
I’m pretty new to C# and modern dev ops, I’ve written some azure functions on dotnet 6 to support actions my team needs done on the cloud, this is extremely insightful, going to refactor
I've been explaining not to do this as that breaks structured logging and a lot of devs don't care. Problem is simply most devs never actually need to diagnose production issues with logs.
I've always stuck with concatenation.
This is a good point, even without the performance reason. I'm curious if there are Java or Python loggers doing this?
Great video! I have one suggestion for a video/course. Do you plan something about caching data in WebAPI? What to cache, when to cache, when to invalidate cache? Or maybe you have stumbled across some useful resources about that?
Awesome! I would like to add additional columns, such as 'Test1' and 'Test2,' to a SQL Server database. I also aim to insert data into these columns using a Logger. Could you please suggest a way for me to achieve this?
here we go
it doesn't matter what you log, just worry about when you render the content. Render it in !!!!
Structure logging is life (: @Nick can you please do a video(s) on how to test in term of efficiency and execution time a flow of methods, finding code hot spots and address what could cause them. Not like a load tests just a single flow and what are best practices for calculate run time and memory allocation .. Keep Coding!
Can do, yeah. I just have to find the perfect usecase to demo it on.
I noticed that modern structure logging systems allow it to be used as a lightweight telemetry. I know guys that use ELK instead prometheus for monitoring and alerting their web services.
I have a working StringInterpolationHandler. I used Microsoft.Extensions.Loggin without Serilog. The LoggerProvider is an empty DummyLogger that does only two things: - Call the formatter - Iterate over the args The state is a custom state that should work with Serilog and other frameworks and it supports alignment and format. I tested log calls with StringInterpolation and without, but with Args array. Both log messages have 3 args: Int, DateTime, String Log with Args: ~495 ns, 264 B allocated Log with StringInterpolation V1: 598 ns, 312 B allocated Log with StringInterpolation V2: 710 ns, 312 B allocated V1 creates the message and the message template in the handler itself and provides it with the state V2 collects the message parts (literals and values) in an array and creates the message or message template only when needed. Both versions did not run in the same process because I implemented the differences depending on a constant. Both versions work with the ArrayPool, if I don't do that they get faster but allocate more. Without the pool, V2 is slower and requires a lot more memory. I don't know if V2 is better - maybe because Message and MessageTemplate are mostly not needed at the same time? And I know I have to compare all different versions and situations in the same process ^^
Now check with LoggerMessage.Define and with the source generated version. It's gonna be both faster and will allocate no memory. The problem with the StringInterpolationHandler approach is that not every variable is a good property name, and leaving it to the variable name will lead to both bugs and inconsistent property names across different logs which will make deterministic searching a nightmare. I still don't see a viable good implementation.
@@nickchapsas I share your opinion that StringInterpolation is not good for logging, but such a StringInterpolationHandler is an interesting project :)
Considering how many people now use Lambda functions with C# and that console logging is directly supported out of the box for lambda, are all these extra packages required if you just implement your own implementation of console logger? I think maybe this is great for services which run within containers or direclty on servers (EC2) but maybe I've missed something here NIck?
You use string interpolation because it's easy. That's about it. Sometimes ease of use outweights other costs. Kind of like when you use C# instead of C++ or Rust.
The easy of use outweights losing crucial logging data? I don't know about that chief.
@@nickchapsas "crusial logging data" is highly debatable.
@@mwwhited Sure. You can always opt in a to lose the data you're logging, but then why are you collecting them in the first place :)
@@mwwhited It's not crucial until you need to debug something, every little bit of information counts. If you know the exact state under which something happened, you can easily reproduce the problem, fix it, and add it as a regression test. Properly using structured logging is a path to great observability.
people use C# instead of c++ because c++ is an obsolete garbage language.
What do you think of using SEQ from datalust to log too? I personally am loving it for how easy it is to install and query the logs in SEQ
I've used SEQ at scale in the past. It didn't do well
IMHO, one thing that is no perfect is the tokens will be random based on each developers' decesion when writing the log. If the data has significant value, I would write some kind of logContext to make the intention clear.
Hey Nick! Where would you say System.Diagnostics.Debug fits in the discussion about loggers?
Check my conditional compilation video out
Nick, great video but I noticed something else. I didn't knew about .net 6 Random.Shared, I was doing some other crazy stuff to have it thread safe. It's just a static call and no big deal? Maybe could be a good video too. Thanks
I think that’s a good video for a short
What is the framework you're using to build these HTTP APIs? It looks really interesting because it looks so simple, considering to learn it, so I'm interested which it is :D
Isn't it better to use LoggerMessage combined with EventId called from an ILogger extension method as is suggested by Microsoft?
Hello Nick, how did you create triple "aaa" snipped that you have on your Rider IDE?
It’s called a Live Template on my IDE. You can create any template you want
@@nickchapsas Thanks
Is logging performed ASYNC (or by fire and forget) in the background?
Depends on which library you are using for logging but it can yeah
I smelled custom string interpolation handlers, but I have never toyed with that feature to know whether it can act as an equally powerful replacement without sacrificing performance. Speaking of analyzers, however, you could give a go at making videos about source analyzers and source generators, including testing, if you can set them up of course.
Custom interpolated string handlers would absolutely work here.
When looking at serilog, they are actually boxing the properties into object arrays as well, so there's no performance loss if you box them in the custom interpolation handler.
Serilog is using generics so the properties aren't boxed. They do have 1 overload that is boxing them but that's for when you exceed the 3-4 overloads that accept generics
@@nickchapsas If you look at the generic overloads, you would see that they point back to the params object array call.
@@mindstyler Ah yeah that's correct, after they check for log level. The problem with the handler is that because I don't know the count ahead of time I can't pre-allocate an array so I have to use a list which I have to do a ToArray() to when calling the Serilog overload which will allocate it again.
@@nickchapsas well, i've toyed around with the custom handler a bit now, because I would love to use string interpolation for logging, and i've made discoveries. You can use the formattedCount from the constructor to initialize the object array and i've also found a microsoft article where they implement a custom handler for logging purposes, which was a really helpful source.
@@mindstyler Hmm the formattedCount is actually a good shout. This could actually work. Then the only problem is enforcing variable names only in the property spots.
now Im wondering how does it work with FormattableString , yay or nay? 🤔
Is this bug fixed currently in .net 7?
You don't have to use postman for these when you have REST Client plugin for Rider (and all JB apps) and httpYac for VSCode and cli
I’m surprised that ILogger doesn’t implement an override with FormattableString. Wouldn’t that theoretically allow you to get the desired result with interpolation?
You'd have a boxing issue
Why did you removed ILogger and replaced with ILogger? ILogger can not log structured? Also microsoft default logger has structured log?
I replaced it to show the API of the Serilog logger. The Microsoft one does structured logging too, but Serilog is a better library
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 surely losing information like SourceContext.
We don't do that on ElasticSearch. The fields generated with this approach (in our software) is insane.
I've used the ELK stack before and the things you can do with logstash and kibana are insane indeed
OK, I am not embarrassed to say it, I didn't know that "structured logging" existed until I saw this video which pulled me with the title "Stop using string interpolation when logging in .NET". So, basically, we shouldn't do string interpolation in logging because if we ever decide to use structured logging and want to be able to do intricate queries on our logs, the use of string interpolation will make it harder? Whatever happened to just having a log file that gets written to on a rolling basis everyday? Is this a case of YAGNI, or am I missing out on something big by not using structured logging? Is it worth it to search/replace all my log statements to do this?
Even for files that you write into, structured logging can be used to parse each line liek a json object and do significantly better analysis for your logs.
You can also use SEQ locally for free and there is a Serilog sink
Seq doesn’t scale for my needs. I’ve used it and had to move away from it
C# 10 already solved this problem didn't it? We have FormattableString/IFormatable and InterpolatedStringHandlerAttribute for this exact reason.
No it didn't C# 10 fixed the boxing problem but you still allocate N amount of strings which wastes memory and you are loosing the variable name of the property which is why Serilog never adopted FormattableString/IFormatable. Same reason why you can't adopt InterpolatedStringHandlerAttribute either. Because a simple variable refactoring can break your logs/alerts.
@@nickchapsas I'm not sure that the demonstrated use case here explains why not to use an interpolated string handler functionally, (and I also wonder when one of the prime justifications for the handler according to MSDN is performance) and as far as I know of interpolated string handlers its not strictly necessary to allocate more strings then would otherwise be allocated by any other method, interpolated strings are natively faster and take up less bytes then String.Format, (and as far as I can see are capable to generally consume less on both ends then conventional formatting would) and its not feasibly impossible to implement an interpolated string handler that might get close to performance of the current formatted manner, though it would be a pain to get anywhere near close to the the default handler, but that's honestly the same with any formatting. As for the others functions, I'm not sure what the point of keeping the variable name would be unless you were specifically formatting according to the variable name, (and I don't recall seeing that outside of maybe debugging specific instances) and are there any other cases where a variable refactor would break logs or alerts?
@@Spartan322 This video is not about performance. I already have one for that. This is about the loss of structured logging details. The first parameter in the log is a message template and the further parameters are used to fill in the template details. Those parameters are the individualized and passed to your log store in which you can further analyse with complex queries to get all sorts of details. You can also set alerts of certain values, for example if a request took more than Xms to complete. Using string interpolation means that you lose all that. If you hack your way into converting the variables to properties in logs then you risk variable name changes breaking your log queries and alerts and also since you can pass down anything and process it verbatim, it can break your parameter parsing all together.. I highly recommend you look into these two things: nblumhardt.com/2015/01/c-6-string-interpolation-and-serilog/ github.com/serilog/serilog/issues/1643 The second one tries to work some ways around the problem but none of them are convincing enough
@@nickchapsas The only reasonable way to solve the Serilog name I can think of would be with an IFormattable constraint for AppendFormatted which would enable you to name your interpolated sections with {expression:name} however I wouldn't be capable to tell you the efficiency of doing that and you're kinda violating the intended format specification for the type which might be undesirable.
Your videos are good but I don't know why you avoid Azure
I don't avoid it, I just haven't used it professionally for the past 3 years and I don't talk about things I don't know extensively
4:17 green :D
If a Nuget package is available? Challenge accepted bud.
seems like if you want 'structured' logging you should log a structure. why are you building messages with parameters at all? why not log a simple string indicating what is happening and then log the json that has the data you want to 'structure'...
Am I the only one using a "progress interface" to log, send back a porogress int, monitor for cancelation request and make espresso?
I still don't know why i should use logging in my apps (junior dev here)
Because colleting information about how your application works corretly, or incorrectly, if extremely useful both to ensure the correct operation of the app, but also investigate how things failed when the eventually failed. Maybe a topic for a full video
Thank you, Nick!
@@TheCodingColtrane Logging is how you figure out what went wrong (or right!) when you can't debug. Which is basically anytime your app is running in a production context.
That CallerArgumentExpression is going to be so non-performant.
It’s compile time so it’s blazing fast
@@nickchapsas so something that accepts a string with unknown number of or even what params doesn't use reflection? How? I'd like to learn!
I've never seen Amazon Cloud Watch in action. Must say... wow... it blows Microsofts pathetic "Application Insights" out of the water. App Insights is an absolute pain to work with, in literally every sense imaginable.
how do you hide and show method parameter hints with short key in here?! kzhead.info/sun/ad6ofciXfamJqok/bejne.html
It's a setting on my IDE. If I hold Ctrl it shows the hints and if I release it it hides them
Sorry your click bait title would be much more sensible as 'When using any structured logging framework ensure you let the structured logging framework generate your message string'. Why is string interpolation singled out here, after all it's just one of many ways to pass a plain string and therefore 'do it wrong'? Is the average .NET developer so lazy/incompetent/ignorant that they can't tell the difference between string interpolation and a structured logging template?
Nothing click bait about the title. Vert straight forward and to the point. The video is all about why you should "stop using string interpolation when logging in .NET". String interpolation is singled out because that's how people concatenate strings nowadays. I've never seen logs in post 2017 C#, using string concatenation or string.Format.
Or "Let your structured logging framework use its own string interpolation instead of using Microsoft's string interpolation". Because string interpolation absolutely is happening here.
@@Erkle64 It's actually using string formating not string interpolation
@@nickchapsas It's not using the thing Microsoft calls string interpolation. But string interpolation in general just means insert things in the middle of a string.
Don't ever tell me how to code!
@Nick: As always thanks for the content. Do you have any tips on how to manage/review usage of property NAMES in message templates? We already use a nice rider plugin (12832-structured-logging) which checks things like parameter count, PascalCase, ... but it is not enough. Log messages are all over the place, different devs of different microservices may use different poperty names for similar things. Consider this example, each line is within a different microservice, meaning the same thing: _logger.LogInformation("Application started from {Path}", myPath); _logger.LogInformation("Application started in {WorkingDirectory}", workingDir); _logger.LogInformation("App started from {AppPath}", _appPath); It would by desireable that at least the Property Name for this message is always exactly the same, so it can be queried (The message template as a whole is a different story..) How to review / lint / check this? One could create a class containing const strings like so while still keeping the structured logging: -------------------- public static class LogProperties { public const string ApplicationPath = "ApplicationPath"; } _logger.LogInformation($"Application started from {{{LogProperties.ApplicationPath}}}", myPath); -------------------- But this has several issues: - The curly bracket syntax is ugly as hell - string interpolation performance hit - One LogProperties class per app still needs synchronisation between teams - A global LogProperties class in the whole stack via nuget package introduces a dependency We use Grafana Loki as log backend and unfortunately without tight review / refactoring dashboarding becomes tedious (names are Case-Sensitive too)
One idea I came up with is to create a file containing a whitelist of wellknown PropertyNames, and a script which is regex grepping the source and extracting all used message template properties, and checking them against the whitelist. This could run as an automated task on the build server after pushing changes. But thats a crude hack, the whitelist would also needed to be reviewed / approved and so on...
In C# 10 interpolated strings are not an issue, have created an example project which illustrates why: github.com/IanPNewson/LoggingStrings
You just tanked your app's performance by allocating an unnecessary amount of objects and you also now leave the property name to the variable name. Variable names don't make good property names and if you need property names to be consistent between log entries (which you do), you can't rely on variable names. That way, changing a var name would be a breaking change because alerts or monitors might rely on that variable name being consistent and deterministic. This is not a viable option at all (and btw if you watched the full video you'd know why because I show this)
@@nickchapsas Did you read my example code? GitHub insights doesn't show any activity but that doesn't mean you didn't. But basically, InterpolatedStringHandler means you can do anything you like with the parameters.
@@ianpnewson I did read your code. I have a similar example in this video. You allocate 2 dictionaries and a string builder. This will lead to very bad performance and you’re not capturing the parameter names in a deterministic way. This approach is just not viable
@@nickchapsas my example was not to illustrate performance, but to illustrate the possibilities with the changes to string interpolation in c#10. I demonstrated you can use string interpolation and also capture structured data. Oh, and it *is* deterministic.
Hi! preserveLogFilename does not work in net.core, I want to keep the logfile name the same and when reached sizelimit create a new file with postfix, as below log_filename.log CURRENT (Always same name) log_filename.log.1 OLD File