T4777: Ability to get logs in machine-readable format

[sever-sever]

Change Summary

Ability to get logs in JSON format
Possible filter by unit. Options for count lines,
UTC time, facility or logs since boot

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Code style update (formatting, renaming)
• Refactoring (no functional changes)
• Migration from an old Vyatta component to vyos-1x, please link to related PR inside obsoleted component
• Other (please describe):

Related Task(s)

• https://phabricator.vyos.net/T4777

Component(s) name

log

Proposed changes

How to test

vyos@r14:~$ /usr/libexec/vyos/op_mode/log.py show --help
usage: log.py show [-h] [--raw] [--boot] [--count COUNT] [--facility FACILITY] [--reverse] [--utc] [--unit UNIT]

optional arguments:
  -h, --help           show this help message and exit
  --raw
  --boot
  --count COUNT
  --facility FACILITY
  --reverse
  --utc
  --unit UNIT
vyos@r14:~$ 

vyos@r14:~$ /usr/libexec/vyos/op_mode/log.py show --unit isc-dhcp-server --count 2
Nov 01 19:14:55 dhcpd[1912]: DHCPREQUEST for 192.0.2.59 from 12:df:c5:d4:f3:d1 (r1) via eth1
Nov 01 19:14:55 dhcpd[1912]: DHCPACK on 192.0.2.59 to 12:df:c5:d4:f3:d1 (r1) via eth1
vyos@r14:~$ 

Raw format:

vyos@r14:~$ /usr/libexec/vyos/op_mode/log.py show --unit isc-dhcp-server --count 2 --raw
[
    {
        "syslog_timestamp": "Nov  1 19:15:26 ",
        "message": "DHCPREQUEST for 192.0.2.59 from 12:df:c5:d4:f3:d1 (r1) via eth1",
        "cursor": "s=6da0a574521e4418b79d7461441efa2c;i=1dfe;b=30118e9a44914a35a10bf01f17e8dd2d;m=6237609f7;t=5ec6bdec30d02;x=b5215f103838ec34",
        "source_realtime_timestamp": "1667322926533534",
        "systemd_invocation_id": "6c0d1f1679184edba692e9a948650692",
        "syslog_pid": "1912",
        "systemd_slice": "system.slice",
        "systemd_unit": "isc-dhcp-server.service",
        "realtime_timestamp": "1667322926533890",
        "boot_id": "30118e9a44914a35a10bf01f17e8dd2d",
        "pid": "1912",
        "syslog_facility": "3",
        "hostname": "r14",
        "cap_effective": "0",
        "syslog_identifier": "dhcpd",
        "gid": "104",
        "exe": "/usr/sbin/dhcpd",
        "priority": "6",
        "systemd_cgroup": "/system.slice/isc-dhcp-server.service",
        "machine_id": "4d6f4d291ae8446f8d2b3decd9da64c7",
        "comm": "dhcpd",
        "transport": "syslog",
        "uid": "126",
        "monotonic_timestamp": "26364742135",
        "cmdline": "/usr/sbin/dhcpd -4 -q -user dhcpd -group vyattacfg -pf /run/dhcp-server/dhcpd.pid -cf /run/dhcp-server/dhcpd.conf -lf /config/dhcpd.leases"
    },
    {
        "hostname": "r14",
        "comm": "dhcpd",
        "gid": "104",
        "monotonic_timestamp": "26364742257",
        "message": "DHCPACK on 192.0.2.59 to 12:df:c5:d4:f3:d1 (r1) via eth1",
        "uid": "126",
        "realtime_timestamp": "1667322926534011",
        "systemd_slice": "system.slice",
        "syslog_timestamp": "Nov  1 19:15:26 ",
        "syslog_pid": "1912",
        "pid": "1912",
        "machine_id": "4d6f4d291ae8446f8d2b3decd9da64c7",
        "cap_effective": "0",
        "syslog_facility": "3",
        "priority": "6",
        "cmdline": "/usr/sbin/dhcpd -4 -q -user dhcpd -group vyattacfg -pf /run/dhcp-server/dhcpd.pid -cf /run/dhcp-server/dhcpd.conf -lf /config/dhcpd.leases",
        "syslog_identifier": "dhcpd",
        "source_realtime_timestamp": "1667322926533547",
        "boot_id": "30118e9a44914a35a10bf01f17e8dd2d",
        "systemd_cgroup": "/system.slice/isc-dhcp-server.service",
        "cursor": "s=6da0a574521e4418b79d7461441efa2c;i=1dff;b=30118e9a44914a35a10bf01f17e8dd2d;m=623760a71;t=5ec6bdec30d7b;x=f68b28ff98f1b8aa",
        "systemd_invocation_id": "6c0d1f1679184edba692e9a948650692",
        "exe": "/usr/sbin/dhcpd",
        "systemd_unit": "isc-dhcp-server.service",
        "transport": "syslog"
    }
]
vyos@r14:~$ 

Request via API

vyos@r14:~$ curl -k --raw 'https://localhost/graphql'  -H 'Content-Type: application/json'  -d '{"query":" {\n ShowLog (data: {key: \"foo\", count: 1}) {\n  success\n  errors\n  data {\n    result\n  }\n}\n}\n"}'

{"data":{"ShowLog":{"success":true,"errors":null,"data":{"result":[{"_SYSTEMD_UNIT":"isc-dhcp-server.service","_GID":"104","_MACHINE_ID":"4d6f4d291ae8446f8d2b3decd9da64c7","SYSLOG_TIMESTAMP":"Nov  1 19:15:49 ","__REALTIME_TIMESTAMP":"1667322949841153","__MONOTONIC_TIMESTAMP":"26388049398","_SYSTEMD_CGROUP":"/system.slice/isc-dhcp-server.service","SYSLOG_FACILITY":"3","_COMM":"dhcpd","_TRANSPORT":"syslog","PRIORITY":"6","_SYSTEMD_INVOCATION_ID":"6c0d1f1679184edba692e9a948650692","_HOSTNAME":"r14","_CMDLINE":"/usr/sbin/dhcpd -4 -q -user dhcpd -group vyattacfg -pf /run/dhcp-server/dhcpd.pid -cf /run/dhcp-server/dhcpd.conf -lf /config/dhcpd.leases","_PID":"1912","SYSLOG_PID":"1912","_CAP_EFFECTIVE":"0","__CURSOR":"s=6da0a574521e4418b79d7461441efa2c;i=1e10;b=30118e9a44914a35a10bf01f17e8dd2d;m=624d9adf6;t=5ec6be026b101;x=f5199e636168cd84","_SOURCE_REALTIME_TIMESTAMP":"1667322949840817","SYSLOG_IDENTIFIER":"dhcpd","_SYSTEMD_SLICE":"system.slice","_BOOT_ID":"30118e9a44914a35a10bf01f17e8dd2d","_EXE":"/usr/sbin/dhcpd","MESSAGE":"DHCPACK on 192.0.2.59 to 12:df:c5:d4:f3:d1 (r1) via eth1","_UID":"126"}]}}}}vyos@r14:~$ 
vyos@r14:~$

Checklist:

• I have read the CONTRIBUTING document
• I have linked this PR to one or more Phabricator Task(s)
• I have run the components SMOKETESTS if applicable
• My commit headlines contain a valid Task id
• My change requires a change to the documentation
• I have updated the documentation accordingly

[dmbaturin]

I'm not exactly against this implementation, but I wonder if using some journalctl bindings could be a faster and a cleaner solution.

The systemd has project has official Python bindings that provide journal reading functionality, see https://github.com/systemd/python-systemd

I think we should investigate it.

[sever-sever]

I'm not exactly against this implementation, but I wonder if using some journalctl bindings could be a faster and cleaner solution.

@dmbaturin for my opinion binary journalctl should be faster than python-systemd, but I didn't test it

[sever-sever]

In the simple example python-systemd 10 times slower than journalctl with log.py script

root@r14:/home/vyos# time /usr/libexec/vyos/op_mode/log.py show --raw &> /dev/null

real	0m0.142s
user	0m0.123s
sys	0m0.018s
root@r14:/home/vyos# 
root@r14:/home/vyos# time ./jlog.py &> /dev/null

real	0m1.206s
user	0m1.164s
sys	0m0.040s
root@r14:/home/vyos# 

jlog.py:

#!/usr/bin/env python3

def show():
    from systemd import journal
    output = journal.Reader()
    return [line for line in output]

print(show())