capture journald properties with rsyslog

Question

I am struggling on how to capture systemd-journald properties into rsyslog files.

My setup

• ubuntu inside docker on arm (raspberrypi): FROM arm64v8/ubuntu:20.04

• docker command (all subsequent actions taken inside running docker container)

   $ docker run --privileged -ti --cap-add SYS_ADMIN --security-opt seccomp=unconfined --cgroup-parent=docker.slice --cgroupns private --tmpfs /tmp --tmpfs /run --tmpfs /run/lock systemd:origin
  

• rsyslog under $ sytemctl status rsyslog

   ● rsyslog.service - System Logging Service
        Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor prese>
        Active: active (running)
   ...
   [origin software="rsyslogd" swVersion="8.2001.0" x-pid="39758" x-info="https://www.rsyslog.com"] start
   ...
  

My plan

Having a small c program to put some information into journal:

    #include <systemd/sd-journal.h>
    #include <stdio.h>
    #include <unistd.h>

    int main(int arcg, char** args) {
      char buffer [50];

      sprintf (buffer, "%lu", (unsigned long)getpid());

      printf("writing to journal\n");

      sd_journal_print(LOG_WARNING, "%s", "a little journal test message");
      sd_journal_send("MESSAGE=%s", "there shoud be a text", "SYSLOG_PID=%s", buffer, "PRIORITY=%i", LOG_ERR, "DOCUMENTATION=%s", "any doc link", "MESSAGE_ID=%s", "e5e4132e441541f89bca0cc3e7be3381", "MEAS_VAL=%d", 1394, NULL);

      return 0;
    }

Compile it: $ gcc joutest.c -lsystemd -o jt

Execute it: $ ./jt

This results inside the journal as $ journalctl -r -o json-pretty:

    {
      "_GID" : "0",
      "MESSAGE" : "there shoud be a text",
      "_HOSTNAME" : "f1aad951c039",
      "SYSLOG_IDENTIFIER" : "jt",
      "_TRANSPORT" : "journal",
      "CODE_FILE" : "joutest.c",
      "DOCUMENTATION" : "any doc link",
      "_BOOT_ID" : "06a36b314cee462591c65a2703c8b2ad",
      "CODE_LINE" : "14",
      "MESSAGE_ID" : "e5e4132e441541f89bca0cc3e7be3381",
      "_CAP_EFFECTIVE" : "3fffffffff",
      "__REALTIME_TIMESTAMP" : "1669373862349599",
      "_SYSTEMD_UNIT" : "init.scope",
      "CODE_FUNC" : "main",
      "_MACHINE_ID" : "5aba31746bf244bba6081297fe061445",
      "SYSLOG_PID" : "39740",
      "PRIORITY" : "3",
      "_COMM" : "jt",
      "_SYSTEMD_SLICE" : "-.slice",
      "MEAS_VAL" : "1394",
      "__MONOTONIC_TIMESTAMP" : "390853282189",
      "_PID" : "39740",
      "_SOURCE_REALTIME_TIMESTAMP" : "1669373862336503",
      "_UID" : "0",
      "_SYSTEMD_CGROUP" : "/init.scope",
      "__CURSOR" : "s=63a46a30bbbb4b8c9288a9b12c622b37;i=6cb;b=06a36b314cee46>
    }

Now as a test, extracting all properties from that journal entry via rsyslog; property in the jargon of rsyslog in principle is the name of a key in the formatted json entry. But if a property (or key name) matches, the whole dictionary item (key and value) shall be captured

To start with this, I've configured rsyslog as:

    module(load="imjournal")
    module(load="mmjsonparse")

    action(type="mmjsonparse")

    if $programname == 'jt' and $syslogseverity == 3 then
      action(type="omfile" file="/var/log/jt_err.log" template="RSYSLOG_DebugFormat")

This config is located in /etc/rsyslog.d/filter.conf and gets automatically included by /etc/rsyslog.conf:

    # /etc/rsyslog.conf configuration file for rsyslog
    #
    # For more information install rsyslog-doc and see
    # /usr/share/doc/rsyslog-doc/html/configuration/index.html
    #
    # Default logging rules can be found in /etc/rsyslog.d/50-default.conf
    
    
    #################
    #### MODULES ####
    #################
    
    #module(load="imuxsock") # provides support for local system logging
    #module(load="immark")  # provides --MARK-- message capability
    
    # provides UDP syslog reception
    #module(load="imudp")
    #input(type="imudp" port="514")
    
    # provides TCP syslog reception
    #module(load="imtcp")
    #input(type="imtcp" port="514")
    
    # provides kernel logging support and enable non-kernel klog messages
    module(load="imklog" permitnonkernelfacility="on")
    
    ###########################
    #### GLOBAL DIRECTIVES ####
    ###########################
    
    #
    # Use traditional timestamp format.
    # To enable high precision timestamps, comment out the following line.
    #
    $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
    
    # Filter duplicated messages
    $RepeatedMsgReduction on
    
    #
    # Set the default permissions for all log files.
    #
    $FileOwner syslog
    $FileGroup adm
    $FileCreateMode 0640
    $DirCreateMode 0755
    $Umask 0022
    $PrivDropToUser syslog
    $PrivDropToGroup syslog
    
    #
    # Where to place spool and state files
    #
    $WorkDirectory /var/spool/rsyslog
    
    #
    # Include all config files in /etc/rsyslog.d/
    #
    $IncludeConfig /etc/rsyslog.d/*.conf

Applied this config: $ systemctl restart rsyslog

Which results in the following: $ cat /var/log/jt_err.log

    Debug line with all properties:
    FROMHOST: 'f1aad951c039', fromhost-ip: '127.0.0.1', HOSTNAME: 
    'f1aad951c039', PRI: 11,
    syslogtag 'jt[39765]:', programname: 'jt', APP-NAME: 'jt', PROCID: 
    '39765', MSGID: '-',
    TIMESTAMP: 'Nov 25 11:47:50', STRUCTURED-DATA: '-',
    msg: ' there shoud be a text'
    escaped msg: ' there shoud be a text'
    inputname: imuxsock rawmsg: '<11>Nov 25 11:47:50 jt[39765]: there 
    shoud be a text'
    $!:{ "msg": "there shoud be a text" }
    $.:
    $/:

My problem

Looking on the resulting rsyslog, I miss a majority, if not all, of items originating from the journal entry. There is really no property (key) matching. Shouldn't be there all properties matched as it is a debug output?

Specifically I am concentrating on my custom property, MEAS_VAL, it is not there. The only property which occurs is "msg", which by the way is questionable whether it is a match of the journal, since the originating property name attached to the resulting content "there shoud be a text" is MESSAGE

So it feels that I don't hit the whole journal capturing mechanism at all, why?

Can we be sure that imjournal gets loaded properly?

I would say yes because of systemd's startup messages:

    Nov 28 16:27:38 f1aad951c039 rsyslogd[144703]: imjournal: Journal indicates no msgs when positioned at head.  [v8.2212.0.master try https://www.rsyslog.com/e/0 ]
    Nov 28 16:27:38 f1aad951c039 rsyslogd[144703]: imjournal: journal files changed, reloading...  [v8.2212.0.master try https://www.rsyslog.com/e/0 ]
    Nov 28 16:27:38 f1aad951c039 rsyslogd[144703]: imjournal: Journal indicates no msgs when positioned at head.  [v8.2212.0.master try https://www.rsyslog.com/e/0 ]

Edit 2022-11-29

Meanwhile I've compiled my own version 8.2212.0.master. But the phenomenon persists.

Answer 1

You're missing most items originating from the journal, because both templates RSYSLOG_DebugFormat and RSYSLOG_TraditionalFileFormat do not have the needed properties (See Reserved template names). RSYSLOG_DebugFormat, however, includes atleast some fields, e.g. procid, msgid and structured-data - which can be seen in the output you've provided.

This means, that if you want to include all the fields, you'll have to create your own template.

The journal fields are stored in key-value pairs. The imjournal module is able to parse these key-value pairs and generate the jsonf property, which then can be used to access fields of the log message as if they were fields in a JSON object.

# load imjournal module
module(load="imjournal")

# specify journal as input source
input(type="imjournal")

template(name="journalTemplate" type="list") {
    property(name="timestamp" dateFormat="rfc3339")
    constant(value=" ")
    property(name="hostname")
    constant(value=" ")
    property(name="syslogtag")
    constant(value=": {")
    property(name="jsonf")
    constant(value="}")
}

if $programname == 'jt' and $syslogseverity == 3 then {
  action(type="omfile" file="/var/log/jt_err.log" template="journalTemplate")
  stop
}

The output of the provided log would then look something like the following:

YYYY-MM-DDTHH:mm:ss myHostname syslogtag: {"_GID" : "0", "MESSAGE" : "there shoud be a text", ... }

---

As seen in the log above, the output of the provided properties will be in JSON. By using the json property parser this can be prevented, as the output can be tailored as desired. If this is used, however, each property must be defined specifically.

template(name="journalTemplate" type="list") {
    property(name="timestamp" dateFormat="rfc3339")
    constant(value=" ")
    property(name="hostname")
    constant(value=" ")
    property(name="syslogtag")
    constant(value=": _GID=")
    property(name="$._GID" format="json")
    constant(value=" MESSAGE=")
    property(name="$.MESSAGE" format="json")
    constant(value=" _HOSTNAME=")
    property(name="$._HOSTNAME" format="json")
    ...
}