1.9.15: `sudo.log` vs. `auth.log` start logging

[opty77]

On Debian GNU/Linux 11.8 (Bullseye) sudo (asking for password) logs its start timestamp in /var/log/sudo.log:

Nov  8 13:27:35 2023 : opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log'
Nov  8 13:27:40 2023 : opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log' ; EXIT=0

but the actual command start timestamp in /var/log/auth.log:

2023-11-08T13:27:40.745588+01:00 kiwi sudo 1259508 - -     opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log'
2023-11-08T13:27:40.751619+01:00 kiwi sudo 1259508 - -     opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log' ; EXIT=0

Bug or feature? :-)

(I had already discovered sooner and wanted to analyze the code first but I would probably have reported much later than even still late now so I'm rather finally going ahead, sorry. :-/)

[millert]

It sounds like sudo is configured to log to both a file (/var/log/sudo.log) and syslog (/var/log/auth.log). In the case of the file log, sudo has control over the entire entry so the time stamp is accurate. In the case of /var/log/authlog, the time stamp is added by whatever log daemon is running, probably the systemd journal. If you switch the log format to JSON sudo will log the start and end times in the JSON data itself (in several formats).

[opty77]

Yes, sudo logs to both files and no, I don't use systemd but rsyslog although I believe that these don't matter. Let me try to rephrase:

When you have to supply the password then sudo logs its own start to /var/log/sudo.log but the actual command start to /var/log/auth.log so the timestamps differ due to password typing and submitting taking a moment. Maybe you noticed I deliberately chose 5 seconds there for a proof of what I found by accident.

On the other hand in case of already cached credentials /var/log/sudo.log:

Nov  9 13:42:40 2023 : opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log'
Nov  9 13:42:40 2023 : opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log' ; EXIT=0

basically matches /var/log/auth.log:

2023-11-09T13:42:40.592802+01:00 kiwi sudo 1298785 - -     opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log'
2023-11-09T13:42:40.597149+01:00 kiwi sudo 1298785 - -     opty : TTY=pts/10 ; PWD=/home/opty ; USER=root ; COMMAND=/bin/bash -c 'tail /var/log/{auth,sudo}.log' ; EXIT=0

Summary: I don't question when sudo/rsyslog logs but rather what (step).

[millert]

For sudo.log, the time stamp logged is the "submit time", which is when the user ran sudo (before authentication). It is not the time when the command started to execute. For auth.log the time stamp is created by rsyslogd so it is the time when the log message was received, which happens after authentication and so is closer to the time the command actually executed. I don't think that either one is really more correct than they other, they are just different.

[opty77]

I believe that sudo should log the same steps to both files to avoid confusion and I would choose "command start" (after authentication) as log records suggest.

If you don't (can't) agree (yet) or I'm still missing something then your explanation probably qualifies enough to close this issue because I would like not to keep it open for too long.

[millert]

Resolved by 39ea317 which changes the time stamp in the log file to match the time the event is logged instead of the time sudo was run. This consistent with historic sudo behavior and should match the time stamp logged via syslog.

[opty77]

Just FYI: It works but unfortunately I found probably new related issue which I'm going to open (hopefully) soon. :-/

Edit: Just opened as #405.