[go: nahoru, domu]

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wrong time in JournalReader #15

Open
mastykin opened this issue May 22, 2019 · 1 comment
Open

wrong time in JournalReader #15

mastykin opened this issue May 22, 2019 · 1 comment

Comments

@mastykin
Copy link

Hello,
I'm using version 1.1.1 on Ubuntu 16.04. There is a difference in timestamps when reading via JournalReader and journalctl. Some of my log messages contain time info, that is identical with journalctl timestamps. Timezone difference doesn't matter, please look to seconds.
Thank you!

reader = JournalReader()
reader.open(JournalOpenMode.SYSTEM)
reader.seek_head()
for record in reader:
    print(record.date, record.data['MESSAGE'])

results in:

2019-05-21 08:53:20 2019-05-21T11:52:40+03:00
2019-05-21 08:53:20 2019-05-21T11:52:40+03:00
2019-05-21 08:53:20 [system] Successfully activated service 'org.freedesktop.timedate1'
2019-05-21 08:53:20 Started Time & Date Service.
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /time 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
2019-05-21 08:53:20 2019-05-21T11:53:43+03:00
2019-05-21 08:53:20 [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
2019-05-21 08:53:20 2019-05-21T11:53:43+03:00
2019-05-21 08:53:20 Starting Time & Date Service...
2019-05-21 08:53:20 2019-05-21T11:53:43+03:00
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
2019-05-21 08:53:20 [system] Successfully activated service 'org.freedesktop.timedate1'
2019-05-21 08:53:20 Started Time & Date Service.
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /time 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
2019-05-21 08:53:20 2019-05-21T11:53:53+03:00
2019-05-21 08:53:20 2019-05-21T11:53:53+03:00
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
2019-05-21 08:53:20 2019-05-21T11:53:53+03:00
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
2019-05-21 08:53:20 admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /time 200 OK
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
2019-05-21 08:55:28 2019-05-21T11:55:53+03:00
2019-05-21 08:55:28 [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
2019-05-21 08:55:28 2019-05-21T11:55:53+03:00
2019-05-21 08:55:28 Starting Time & Date Service...
2019-05-21 08:55:28 2019-05-21T11:55:53+03:00
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
2019-05-21 08:55:28 [system] Successfully activated service 'org.freedesktop.timedate1'
2019-05-21 08:55:28 Started Time & Date Service.
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
2019-05-21 08:55:28 admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /time 200 OK
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
2019-05-21 08:57:36 2019-05-21T11:58:27+03:00
2019-05-21 08:57:36 [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
2019-05-21 08:57:36 Starting Time & Date Service...
2019-05-21 08:57:36 2019-05-21T11:58:27+03:00
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
2019-05-21 08:57:36 2019-05-21T11:58:27+03:00
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
2019-05-21 08:57:36 [system] Successfully activated service 'org.freedesktop.timedate1'
2019-05-21 08:57:36 Started Time & Date Service.
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
2019-05-21 08:57:36 admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK

journalctl output:

май 21 11:52:40 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:52:40+03:00
май 21 11:52:40 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:52:40+03:00
май 21 11:52:40 mitya-VirtualBox dbus[620]: [system] Successfully activated service 'org.freedesktop.timedate1'
май 21 11:52:40 mitya-VirtualBox systemd[1]: Started Time & Date Service.
май 21 11:52:40 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
май 21 11:52:40 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
май 21 11:52:40 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /time 200 OK
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
май 21 11:53:43 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:53:43+03:00
май 21 11:53:43 mitya-VirtualBox dbus[620]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
май 21 11:53:43 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:53:43+03:00
май 21 11:53:43 mitya-VirtualBox systemd[1]: Starting Time & Date Service...
май 21 11:53:43 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:53:43+03:00
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
май 21 11:53:43 mitya-VirtualBox dbus[620]: [system] Successfully activated service 'org.freedesktop.timedate1'
май 21 11:53:43 mitya-VirtualBox systemd[1]: Started Time & Date Service.
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
май 21 11:53:43 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /time 200 OK
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
май 21 11:53:53 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:53:53+03:00
май 21 11:53:53 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:53:53+03:00
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
май 21 11:53:53 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:53:53+03:00
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
май 21 11:53:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /time 200 OK
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
май 21 11:55:53 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:55:53+03:00
май 21 11:55:53 mitya-VirtualBox dbus[620]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
май 21 11:55:53 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:55:53+03:00
май 21 11:55:53 mitya-VirtualBox systemd[1]: Starting Time & Date Service...
май 21 11:55:53 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:55:53+03:00
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
май 21 11:55:53 mitya-VirtualBox dbus[620]: [system] Successfully activated service 'org.freedesktop.timedate1'
май 21 11:55:53 mitya-VirtualBox systemd[1]: Started Time & Date Service.
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
май 21 11:55:53 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /time 200 OK
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /static/http.js 304 NOT MODIFIED
май 21 11:58:27 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:58:27+03:00
май 21 11:58:27 mitya-VirtualBox dbus[620]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
май 21 11:58:27 mitya-VirtualBox systemd[1]: Starting Time & Date Service...
май 21 11:58:27 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:58:27+03:00
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/actions/sntp 200 OK
май 21 11:58:27 mitya-VirtualBox uspd.cfg_datetime[32024]: 2019-05-21T11:58:27+03:00
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/events/schdl 200 OK
май 21 11:58:27 mitya-VirtualBox dbus[620]: [system] Successfully activated service 'org.freedesktop.timedate1'
май 21 11:58:27 mitya-VirtualBox systemd[1]: Started Time & Date Service.
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/servers/sntp 200 OK
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/state/time 200 OK
май 21 11:58:27 mitya-VirtualBox uspd.debug[32024]: admin@example.com 127.0.0.1 GET /api/v0.10/settings/time/local 200 OK
@brettcs
Copy link
Contributor
brettcs commented Aug 21, 2021

I just tried to reproduce this but wasn't successful. I used this script to generate a journal entry, show it in journalctl, then show it like the original report:

#!/usr/bin/env python3

import datetime, os, subprocess
from cysystemd.reader import JournalReader, JournalOpenMode

IDENT = 'cysystemd'

subprocess.run([
    'logger', '-t', IDENT, '-p', 'user.debug',
    f"current time is {datetime.datetime.utcnow().isoformat(timespec='seconds')}",
], check=True)
    
jenv = os.environ.copy()
jenv['TZ'] = 'Etc/UTC'
subprocess.run(['journalctl', '--user', '-n', '1', '-t', IDENT],
               check=True, env=jenv)

journal = JournalReader()
journal.open(JournalOpenMode.CURRENT_USER)
journal.seek_tail()
while record := journal.previous():
    if record.data.get('SYSLOG_IDENTIFIER') == IDENT:
        break

print(record.date.isoformat(timespec='seconds'), record.data.get('MESSAGE', ''))

When I run it on my system, the times all match:

% ./journaltimetest.py
…
Aug 21 20:13:14 hostname cysystemd[271838]: current time is 2021-08-21T20:13:14
2021-08-21T20:13:14 current time is 2021-08-21T20:13:14

I noticed that the logs in the original report are apparently setting the system time via NTP a lot, and there's a reference to VirtualBox. With time potentially changing out from underneath the system, I wonder if maybe one of these processes started with a clock that was out of sync or something?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants