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

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

[Jack]

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?

Thanks for any thoughts.

Jack

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

[Jack]

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.

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

[cal]

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

Cal

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

[Jack]

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.

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

[cal]

On 11/17/20 7:33 AM, Jack wrote:
> 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.

You may be able to get somewhere by setting the TZ environment variable 
to your desired timezone.

https://www.gnu.org/software/libc/manual/html_node/TZ-Variable.html

Cal