Re: [gentoo-user] odd issue with RTKIT syslog-ng

[Jack <ostroffjh@users.sourceforge.net>]

On 2020.11.16 21:00, cal wrote:
> On 11/16/20 4:22 PM, Jack wrote:
>> On 2020.11.15 19:02, Jack wrote:
>>> As usual, I've got what seems to be a really obscure problem, and I  
>>> have not found any reference to it searching the interwebs.
>>> 
>>> The suspect package is sys-auth/rtkit-0/13-r1 (which has nothing to  
>>> do with chkrootkit) and I'm using app-admin/syslog-ng-3.26.1-r1.
>>> 
>>> As a typical example from /var/log/messages (extract, and having  
>>> reconfigured syslog-ng to us iso timestamps)
>>> 
>>> 2020-11-15T18:30:01-05:00 localhost CROND[7320]: (root) CMD  
>>> (/usr/lib/sa/sa1 1 1)
>>> 2020-11-15T23:34:10-05:00 localhost rtkit-daemon[6263]: Supervising  
>>> 0 threads of 0 processes of 0 users.
>>> 2020-11-15T23:36:38-05:00 localhost rtkit-daemon[6263]: Supervising  
>>> 0 threads of 0 processes of 0 users.
>>> 2020-11-15T18:40:01-05:00 localhost CROND[15943]: (root) CMD (test  
>>> -x /usr/sbin/run-crons && /usr/sbin/run-crons)
>>> 
>>> All rtkit messages to syslog seem to be in UTC, or at least five  
>>> hours off from my local Americas/New York timezone.  rtkit uses the  
>>> syslog() call for all logging, and there is nothing in those calls  
>>> that even mentions timezone.
>>> 
>>> However, in digging further, I found two log entries from rtkit  
>>> which do appear to be using local time.  In looking at the rtkit  
>>> source, those two use the LOG_INFO and LOG_NOTICE as their levels.   
>>> All other logging in rtkit uses LOG_ERR, LOG_DEBUG, or LOG_WARNING,  
>>> with one exception:  I see one LOG_INFO message (repeated,  
>>> scattered across the log) which does show the UTC time.
>>> 
>>> So, does anyone have an idea what is going on?
>>> 
>>> I have one theory so far, but I a bit stuck on how to test it.  I'm  
>>> not sure where in the boot process rtkit gets started, but I think  
>>> it's automatically started when Dbus starts.  As part of the  
>>> daemon's startup routine, it drops some privileges.  Is it possible  
>>> that the applicable timezone gets changed when it drops  
>>> privileges?  As far as I can tell, the log messages with the  
>>> correct time are all produced before it drops privs.  Am I barking  
>>> up the right tree, or am I barking mad?
>> 
>> I've done some more digging, with lots of debugging output.  Up to a  
>> point, the process acknowledges the local timezone.  However, after  
>> doing a 'chroot "/proc"' and then 'chdir "/"' it thinks it's UTC.   
>> Still doesn't make any sense to me, though.
> 
> glibc uses /etc/localtime to for timezone conversion.  Changing root  
> to a new root directory that does not have this file (or has a  
> different one in its place) will show a different local time  
> conversion.
> 
> Example program:
> #include <stdio.h>
> #include <time.h>
> #include <unistd.h>
> 
> int main()
> {
> 	time_t now = time(NULL);
> 	printf("Time outside of chroot = %s", ctime(&now));
> 	chroot("/proc");
> 	printf("Time inside of chroot = %s", ctime(&now));
> 	return 0;
> }
> 
> Time outside of chroot = Mon Nov 16 17:58:19 2020
> Time inside of chroot = Tue Nov 17 01:58:19 2020
Thanks for the confirmation.  I finally also tracked it down to the  
same thing.  In this particular case, once rtkit does the chroot, it  
gets the same time, but without knowing the time zone, so assumes UTC.   
When it calls syslog, syslog-ng uses that UTC timestamp as is, but  
apparently doesn't know it is not in local time.

I'm going to see if the program can capture the local time zone before  
doing the chroot, and then applying it again afterwards.