console log should have an option to add timestamps

[Clint Byrum]

While some programs will readily output timestamps, it would be better if console log would add them. This would make the logs sortable and mergable for debugging purposes.

[Steve Langasek (vorlon)]

(nominally "wishlist", but raising it higher because this impacts the usability of log files)

[James Hunt (jamesodhunt)]

I can see this would be useful, but since the data the logger receives is byte-oriented, adding timestamp data certainly wouldn't look very pretty. It would also change the semantics of the stanza and break all the log tests since they currently assume the log contains only what is output from the jobs.

Rather than adding timestamps, my strong preference would be to support 'console syslog' (bug 885202) such that timestamps or time offsets are added "for free".

[Clint Byrum (clint-fewbar)]

Excerpts from James Hunt's message of 2013-03-20 10:57:23 UTC:
> I can see this would be useful, but since the data the logger receives
> is byte-oriented, adding timestamp data certainly wouldn't look very
> pretty. It would also change the semantics of the stanza and break all
> the log tests since they currently assume the log contains only what is
> output from the jobs.
>
> Rather than adding timestamps, my strong preference would be to support
> 'console syslog' (bug 885202) such that timestamps or time offsets are
> added "for free".
>

Except they're lost in early boot, when they might do a lot of good in
finding timing problems.

The tests can be fixed. Reading and looking for newlines to know when
to add a timestamp is not hard. This seems trivial to do as long as we
have easy access to the system clock, which I'm not entirely sure we do.

[Steve Langasek (vorlon)]

On Wed, Mar 20, 2013 at 10:57:23AM -0000, James Hunt wrote:

> Rather than adding timestamps, my strong preference would be to support
> 'console syslog' (bug 885202) such that timestamps or time offsets are
> added "for free".

I don't think a proliferation of 'console' options is a good idea here.
Consistency is valuable... it's not like there's a whole lot of filtering
you could usefully do with syslog other than string matches, given that you
won't have meaningful message priorities and facilities.

[James Hunt (jamesodhunt)]

The description of this bug already mentions a new option (by which I assume Clint means something like 'console timelog' or 'console log --timestamps' ?)

So, that already implies a new variety of console stanza. I personally do not think we should change the current meaning of 'console log' since, as we do not currently support syslog, who knows what sorts of scripts folk have that might be slurping this data and piping it over syslog or filtering the logs with nagios, etc (let's not forget that 'console log' is in an LTS release already).

Adding something like 'console syslog' seems like a good alternative as it is not breaking the existing behaviour. But for another twist, how about 'console kmsg' - that *is* available from early boot and also has the ability to timestamp.

What format would these timestamps take? Would that format be configurable? What time resolution is appropriate? I'd rather leave an existing facility like syslog or the kernel ring buffer to deal with that.

> Reading and looking for newlines to know when
> to add a timestamp is not hard.
Imagine this scenario: a job produces a 300Mb stream of bytes which only contains \n right at the end. That means -- if we want to add timestamps -- that Upstart has to buffer that data until it sees the \n (since it wouldn't make sense to write the timestamp *before* a "line" of data was actually read). This is admittedly a contrived example but it has to be catered for. Currently, that situation should not arise since the data is persisted as soon as possible.

[Steve Langasek (vorlon)]

On Fri, Mar 22, 2013 at 04:13:07PM -0000, James Hunt wrote:
> The description of this bug already mentions a new option (by which I
> assume Clint means something like 'console timelog' or 'console log
> --timestamps' ?)

Yeah, I see that it does say that. But I think if we implement this, it
should be part of 'console log', not an added option.

> So, that already implies a new variety of console stanza. I personally
> do not think we should change the current meaning of 'console log'
> since, as we do not currently support syslog, who knows what sorts of
> scripts folk have that might be slurping this data and piping it over
> syslog or filtering the logs with nagios, etc (let's not forget that
> 'console log' is in an LTS release already).

That's true, but we've never promised to maintain compatibility with the
'console log' behavior between upstream releases. If timestamping is
important (and I think it is), I think it's worth changing the standard
behavior for, not just making it a new option.

> Adding something like 'console syslog' seems like a good alternative as
> it is not breaking the existing behaviour. But for another twist, how
> about 'console kmsg' - that *is* available from early boot and also has
> the ability to timestamp.

kmsg is available from early boot, but if you overflow the kernel ringbuffer
then the early messages don't get logged anywhere persistent on disk. Also,
my personal experience is that upstart's use of kmsg is fairly
unsatisfactory already because it makes it difficult to read the output of
'dmesg' when looking for kernel issues.

> What format would these timestamps take?

ISO, the one true time format.

> Would that format be configurable?

No.

> What time resolution is appropriate?

Second-level resolution should be sufficient, just as it is for syslog.

> > Reading and looking for newlines to know when
> > to add a timestamp is not hard.

> Imagine this scenario: a job produces a 300Mb stream of bytes which only
> contains \n right at the end. That means -- if we want to add timestamps
> -- that Upstart has to buffer that data until it sees the \n (since it
> wouldn't make sense to write the timestamp *before* a "line" of data was
> actually read).

Why doesn't it make sense? I don't see any reason that the time at the end
of the write is more relevant than the time at the beginning of the write -
in the vast majority of cases it's exactly the same at any resolution we
would care about - and if you write out the timestamp at the beginning and
start writing the rest of the line afterwards, you don't have this buffering
problem at all.

Cheers,
--
Steve Langasek Give me a lever long enough and a Free OS
Debian Developer to set it on, and I can move the world.
Ubuntu Developer http://www.debian.org/
<email address hidden> <email address hidden>

[Clint Byrum (clint-fewbar)]

Excerpts from James Hunt's message of 2013-03-22 16:13:07 UTC:
> The description of this bug already mentions a new option (by which I
> assume Clint means something like 'console timelog' or 'console log
> --timestamps' ?)
>
> > Reading and looking for newlines to know when
> > to add a timestamp is not hard.
> Imagine this scenario: a job produces a 300Mb stream of bytes which only contains \n right at the end. That means -- if we want to add timestamps -- that Upstart has to buffer that data until it sees the \n (since it wouldn't make sense to write the timestamp *before* a "line" of data was actually read). This is admittedly a contrived example but it has to be catered for. Currently, that situation should not arise since the data is persisted as soon as possible.

Max line length can be low enough to not care much about the
buffer. Arbitrarily I'll say 8K because that seems to be the standard
linux/unix answer for buffers. After 8K, write the line, w/ a timestamp,
and a mark of some kind to note the line continuation so lines can be
reassembled automatically.

[btw, clever way to make your point, not line wrapping it.. ;) ]

[Michał Sawicz (saviq)]

Sorry for digging this up, but it became more even important now that we do session upstart. Syslog or kmsg are not valid options, and I agree this is important - my immediate use case is being able to merge verbose autopilot output with the tested app output when the app is launched via session upstart.

[Leo Arias (elopio)]

+1, this makes it really hard to link the unity8 events to autopilot events when digging into the logs of a failed test.