pveproxy / systemd journald / perl buffering

Because I was debugging — what later turned out to be — an application firewall that was messing with my connections to Proxmox pveproxy on port 8006, I wanted more debug logs. Telling pveproxy to give me more info gave me a bit of a hard time.

Connections from a remote peer would get disconnected, and it initially looked like pveproxy was to blame.

Step one: get more info from pveproxy.

pveproxy has a pveproxy start --debug=1 mode. I added that to the systemd config using an /etc/systemd/system/pveproxy.service.d/override.conf file:

[Service]
# Wipe the original ExecStart= first.
ExecStart=
# Enable debugging.
ExecStart=/usr/bin/pveproxy start --debug=1

Alas, this refused to start, because --debug runs in the foreground. Add Type=simple:

[Service]
# pveproxy --debug stays in the foreground.
Type=simple
# Wipe the original ExecStart= first.
ExecStart=
# Enable debugging.
ExecStart=/usr/bin/pveproxy start --debug=1

Okay. The pveproxy service now started successfully. But no extra logging appeared. Except.. after a restart there suddenly were logs.

I've seen this before. Output buffering? Yes.

Output buffering is an optimization where output isn't flushed after every line, but first when a larger buffer is full. Useful if you're writing lots of output. Terrible if it means that log output is saved for later. I want to see my debug output live.

For Python, there is the PYTHONUNBUFFERED=1 environment variable or the python -u flag. pveproxy is a Perl application however. ChatGPT will gladly hallucinate a PERL_UNBUFFERED=1, but that doesn't exist. You need this code instead:

select STDERR;$|=1;select STDOUT;$|=1;

Doing file descriptor modifications, just before program start, with stdbuf(1) doesn't fix things. And I did not want to install Expect just for the unbuffer(1) application.

Is there another way to inject the $|=1; without modifying the existing Perl script?

I settled for the following. (This should actually be possible without the sh -c, but systemd escaping did not agree with me.)

[Service]
# pveproxy --debug stays in the foreground.
Type=simple
# Wipe the original ExecStart= first.
ExecStart=
# Enable debugging, with PERL_UNBUFFERED=1.
#ExecStart=/usr/bin/pveproxy start --debug=1
ExecStart=/bin/sh -c 'exec /usr/bin/perl -Te '\''select STDERR;$|=1;select STDOUT;$|=1;do "/usr/bin/pveproxy" or die "Could not run: $@ $!";'\'' -- start --debug=1'

Now pveproxy starts and the debug output appears in journald as soon as it's written.

For the record, the debug output turned out to be useless. Instead, tcpdump revealed that traffic from the client would contain data (a [P], for the TLS ClientHello), but when looking at the traffic on the receiving host, I would see a [R] (reset). The TCP traffic had been altered to tear down the connection in the outbound direction. Apparently there was an application firewall in the middle, sniffing that port 8006 traffic, and deciding that TLS was dangerous on non-443 ports. *Sigh*