Skip to content
This repository has been archived by the owner. It is now read-only.

Output timestamp by default #483

Closed
johanskoldekrans opened this issue Aug 29, 2016 · 26 comments

Comments

@johanskoldekrans
Copy link

commented Aug 29, 2016

Is there a way to output the timestamp of each log to the stdout-files? Without having to do it everywhere or using a provider? we are happy with the logging infrastructure you built for core but just want it to output the time.

@BrennanConroy

This comment has been minimized.

Copy link
Member

commented Aug 29, 2016

When you call Log(...) you could pass in a formatter that adds the timestamp:

logger.Log(LogLevel.Information, 1, someObj, null, (s, e) => DateTime.Now + " " + s.ToString());
@benaadams

This comment has been minimized.

Copy link
Contributor

commented Aug 29, 2016

Wondering if it would be worth moving something like Kestrel's DateHeaderValueManager and interface up a few abstraction levels as most of the datetimes and the ToStrings will be identical over a request that only take ms.

@johanskoldekrans

This comment has been minimized.

Copy link
Author

commented Aug 29, 2016

@BrennanConroy Yes, I know it can be done when I call Log() but i would love to have it on everything kestrel logs. We want to move our production environment to Linux and this is one of the last hurdles to get good logging for everything. The IIS-log is easy to parse but the Kestrel log seems better for debugging as it is now if you don't add lots of extras in a formatter and that doesnt help what Kestrel outputs. Would be nice to have an option in startup you can set to format all requests or add basic tracking data.

@johanskoldekrans

This comment has been minimized.

Copy link
Author

commented Aug 29, 2016

If you believe the cost is too high to implement as default an optional setting might be best or a general formatter for all Log()-calls.

@muratg

This comment has been minimized.

Copy link

commented Oct 5, 2016

This is an interesting idea, though I don't think most people would prefer this to be the default. It has to be an option at best.

Since there's an easy workaround (basically making an extension method from @BrennanConroy's snippet above), backlogging.

@muratg muratg added this to the Backlog milestone Oct 5, 2016

@thenathanjones

This comment has been minimized.

Copy link

commented Dec 2, 2016

@muratg It's interesting that you believe people wouldn't prefer this to be the default. I've never worked on a system where we didn't want the time outputted, and in fact it is in the default log format for nearly every logger I've ever used? I get the desire for simplicity, in fact I'd love the time to be added purely so I don't have to add anything else.

@HarelM

This comment has been minimized.

Copy link

commented Mar 18, 2017

I agree with @thenathanjones. For some reason this is also the default for Msbuild (and for the life of me I couldn't find a way to change it, but this is irrelevant for here), is this a Microsoft mindset?
A correctly written log must have a time-stamp.
I also couldn't find a way to format the log that is written to the console, am I missing something?
I'm writing a console application that is scheduled to run every day, I want to be able to run it manually and see the log written to the console - this console will be written to a file so I can check it later, so I need the logging to the console to be very much like when writing to a log file.

@bgever

This comment has been minimized.

Copy link

commented Aug 7, 2017

So I was debugging a problem and used the logs to find out what happened,
but I was unable to pinpoint when it happened, because there are no timpestamp!

Sure, for development-time I get it, but we're surely meant to be able to run .NET Core in production, right?

Sorry for being blunt, but it's ridiculous there is no timestamp information. Just look at all the thumbs up!

CC: @Tratcher @danroth27

@davidfowl

This comment has been minimized.

Copy link
Member

commented Aug 7, 2017

Just use a sink like Serilog that has tons of enrichers. We provide the abstractions and a few very basic sinks, the value being that libraries can take a dependency on this without being tied to a specific logging sink.

I highly recommend using a sink that supports timestamps and other ambient information. This should not be part of the general logging interface.

@bgever

This comment has been minimized.

Copy link

commented Aug 7, 2017

@davidfowl I don't think that's going to work with Azure App Service using the ANCM stdoutLogFile to get output files.

Could you clarify why this should not be part of the general logging interface? Per the above customer feedback and upvotes, it looks like many expect this to be a pretty fundamental feature.

@davidfowl

This comment has been minimized.

Copy link
Member

commented Aug 7, 2017

@davidfowl I don't think that's going to work with Azure App Service using the ANCM stdoutLogFile to get output files.

Of course it would. Use Serilog's console logger and it'll work just fine with ANCM's stdoutLogFile.

Could you clarify why this should not be part of the general logging interface?

The logging interface should be minimal as it's an abstraction that should work for every sink out there. Logging timestamps is not a fundamental piece of information and doesn't belong on the core logging abstraction. On top of that, each of the sinks have their own ways to add timestamps and applying other ambient information to each log.

Per the above customer feedback and upvotes, it looks like many expect this to be a pretty fundamental feature.

Don't confuse me saying "it doesn't belong on the abstraction" with "it's not useful", customers ask for lots of things and it's our job to make sure we make people happy while preserving what we think are the right abstractions.

That said, we could consider adding something specific to the console logger since that seems to be what people are using (It's the only sink we provide that's barely useful TBH). I'm not sure why people are using the console logging in production anyways, you'll lose all of the structured information and richness the logging system provides.

@bgever

This comment has been minimized.

Copy link

commented Aug 7, 2017

@davidfowl I don't think that's going to work with Azure App Service using the ANCM stdoutLogFile to get output files.

Of course it would. Use Serilog's console logger and it'll work just fine with ANCM's stdoutLogFile.

Thanks for the pointer, at first I dismissed this option as it means plugging in yet another framework abstraction into the pipeline for something as simple as console log output. I see how it can work.

It would be really helpful to have timestamps in the standard console logger as it helps for the following scenarios:

  • Determine whether console entries are recent nor not.
  • If looking at an historical output, when did certain events happen.

Then it does not require to re-route the built-in console logger and add in extra configuration.

@davidfowl

This comment has been minimized.

Copy link
Member

commented Aug 7, 2017

I think the problem is that people misunderstand what this logging repository really is and it's our fault and should be made clearer. This really is a logging abstraction, the default sinks are very extremely basic and usually farm out to other systems to get more features. Timestamps is one thing, but what happens when you want some other ambient piece of information, like the machine name?

There are so many amazing 3rd party logging systems with richer features than what we will ever provide OOTB. I'd recommend you use those in your production applications. I'd also recommend picking a logging system that preserves the structured logs so you can filter/query search them without re-parsing console output piped to an file.

@bgever

This comment has been minimized.

Copy link

commented Aug 7, 2017

Maybe the documentation on the Introduction to Logging in ASP.NET Core page could be improved to make that point clearer?

Since it mainly sets out how to setup logging with the built-in console logger. The console logger is also in most getting started guides, and the new WebHost.CreateDefaultBuilder configures the console logger by default as well.

To support your point, we do use a 3rd party logger in production for all the benefits you mentioned.
We're now setting up our first production facing ASP.NET Core frontend in Azure App Services and encountered this during the first trial runs.
You can't beat simple console to file logging combined with the excellent new App Service Editor. 😄

Maybe a production scenario example in that linked page with the use of Serilog would help? As it is a pretty neat solution.

Keep up the great work! 👍

@davidfowl

This comment has been minimized.

Copy link
Member

commented Aug 7, 2017

You can't beat simple console to file logging combined with the excellent new App Service Editor.

Oh yes you can 😄. Losing the structure and scope from logs is a tragedy.

Maybe a production scenario example in that linked page with the use of Serilog would help? As it is a pretty neat solution.

Yes, we should have something.

@HarelM

This comment has been minimized.

Copy link

commented Aug 7, 2017

As written by many other here, and to clarify what I wrote:
Logging abstraction should stay abstract and there shouldn't be any change in the interface IMHO.
Having said that, the fact that the tutorials are pointing to the default console logger, and the fact that it's super easy to add to a project can make it as a possible production logger candidate for simple and small applications (for example command-line apps that need to do a very specific and small task).
These would benefit from adding a time-stamp to every line of log (Also can be made optional in a configuration class if you don't think it should be by default, I think it should).
I might not understand the repositories hierarchy well, but isn't this the repository that hold the code for the default console logger?

@offbeatful

This comment has been minimized.

Copy link

commented Sep 10, 2017

+1 to have configuration to output time stamps.
My case is to have my NUnit tests output logs with time stamps.

@alexb5dh

This comment has been minimized.

Copy link

commented Sep 10, 2017

For now you can also replace default logger with something like this:

using System;
using Microsoft.Extensions.Logging;

public class TimedLogger<T>: ILogger<T>
{
    private readonly ILogger _logger;

    public TimedLogger(ILogger logger) => _logger = logger;

    public TimedLogger(ILoggerFactory loggerFactory): this(new Logger<T>(loggerFactory)) { }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter) =>
        _logger.Log(logLevel, eventId, state, exception, (s, ex) => $"[{DateTime.UtcNow:HH:mm:ss.fff}]: {formatter(s, ex)}");

    public bool IsEnabled(LogLevel logLevel) => _logger.IsEnabled(logLevel);

    public IDisposable BeginScope<TState>(TState state) => _logger.BeginScope(state);
}

Replace it in Startup.ConfigureServices:

services.Replace(ServiceDescriptor.Singleton(typeof(ILogger<>), typeof(TimedLogger<>)));
@HarelM

This comment has been minimized.

Copy link

commented Oct 23, 2017

I would have +1 the above except it's not focused on the topic of this issue and also I believe DI is essential to every system - The amount of applications I've seen that started from a "simple console application" and developed to an monster are too many to count as so I think DI is a must even for small projects as they tend to grow.
Regardless, I agree that basic logging should be part of the framework and it shouldn't depend on third-party packages.
I also think that the MSDN tutorials are good enough as opposed to framework with less documentation I needed to use, of course they can be made better as do almost anything :-).

@dalbani

This comment has been minimized.

Copy link

commented Sep 24, 2018

@alexb5dh: for some reason, I don't see any difference in the logging (i.e. no timestamp) when calling services.Replace(...). What could I be doing wrong?

@ylhyh

This comment has been minimized.

Copy link

commented Sep 28, 2018

@davidfowl

I'm not sure why people are using the console logging in production anyways

In docker environment, use console logging can easily output logs to stdout, that's why we use console logging.

@muratg muratg modified the milestones: Backlog, 3.0.0 Sep 28, 2018

@jemiller0

This comment has been minimized.

Copy link

commented Sep 28, 2018

Something is seriously wrong with a system that can't do something as simple as output a timestamp. There should be a reference implementation that works in a reasonable manner. IMHO, it is ridiculous that you should have to use a third party library to do something as critical as logging. Forcing dependency injection is ridiculous as well. I would be happy to stick with using TraceSource if it weren't for the fact that it was lobotomized and made completely useless on .NET Core due to the fact that it doesn't read the settings from the config file. As far as I'm concerned the new design is convoluted as hell. Microsoft should be designing systems that are easy to use. Or people will switch to another platform. I'm not even a Python programmer and I was able to get it's built-in logging working with a minimum of hassle. .NET Core should have something that is similarly easy to use and it doesn't. I don't know if you've noticed, but, you are losing market share. It is hard enough to make an argument to use Microsoft products where I work. I need to be able to say, we should be using C# because it is better and here's why. If I Python programmer looked at this, they would think it was a joke.

@muratg

This comment has been minimized.

Copy link

commented Sep 28, 2018

Something is seriously wrong with a system that can't do something as simple as output a timestamp.

@jemiller0 This is totally possible today with a formatter. Your other points (on DI, 3rd party libraries vs internal ones etc.) are subjective and lots of folks think otherwise.

That being said, this is now in for 3.0.0 milestone.

@cwe1ss

This comment has been minimized.

Copy link
Contributor

commented Sep 28, 2018

@muratg This is totally possible today with a formatter.

Does that work globally or do I have to pass the formatter to every call?

@muratg

This comment has been minimized.

Copy link

commented Sep 28, 2018

@cwe1ss currently you'd probably want to implement extension methods with specific formatters you'd like.

#483 (comment) is also another approach you may consider looking into.

@cwe1ss

This comment has been minimized.

Copy link
Contributor

commented Sep 28, 2018

#483 (comment) is also another approach you may consider looking into.

that's interesting, thank you!

Extension methods / per call parameters aren't a solution in my opinion as they wouldn't work on any 3rd party log calls (e.g. anything from the ASP.NET framework)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
You can’t perform that action at this time.