openssh unix dev - Sep 2015 - [Bug 2464] New: Adding timestamp to debug messages (log.c:do_log)

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

            Bug ID: 2464
           Summary: Adding timestamp to debug messages (log.c:do_log)
           Product: Portable OpenSSH
           Version: 7.1p1
          Hardware: All
                OS: All
            Status: NEW
          Severity: enhancement
          Priority: P5
         Component: Miscellaneous
          Assignee: unassigned-bugs at mindrot.org
          Reporter: lzsiga at freemail.c3.hu

Created attachment 2702
  --> https://bugzilla.mindrot.org/attachment.cgi?id=2702&action=edit
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.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

L?rinczy Zsigmond <lzsiga at freemail.c3.hu> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |lzsiga at freemail.c3.hu

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

Darren Tucker <dtucker at zip.com.au> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |dtucker at zip.com.au
   Attachment #2702|application/octet-stream    |text/plain
          mime type|                            |
   Attachment #2702|0                           |1
           is patch|                            |

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

Darren Tucker <dtucker at zip.com.au> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Attachment #2702|0                           |1
        is obsolete|                            |

--- Comment #1 from Darren Tucker <dtucker at zip.com.au> ---
Created attachment 2740
  --> https://bugzilla.mindrot.org/attachment.cgi?id=2740&action=edit
adding timestamp to debug messages

Reformatting as unified diff for ease of commenting.  Not sure if we
want to do this, though.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

--- Comment #2 from Darren Tucker <dtucker at zip.com.au> ---
Comment on attachment 2740
  --> https://bugzilla.mindrot.org/attachment.cgi?id=2740
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.

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

--- Comment #3 from Darren Tucker <dtucker at zip.com.au> ---
Created attachment 2741
  --> https://bugzilla.mindrot.org/attachment.cgi?id=2741&action=edit
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.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |djm at mindrot.org

--- Comment #4 from Damien Miller <djm at mindrot.org> ---
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.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

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

Hmmm... full IOS8601 compliance would include the timzeone so the format
string would be "%Y%m%dT%H%M%S%z" (and need to increase the size of
the
timebuf[20] by one byte or you would use gmtime() instead of localtime()
and the format string "%Y%m%dT%H%M%SZ". I think gmtime() may be
simpler.

	-- Mark

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

Darren Moffat <darren.moffat at oracle.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |darren.moffat at oracle.com

--- Comment #5 from Darren Moffat <darren.moffat at oracle.com> ---
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.

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

--- Comment #6 from Darren Moffat <darren.moffat at oracle.com> ---
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.

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=2464

jason.nader at protonmail.com changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jason.nader at protonmail.com

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.