Allow systemd-journal-remote to spawn http(s) server for multiple ports

[HaanJde]

systemd version the issue has been seen with

252.17-1~deb12u1

Used distribution

Debian 12.2

Linux kernel version used

6.1.0-13-amd64

CPU architectures issue was seen on

x86_64

Component

systemd-journal-remote, systemd-journal-upload

Expected behaviour you didn't see

Journal upload succeeding.

Unexpected behaviour you saw

Journal upload failing.

Steps to reproduce the problem

systemctl restart systemd-journal-upload.service

Additional program output to the terminal or log subsystem illustrating the issue

On connecting a remote (debian 12.2 named 'source', same kernel and systemd) system to 
upload it's journal messages to a central journal system (named 'sink') the
following error messages were produced:

Oct 22 15:49:35 source systemd-journal-upload[11706]: Upload to http://sinkip:19532/upload failed: Recv failure: Connection reset by peer
Oct 22 15:49:35 source systemd[1]: systemd-journal-upload.service: Main process exited, code=exited, status=1/FAILURE
Oct 22 15:49:35 source systemd[1]: systemd-journal-upload.service: Failed with result 'exit-code'.
Oct 22 15:49:35 source systemd[1]: systemd-journal-upload.service: Consumed 4.256s CPU time.

Oct 22 17:02:44 source systemd-journal-upload[12136]: Upload to http://sinkip:19532/upload failed: Recv failure: Connection reset by peer
Oct 22 17:02:44 source systemd[1]: systemd-journal-upload.service: Main process exited, code=exited, status=1/FAILURE
Oct 22 17:02:44 source systemd[1]: systemd-journal-upload.service: Failed with result 'exit-code'.
Oct 22 17:02:44 source systemd[1]: systemd-journal-upload.service: Consumed 4.340s CPU time.

Oct 22 15:49:27 sink systemd-journal-remote[1397]: /var/log/journal/remote//remote-sourceip.journal: Journal header limits reached or header out-of-date, rotating
Oct 22 15:49:29 sink systemd-journal-remote[1397]: /var/log/journal/remote//remote-sourceip.journal: Journal header limits reached or header out-of-date, rotating
Oct 22 15:49:32 sink systemd-journal-remote[1397]: Entry with no payload, skipping
Oct 22 15:49:35 sink systemd-journal-remote[1397]: /var/log/journal/remote//remote-sourceip.journal: Journal header limits reached or header out-of-date, rotating
Oct 22 15:49:35 sink systemd-journal-remote[1397]: Stream declares field with size 4922226994454288453 > DATA_SIZE_MAX = 805306368

Oct 22 17:02:36 sink systemd-journal-remote[1397]: /var/log/journal/remote//remote-sourceip.journal: Journal header limits reached or header out-of-date, rotating
Oct 22 17:02:38 sink systemd-journal-remote[1397]: /var/log/journal/remote//remote-sourceip.journal: Journal header limits reached or header out-of-date, rotating
Oct 22 17:02:41 sink systemd-journal-remote[1397]: Entry with no payload, skipping
Oct 22 17:02:44 sink systemd-journal-remote[1397]: /var/log/journal/remote//remote-sourceip.journal: Journal header limits reached or header out-of-date, rotating
Oct 22 17:02:44 sink systemd-journal-remote[1397]: Stream declares field with size 4922226994454288453 > DATA_SIZE_MAX = 805306368

If needed more information can be provided.

[HaanJde]

sudo journalctl --verify (with and without --merge and run for individual files with --file) said 100% PASS.

[HaanJde]

Ran both sides (source and sink) with SYSTEMD_LOG_LEVEL=debug

The interesting part (I think) of the sink log file:

Oct 26 12:56:19 sink systemd-journal-remote[990375]: Writer ref count 1
Oct 26 12:56:19 sink systemd-journal-remote[990375]: Closing journal file /var/log/journal/remote//remote-10.0.0.104.journal.
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Accepting new raw connection on fd:4
Oct 26 12:56:24 sink systemd-journal-remote[990375]: varlink: Setting state idle-client
Oct 26 12:56:24 sink systemd-journal-remote[990375]: varlink: Sending message: {"method":"io.systemd.Resolve.ResolveAddress","parameters":{"address":[10,1,1,100],"family":2,"flags":0}}
Oct 26 12:56:24 sink systemd-journal-remote[990375]: varlink: Changing state idle-client → calling
Oct 26 12:56:24 sink systemd-journal-remote[990375]: varlink: New incoming message: {"error":"io.systemd.Resolve.DNSError","parameters":{"rcode":3}}
Oct 26 12:56:24 sink systemd-journal-remote[990375]: varlink: Changing state calling → called
Oct 26 12:56:24 sink systemd-journal-remote[990375]: varlink: Changing state called → idle-client
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Accepted raw ipv4 connection from 10.1.1.100:47706
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Fixed min_use=16.0M max_use=4.0G max_size=128.0M min_size=512.0K keep_free=4.0G n_max_files=100
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Opened output file /var/log/journal/remote//remote-10.1.1.100.journal
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Creating source for fd:11 (10.1.1.100)
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Ignoring invalid field: "POST /upload HTTP/1.1\r"
Oct 26 12:56:24 sink systemd-journal-remote[990375]: Ignoring invalid field: "Host: 10.1.1.202:19532\r"

I'm going to test to see what happens when that ip address is resolvable.

The complete logfiles (8.5MB) are available on request.

[HaanJde]

Making the IP address resolvable to a hostname makes no difference but for the name of the journalfile created.

I keep getting the same 9K ' ... Ignoring invalid field: ... ' error messages.

[HaanJde]

Root cause found, at least: as far as I can dig.

The system running the sink is connected to two networks and is accepting journals from 1 system on one and 6 on the other network. All systems have the above mentioned versions (Debian 12.2, kernel 6.1.0-13-amd64, systemd 252.17-1~deb12u1), all are using the systemd-journal-upload.

The six on the first network were working fine, dumping to their hearts content.

The single system on the second was having the above mentioned problems.

Working with precision, the systemd-journal-remote.socket's ListenStreams were configured to be listening on the ip addresses reserved for that specific purpose. This was done with the edit/override possibility on the socket:

$ sudo systemctl edit systemd-journal-remote.socket :
...
[Socket]
ListenStream=
ListenStream=10.0.0.202:19532
ListenStream=10.1.1.202:19532
...

Guess what: the 6 working clients were on the first ip, the 1 that didn't on the second.

• Changing the order resulted in 1 working and 6 failing clients.
• Adding an additional ListenStream with 127.0.0.1 didn't change anything.
• Removing all ListenStream settings resulting in listening on 0.0.0.0:19532 made all 7 systems working.

Can someone look into this please?

[mrc0mmand]

Thank you for the detailed report! I can reproduce this locally, will try to look into what's going on.

[mrc0mmand]

Ah, so this is expected. From systemd-journal-remote.service(8):

       $LISTEN_FDS
           systemd-journal-remote supports the $LISTEN_FDS/$LISTEN_PID protocol. Open sockets inherited through socket
           activation behave like those opened with --listen-raw= described above, unless they are specified as an argument
           in --listen-http=-n or --listen-https=-n above. In the latter case, an HTTP or HTTPS server will be spawned using
           this descriptor and connections must be made over the HTTP protocol.

The systemd-journal-remote.service uses --listen-https=-3, which means it opens an http server only on the first socket, all following sockets are opened in a "raw" mode, where systemd-journal-remote expects a stream of journal events, hence the "invalid field" messages.

Currently there's no way to open the http server on multiple ports, and systemd-journal-upload doesn't support uploading "raw" events, so it seems like using only one socket is the only viable solution here.

/cc @poettering in case there are some details I'm missing

[HaanJde]

@mrc0mmand : Thanks for your clear explanation of where I went wrong.

I do think that I have a valid use case though, so should I put in a RFE?

[mrc0mmand]

@mrc0mmand : Thanks for your clear explanation of where I went wrong.

I do think that I have a valid use case though, so should I put in a RFE?

No need, I switched this one to an RFE, since having the use case explanation is definitely helpful.

[Thaodan]

Originally the bug was about DATA_SIZE_MAX being exceeded. Is this a side this issue?
I got the same error when importing a log file locally from stdin.