Format log messages for journald consumption
Compare changes
+ 1
− 1
In this MR I reformat our log output so it's better parsable by the journal. The big change is that I replaced the literal priority indicators ('ERROR', 'WARNING', etc.) with ones following the scheme used by the kernel's printk() enclosed in angled brackets. When those are put onto stdout (or stderr) from within a systemd service they are parsed by systemd (in its default configuration). This gives us the advantage that we can filter on priority, e.g.:
; sudo journalctl -u runSCdaq -f
-- Logs begin at Wed 2018-10-17 13:59:16 CEST. --
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: config::print: key scone_board value kcu1500_ugmt
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: config::print: key scone_host value localhost
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: config::print: key scone_port value 8080
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: config::print: key threads value 8
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: config::print: key verbosity value 0
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Configuration loaded
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: Configuration translated into:
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: MAX_BYTES_PER_INPUT_SLICE: 1048576
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: TOTAL_SLICES: 1000
Sep 24 18:33:25 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: Created input filter and allocated at 0x7f8258ae00c0
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: WZDmaInputFilter::WZDmaInputFilter: Created WZ DMA input filter
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: WZDmaInputFilter::~WZDmaInputFilter: Destroyed WZ DMA input filter
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::~InputFilter: Destroy input filter and delete at 0x7f8258ae00c0
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::~InputFilter: Input operator performed 0 read
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Terminating the internal TCP server.
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Internal TCP server is terminated.
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: Resetting the board...
Sep 24 18:33:27 cmd-scouting-ctrlhub runSCdaq.sh[17196]: ok
Sep 24 18:33:27 cmd-scouting-ctrlhub runSCdaq.sh[17196]: Clearing caches...
Sep 24 18:33:27 cmd-scouting-ctrlhub sudo[17264]: scouter : TTY=unknown ; PWD=/opt/scdaq/src ; USER=root ; COMMAND=/bin/tee /proc/sys/vm/drop_caches
Sep 24 18:33:28 cmd-scouting-ctrlhub runSCdaq.sh[17196]: Waiting 30 seconds...
Sep 24 18:33:28 cmd-scouting-ctrlhub runSCdaq.sh[17196]: 30...
Sep 24 18:33:43 cmd-scouting-ctrlhub runSCdaq.sh[17196]: 15...
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: Starting scdaq...
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: scdaq started with conffile: /etc/scdaq/scdaq.conf
[snip]
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Configuration loaded
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: Configuration translated into:
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: MAX_BYTES_PER_INPUT_SLICE: 1048576
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: TOTAL_SLICES: 1000
Sep 24 18:33:58 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::InputFilter: Created input filter and allocated at 0x7f965f27f0c0
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: WZDmaInputFilter::WZDmaInputFilter: Created WZ DMA input filter
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: WZDmaInputFilter::~WZDmaInputFilter: Destroyed WZ DMA input filter
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::~InputFilter: Destroy input filter and delete at 0x7f965f27f0c0
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: InputFilter::~InputFilter: Input operator performed 0 read
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Terminating the internal TCP server.vs.
; sudo journalctl -u runSCdaq -f -p err
-- Logs begin at Wed 2018-10-17 13:59:16 CEST. --
Sep 24 18:31:49 cmd-scouting-ctrlhub runSCdaq.sh[15307]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:32:23 cmd-scouting-ctrlhub runSCdaq.sh[15307]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:32:48 cmd-scouting-ctrlhub systemd[1]: Can't convert PID files /var/log/scdaq/pid O_PATH file descriptor to proper file descriptor: Is a directory
Sep 24 18:32:53 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:33:26 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:33:59 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:34:32 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:35:05 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:35:38 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"
Sep 24 18:36:11 cmd-scouting-ctrlhub runSCdaq.sh[17196]: main: Error in pipelines. Error text is: "map::at"(Which just now made me find a bug in our service file.. ) And error messages are also highlighted.
Additionally I removed the logger at output as it doesn't appear to be necessary anymore. I also renamed the wrapper script to make the name in the log a bit clearer.
Belongs to #19 (closed).