Streaming journalctl -afu rauc piles up messages

[SurrealW0rld]

Context:
I‘m trying to stream the progress of a rauc installation, i.e. its journalctl output, to an external viewer via a socket. For this, another service on the device with the rauc installation spawns a child process with journalctl and it listens to the ‘data’ emissions to process the data and then streams it to the external viewer.

Problem:
These ‘data’ emissions are send in bulk when the installation is finished which both is not suited for live monitoring and is happening while the socket is closing, so no messages reach the external viewer. Using journalctl in console with the same command on that device works as usual and updates live and using my service to live monitor other services from that device to an external viewer is also working as expected, only the combination of journalctl -u rauc and streaming it does not work.

Code:
The service managing this is written with NestJS and here is the condensed code where the data jam is happening:

export class ServiceStreamer {

  private spawn: childProcess.ChildProcess;
  private spawnOptions: childProcess.CommonSpawnOptions = {
    shell: true,
    stdio: ['ignore', 'pipe', 'inherit']
  };
  private emitter: EventEmitter = new EventEmitter();

  public async startSpawn() {
    this.spawn = childProcess.spawn(
      'journalctl -u rauc -a -o json -f -n 100',
      this.spawnOptions
    );
    this.initializEvent();
  }

  private initializEvent() {
    this.spawn.stdout.on('data', data => this.onData(data));
  }

 
  private onData(data_) { 
    /* … message processing before streaming */ 
    this.emitter.emit('data', result);
  }
  public stopSpawn() {
    this.spawn.stdout.destroy();
  }

}

data => this.onData(data) is the bottleneck, visible if changing the callback to

data => {
  Logger.debug(‘data received’);
  this.onData(data);
}

Do I need to configure the childprocess spawning in a specific way for rauc or is there another problem?

[ejoerns]

@SurrealW0rld I am not fully sure if I understood your use case. If you intend to show actual progress information, then you should preferably use the D-Bus API designed for this: https://rauc.readthedocs.io/en/latest/using.html#processing-progress-data

Do I need to configure the childprocess spawning in a specific way for rauc or is there another problem?

Since you spawn a 'journalctcl' subprocess, there should be nothing RAUC-specific in the question. For a normal journalctl -u -rauc -f, you should see the log messages live (at least I do).

If you don't need the journal, you could also start the RAUC service directly and then redirect stdout/stderr, but I would not encourage you to do so.

Also note that for remote-monitoring of the log or journal, there are existing mechanisms like https://www.freedesktop.org/software/systemd/man/latest/systemd-journal-remote.service.html or rsyslog

[SurrealW0rld]

So, the use case is:

• I'm triggering an update via rauc from a remote website application hosted on that device which should be updated
• I want to supervise the update, its progress and possible problems/errors live from that website application
• for that I want to stream the (sanitised) stdout via a websocket to the frontend

This procedure is working for other systemd services to watch them live. And, as you mentioned, I can see the log messages live on console on that device with journalctl -u -rauc -f. So, both modular use cases - remote streaming of other systemd services on the one side and journalctl rauc on device on the other side - are working singularly. But when I combine it to stream the journalctl rauc stdout to the remote frontend, than the data is not emitted until the installation process is done and the device starts rebooting. At that point the websockets are already disconnecting and not reaching the frontend anymore, besides that even this would be far from live logging.

The D-Bus API seems to be quite less comfortable to use, the data snippets are much more compartmentalised as far as I have seen it.

I didn't knew the remote monitoring service. Would you recommend that instead of setting up a websocket stream? Between stdout and streaming it on the socket, I'm sanitizing and processing the output a bit (I haven't mentioned that before). With remote this would need to happen on the frontend. I would think that this is not the best option as data processing should actually happen in the backend on device.

[ejoerns]

Thank you for explaining the use case in more details!

What confuses me about the journal is that rauc should behave differently than any other service running on your device. And that this is not reproducible without the remote forwarding. If there was a more simple setup to reproduce it, I guess we could have a look...

The D-Bus API provides information meant for visualizing progress or inspecting installation results. They provide less information than you will get from the journal of course. In the end, it is more about who the information is for. If you know about RAUC internals and how it works, the journal will help you. If you are an 'end user' waiting for an installation to finish or fail, the D-Bus information should be sufficient.

E.g. the LastError Property should be a very simple way to check the error in case an installation fails (i.e. Completed Signal is emitted with code != 0).

[jluebbe]

This sounds like you have some buffering between journalctl and your reading process. Are the timestamps reported by the journal for RAUC messages correct?

[SurrealW0rld]

@ejoerns Could you specify what you mean with the statement that rauc should behave differently? The setup in my original question ended with this.emitter.emit('data', result); in the onData() method. The subscription to this emission is forwarding it to the websocket (both are in a second file), so the whole websocket component has been omitted in the above code.

Ah okay, it is not meant for end user information, but pre-eminently for inspection in case something goes wrong and additionally that an end user has a sense of progress during the rauc install process.

@jluebbe Yes, this could be the case. But I don't know why it is happening in that case while there is no issue when just replacing the called service. Right now, when I tested again multiple times for the timestamp comparison, stdout wasn't emitting anything. The adapted code for logging the emitted data:

this.spawn.stdout.on('data', data => {
  Logger.warn(data);
  this.onData(data, service);
});

didn't log anything. So, as you suspect I think the bottleneck is somewhere between the stdout of rauc and the 'data'-listenener's reading of it, possibly due to buffering, which I'm not explicitly managing, though. For other services the timestamps seem perfectly fine:

date on device in console:
Tue Feb 27 01:32:06 PM CET 2024

Monotonic timestamp from journal messages:
1709037126245

Date on frontend [new Date(number in milliseconds from the timestamp)]:
Date Tue Feb 27 2024 13:32:06 GMT+0100

Frontend Date as ISO-string:
2024-02-27T12:32:06.245Z

But could it be that the output format (-o json) could cause the issue explicitly for rauc?

[SurrealW0rld]

The output format is seemingly not causing the issue. Do you have any other idea where I could investigate the cause?