Bug 2464 - Adding timestamp to debug messages (log.c:do_log)
Summary: Adding timestamp to debug messages (log.c:do_log)
Status: NEW
Alias: None
Product: Portable OpenSSH
Classification: Unclassified
Component: Miscellaneous (show other bugs)
Version: 7.1p1
Hardware: All All
: P5 enhancement
Assignee: Assigned to nobody
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-09-12 16:47 AEST by Lőrinczy Zsigmond
Modified: 2019-01-04 02:18 AEDT (History)
4 users (show)

See Also:


Attachments
adding timestamp to debug messages (373 bytes, patch)
2015-09-12 16:47 AEST, Lőrinczy Zsigmond
no flags Details | Diff
adding timestamp to debug messages (913 bytes, patch)
2015-10-29 11:13 AEDT, Darren Tucker
no flags Details | Diff
Changes as suggested. (847 bytes, patch)
2015-10-29 11:59 AEDT, Darren Tucker
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Lőrinczy Zsigmond 2015-09-12 16:47:45 AEST
Created attachment 2702 [details]
adding timestamp to debug messages

Hi, I know it is very trivial thing, but it still might be helpful when hunting problems (for example my problem occurred at boot-time on an AIX-computer (it wasn't sshd's fault, but the -d option helped to debug)).
See the attached paths.
Comment 1 Darren Tucker 2015-10-29 11:13:42 AEDT
Created attachment 2740 [details]
adding timestamp to debug messages

Reformatting as unified diff for ease of commenting.  Not sure if we want to do this, though.
Comment 2 Darren Tucker 2015-10-29 11:26:31 AEDT
Comment on attachment 2740 [details]
adding timestamp to debug messages

>+#include <sys/timeb.h>

style(9) says this should go with the other <sys/...> includes. 

>+		ftime (&tb);

ftime is obsolete and has been removed from POSIX.1-2008.  Should use gettimeofday instead.

>+		localtime_r (&tb.time, &tm);
>+		p += strftime (p, 16, "%Y%m%d.%H%M%S", &tm);

I'm not a fan of unnecessary pointer arithmetic.  Since this is neither time nor space critical, I'd rather strftime into a static buffer then use snprintf to assemble the final string.

>+		p += sprintf (p, ".%03d ", tb.millitm);

also not a fan of unbounded string functions even if this particular one is safe.
Comment 3 Darren Tucker 2015-10-29 11:59:39 AEDT
Created attachment 2741 [details]
Changes as suggested.

Diff updated with suggested changes (also, making the timestamp format ISO8601 compliant).

That said, what's the use case for this?  The timestamps are bulky, and the only time I'm ever interested in the timing of them is the relative time, which could be done in a lot less space by printing the number of seconds since the previous log message.
Comment 4 Damien Miller 2015-10-29 12:04:51 AEDT
Why not use syslog? Both ssh and sshd support it and you get timestamps for free?

I definitely don't think it should be on by default.
Comment 5 Darren Moffat 2019-01-04 02:17:05 AEDT
I've had some usecases recently for some sort of timestamp or timedelta in the debug messages output.

It is fairly common to request 'ssh -vvv' output when debugging connection problems.

In my environment the person assisting with the debugging of the connection is almost never the one running the client (or server). 
While it is true that syslog would add a timestamp, it isn't always possible for the user that is running the 'ssh -vvv' to update the syslog configuration.  That could be for a various reasons, eg lacking privilege to do so or the system syslog configuration is controlled via a configuration management system and isn't allowed to be altered.

I agree with the prior comments that a delta rather than an absolute time is probably more generally useful but either would be sufficient.
Comment 6 Darren Moffat 2019-01-04 02:18:13 AEDT
As for it being on by default, maybe a good compromise would be that
timestamps are only added when the debug output is sent to a file rather than on stderr/syslog.