Reading systemd journal from Python script

Question

I am trying to emulate this shell command in Python using the systemd libraries http://www.freedesktop.org/software/systemd/python-systemd/journal.html

I am actually trying to emulate this command but within Python.

journalctl --since=-5m --no-pager

I have seen others do this in Python by calling the journal executable but that is a pretty bad way of doing it.

I wrote this simple script based on the documentation linked above

import select
from systemd import journal

j = journal.Reader()
j.log_level(journal.LOG_INFO)
# j.add_match(_SYSTEMD_UNIT="systemd-udevd.service")

j.seek_tail()
j.get_next()

while j.get_next():
    for entry in j:
        if entry['MESSAGE'] != "":
            print(str(entry['__REALTIME_TIMESTAMP'] )+ ' ' + entry['MESSAGE'])

There are a few issues here

1. the log seems to start from about 5 days ago which means the seek_tail did not appear to work.
2. I am getting a lot of junk in here is there a specific filter I should use to match the data I get from journalctl command given at the beginning of the question?

Ideally longer term I want to just be following this journal based on a set of filters/matches to emulate the command 'journalctl -f' but I just need to resolve this issue first. I want to end up with something like this but it doesnt work either.

import select
from systemd import journal

j = journal.Reader()
j.log_level(journal.LOG_INFO)

# j.add_match(_SYSTEMD_UNIT="systemd-udevd.service")
j.seek_tail()

p = select.poll()
p.register(j, j.get_events())
while p.poll():

    while j.get_next():
        for entry in j:
            if entry['MESSAGE'] != "":
                print(str(entry['__REALTIME_TIMESTAMP'] )+ ' ' + entry['MESSAGE'])

Whorton

Answer 1

I am also working on similar python module.

According to the following links, we have to call sd_journal_previous (In python systemd module, that is journal.Reader().get_previous()).

http://www.freedesktop.org/software/systemd/man/sd_journal_seek_tail.html

https://bugs.freedesktop.org/show_bug.cgi?id=64614

In addition, your example code will consume 80 - 100% CPU load, because the state of reader remains "readable" even after get an entry, which results in too many poll().

According to the following link, it seems we have to call sd_journal_process (In python systemd module, that is journal.Reader().process()) after each poll(), in order to reset the readable state of the file descriptor.

http://www.freedesktop.org/software/systemd/man/sd_journal_get_events.html

In conclusion, your example code would be:

import select
from systemd import journal

j = journal.Reader()
j.log_level(journal.LOG_INFO)

# j.add_match(_SYSTEMD_UNIT="systemd-udevd.service")
j.seek_tail()
j.get_previous()
# j.get_next() # it seems this is not necessary.

p = select.poll()
p.register(j, j.get_events())

while p.poll():
    if j.process() != journal.APPEND:
        continue

    # Your example code has too many get_next() (i.e, "while j.get_next()" and "for event in j") which cause skipping entry.
    # Since each iteration of a journal.Reader() object is equal to "get_next()", just do simple iteration.
    for entry in j:
        if entry['MESSAGE'] != "":
            print(str(entry['__REALTIME_TIMESTAMP'] )+ ' ' + entry['MESSAGE'])

Disturbance

Thats is excellent thanks for that it appears to work. I did suspect that maybe the seek_tail followed by a get_events might cause it to loop back to the beginning. I stupidly never thought to try the get_previous then get_next though. Now to mess around with the loglevel as it appears there is more information in the command journalctl -f than when using loglevel.INFO – Whorton

even loglevel.DEBUG shows less than the command 'journalctl -f' things such as starting and stopping services do not appear to be caught by the python script. – Whorton

Nevermind I was not running the script as root. DUH!!! Thankyou for you assistance with this its working perfectly now. – Whorton

I found it seems "j.get_next()" (after j.get_previous()) is not necessary. – Disturbance

There is a method reliable_fd(). Whether that needs to be called before polling? Well, I don't know under what circumstances it could be False. When I called it it returned True. Maybe it does not work on non-persistent journals? – Shanda

Everything works fine except for the first time on calling j.process() after the first event appeared. Here the event ID is journal.INVALIDATE instead of journal.APPEND. So the first event will not be printed because continue is called. Just the next time the two first events are being printed after which everything works fine and as expected. – Floriculture

Answer 2

The previous answer works and the hint about calling get_next() after seek_tail() is indeed essential.

An easier way would be (but obviously the previous version using polling is more flexible in bigger apps)

import systemd.journal

def main():
  j = systemd.journal.Reader()
  j.seek_tail()
  j.get_previous()
  while True:
    event = j.wait(-1)
    if event == systemd.journal.APPEND:
      for entry in j:
         print entry['MESSAGE']

if __name__ == '__main__':
  main()

If one wants to watch what is going on in detail the following version supporting debug output might be helpful (calling it with some argument(s) will turn that on)

import sys
import systemd.journal

def main(debug):
  j = systemd.journal.Reader()
  j.seek_tail()
  j.get_previous()
  while True:
    event = j.wait(-1)
    if event == systemd.journal.APPEND:
      for entry in j:
         print entry['MESSAGE']
    elif debug and event == systemd.journal.NOP:
      print "DEBUG: NOP"
    elif debug and event == systemd.journal.INVALIDATE:
      print "DEBUG: INVALIDATE"
    elif debug:
      raise ValueError, event   

if __name__ == '__main__':
  main(len(sys.argv) > 1)

For me it results always in one INVALIDATE at the beginning. Not sure what that really means. Having something that is used as iterator being invalidated sounds to me that I might have recreate/reopen/refresh it somehow. But at least during my basic testing the code above just works. Not sure whether there could be any race conditions. Actually I would have difficulties to explain how that code is free of races.

Shanda

Do not drop events with INVALIDATE. It's just a flag which tells the client to clear/refresh its display, as opposed to appending new messages. – Eatable

@Eatable Can you explain what you mean by a.) the client b.) clear refresh its display? All previously shown events are invalid? In what context would that happen? Haven't used it for a while, but in my answer above, INVALIDATE came always and only as the first event. So in that case there would not be really to clear/refresh. Unless the program still showed something from a different machine or a previous boot, but that would be just stupid implementation to mix input from different sources. A new source does not need to tell me, forget about previous ones. – Shanda

Yes, as far as I understood, clear all events: "If SD_JOURNAL_INVALIDATE, journal files were added or removed (possibly due to rotation). In the latter event, live-view UIs should probably refresh their entire display", see freedesktop.org/software/systemd/man/… – Eatable

One thing I stumbled over. In event = j.wait(-1), event is an integer corresponding to a state change. I first thought it contains an event, aka a journald log line. It's probably less confusing to think of event as state_change. – Darrow