New s6 console logging doesn't handle multi-line logs

[shaunco]

This s6-log config doesn't properly handle multi-line logs, which breaks any form of structured log collector (datadog, signoz, etc):

open-balena-api/entry.sh

Line 7 in 104aabe

exec > >(exec s6-log -b p"api[$$]:" 1 || true) 2>&1

So, we end up with logs like this:

api[523]: No webresource handler loaded.
api[523]: (node:531) NOTE: The AWS SDK for JavaScript (v2) is in maintenance mode.
api[523]:  SDK releases are limited to address critical bug fixes and security issues only.
api[523]:
api[523]: Please migrate your code to use AWS SDK for JavaScript (v3).
api[523]: For more information, check the blog post at https://a.co/cUPnyil
api[523]: Successfully executed standard models.
api[523]: Successfully executed migrations model.
api[523]: Successfully executed tasks model.
api[523]: Successfully executed webresource model.
api[523]: Loading application config
api[523]: Successfully executed balena model.
api[523]: Successfully executed v7 model.
api[523]: Successfully executed v6 model.
api[523]: Async migration execution is enabled
api[523]: Creating superuser account...
api[523]: Superuser already exists!
api[523]: Server listening in development mode on port 80

api[523]: node:internal/process/promises:394
api[523]:     triggerUncaughtException(err, true /* fromPromise */);
api[523]:     ^
api[523]:
api[523]: Error [XMLParserError]: Non-whitespace before first tag.
api[523]: Line: 0
api[523]: Column: 1
api[523]: Char: u
api[523]:     at error (/usr/src/app/node_modules/sax/lib/sax.js:667:10)
api[523]:     at strictFail (/usr/src/app/node_modules/sax/lib/sax.js:693:7)
api[523]:     at beginWhiteSpace (/usr/src/app/node_modules/sax/lib/sax.js:967:7)
api[523]:     at SAXParser.write (/usr/src/app/node_modules/sax/lib/sax.js:1019:11)
api[523]:     at exports.Parser.Parser.parseString (/usr/src/app/node_modules/xml2js/lib/parser.js:337:31)
api[523]:     at Parser.parseString (/usr/src/app/node_modules/xml2js/lib/parser.js:5:59)
api[523]:     at NodeXmlParser.parse (/usr/src/app/node_modules/aws-sdk/lib/xml/node_parser.js:31:10)
api[523]:     at Request.extractError (/usr/src/app/node_modules/aws-sdk/lib/services/s3.js:743:39)
api[523]:     at Request.callListeners (/usr/src/app/node_modules/aws-sdk/lib/sequential_executor.js:106:20)
api[523]:     at Request.emit (/usr/src/app/node_modules/aws-sdk/lib/sequential_executor.js:78:10)
api[523]:     at Request.emit (/usr/src/app/node_modules/aws-sdk/lib/request.js:686:14)
api[523]:     at Request.transition (/usr/src/app/node_modules/aws-sdk/lib/request.js:22:10)
api[523]:     at AcceptorStateMachine.runTo (/usr/src/app/node_modules/aws-sdk/lib/state_machine.js:14:12)
api[523]:     at /usr/src/app/node_modules/aws-sdk/lib/state_machine.js:26:10
api[523]:     at Request.<anonymous> (/usr/src/app/node_modules/aws-sdk/lib/request.js:38:9)
api[523]:     at Request.<anonymous> (/usr/src/app/node_modules/aws-sdk/lib/request.js:688:12) {
api[523]:   code: 'XMLParserError',
api[523]:   retryable: true,
api[523]:   time: 2025-09-10T17:57:17.788Z,
api[523]:   statusCode: 503
api[523]: }

api[523]:
api[523]: Node.js v24.7.0
api[523]: Program node --enable-source-maps --loader @swc-node/register/esm-register index.js exited with code 1
api[523]:
s6-rc: info: service legacy-services: stopping

where everything in that middle code block was actually a single line of log output.

Unfortunately s6-log is line oriented, so the exec pipe has to feed something else like jq or awk first:

1. jq

   # stdout -> jq-> s6-log -> stdout
   exec > >(jq -R -c --arg app "api" --arg pid "$$" \
     '{ts:(now|todateiso8601), app:$app, pid:($pid|tonumber), stream:"stdout", msg:.}' \
     | s6-log -b -l 0 1) \
     2> >(jq -R -c --arg app "api" --arg pid "$$" \
     '{ts:(now|todateiso8601), app:$app, pid:($pid|tonumber), stream:"stderr", msg:.}' \
     | s6-log -b -l 0 1)

2. awk

   json_filter() {
     awk -v app="$1" -v pid="$$" -v stream="$2" '
       function esc(s){ gsub(/\\/,"\\\\",s); gsub(/"/,"\\\"",s);
                        gsub(/\r/,"",s); gsub(/\t/,"\\t",s); gsub(/\n/,"\\n",s); return s }
       { line=$0; printf("{\"app\":\"%s\",\"pid\":%d,\"stream\":\"%s\",\"msg\":\"%s\"}\n",
                         app, pid, stream, esc(line)); fflush() }'
   }
   exec > >(json_filter api stdout | s6-log -b -l 0 1) \
       2> >(json_filter api stderr | s6-log -b -l 0 1)

The other alternative is to use something like Pino in open-balena-api, but that would require all the various console.log and other logging calls to be reworked into a pino logger ... great long term, but the above is an easier fix. Additionally, the above works for the -s3 and -vpn projects as well that can't move to something line Pino.

(cc @klutchell )

[klutchell]

@shaunco the previous implementation of rsyslog wasn't producing JSON output, so I would hesitate to switch to that now as it's actually less human-readable without a parser.

The current prefix (service[pid]: msg) is what rsyslog was producing only there was also a timestamp, but we decided the timestamp was redundant since container loggers provide those anyway.

Though we should definitely try to fix the grouping of single messages to avoid the extra prefix on newlines. How do you suggest a shell process detect when a message ends if not newlines? The functions above don't actually work, they just buffer forever until the container is stopped.

[klutchell]

I've been testing rsyslog which we used to use to send logs to logentries, and we had combined it with systemd-journald.

systemd-journald doesn't have any grouping of multi-line messages apparently, and rsyslog has 3 built-in modes for splitting with mixed results, unless we make a regex that is app-specific.

Were these logs previously parsed correctly in a collector you were using? I'm wondering how this ever worked before if we are going to try and match that behaviour, let alone improve upon it.

[shaunco]

Under the old systemd/journald base container, I had slapped together a pretty ugly sidecar that made use of a lifecycle start entry to inject helpers and shared volume in our deployment yml:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: ob-vpn
  labels:
    app.kubernetes.io/name: ob-vpn
    app.kubernetes.io/component: vpn
spec:
  selector:
    matchLabels:
      app.kubernetes.io/name: ob-vpn
      app.kubernetes.io/component: vpn
  replicas: 1
  revisionHistoryLimit: 0
  template:
    spec:
      containers:
        - name: ob-vpn
          image: balena/open-balena-api:v43.0.7
          imagePullPolicy: IfNotPresent
          ports:
            - name: tcp-vpn
              containerPort: 443
            - name: tcp-tunnel
              containerPort: 3128
            - name: http-api
              containerPort: 80
          securityContext:
            privileged: true
            capabilities:
              add: ["SYS_ADMIN", "SYS_RESOURCE", "NET_ADMIN"]
          envFrom:
            - secretRef:
                name: ob-vpn-secrets
          resources:
            {{- toYaml .Values.obVpn.resources | nindent 12 }}
          env:
            {{ removed }}
          volumeMounts:
            - mountPath: /run
              name: run
            - mountPath: /sys/fs/cgroup
              name: cgroup
            - name: log-volume
              mountPath: /var/log/sidecar
          lifecycle:
            postStart:
              exec:
                command:
                  - /bin/sh
                  - -c
                  - |
                    echo '#!/bin/bash
                    LOG_FILE="/var/log/sidecar/syslog.log"
                    MAX_SIZE=2097152
                    rotate_log() {
                        if [ -f "$LOG_FILE" ]; then
                            SIZE=$(stat -c%s "$LOG_FILE")
                            if [ $SIZE -ge $MAX_SIZE ]; then
                                mv "$LOG_FILE" "${LOG_FILE}.1"
                                touch "$LOG_FILE"
                                chmod 640 "$LOG_FILE"
                            fi
                        fi
                    }
                    while IFS= read -r line; do
                        echo "$line" >> "$LOG_FILE"
                        rotate_log
                    done' > /var/log/sidecar/rotate.sh
                    chmod +x /var/log/sidecar/rotate.sh
                    echo '
                      module(load="imjournal" RateLimit.Interval="0" RateLimit.Burst="0")
                      module(load="mmjsonparse")
                      module(load="omprog")
                      if ($syslogfacility-text == "kern") then {
                          stop
                      }
                      template(name="jsonFormat" type="list") {
                          constant(value="{")
                          constant(value="\"timestamp\":\"")     property(name="timereported" dateFormat="rfc3339")
                          constant(value="\",\"host\":\"")       property(name="hostname")
                          constant(value="\",\"severity\":\"")   property(name="syslogseverity-text")
                          constant(value="\",\"facility\":\"")   property(name="syslogfacility-text")
                          constant(value="\",\"message\":\"")    property(name="msg" format="json")
                          constant(value="\"}\n")
                      }
                      *.* action(type="omfile" file="/var/log/sidecar/syslog.log" template="jsonFormat")                 
                      *.* action(type="omprog" binary="/var/log/sidecar/rotate.sh")
                    ' > /etc/rsyslog.d/00-log-to-stdout.conf
                    systemctl restart rsyslog || true
        - name: log-sidecar
          image: busybox
          args: [/bin/sh, -c, "tail -n+1 -F /var/log/sidecar/syslog.log"]
          volumeMounts:
            - name: log-volume
              mountPath: /var/log/sidecar
      volumes:
        - name: run
          emptyDir:
            medium: Memory
        - name: cgroup
          emptyDir:
            medium: Memory
        - name: log-volume
          emptyDir: {}

This used an rsyslog.d conf to write json out to a log file on a shared volume, and then the sidecar tailed that log file... and we had datadog only pull logs from the sidecar. The json properly encapsulated multi-line logs.

I much prefer the new s6 init, but my old rsyslog patch/sidecare above obviously no longer works.

[shaunco]

The functions above don't actually work, they just buffer forever until the container is stopped.

Doh! I had tested them standalone instead of in an s6 init container.

the previous implementation of rsyslog wasn't producing JSON output, so I would hesitate to switch to that now as it's actually less human-readable without a parser

Fair, although an ENV option that would allow for JSON to be optionally enabled would be really nice ... but doesn't work for s3 and vpn containers, since you could use Pino in the api code, but are just running third party tools in vpn/s3.

systemd-journald doesn't have any grouping of multi-line messages

Good point. This is why we always land back on JSON for structured logging output when a collector is involved. Going back to the ENV option (LOG_MODE - default to PLAIN, but have JSON as an option) means that the choice of human readability or machine readability is up to the user.