[Journald] input crashes with "failed to read message field: cannot allocate memory"

[belimawr]

Filebat: 8.13.2
Host OS: Amazon Linux 2
Systemd/Journald version: systemd 252 (252.16-1.amzn2023.0.2)

journalctl --version
systemd 252 (252.16-1.amzn2023.0.2)
+PAM +AUDIT +SELINUX -APPARMOR +IMA +SMACK +SECCOMP -GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN -IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 -BZIP2 -LZ4 +XZ -ZLIB -ZSTD +BPF_FRAMEWORK +XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified

##How to reproduce

1. Flood jounrald with logs so it it rotates logs every minute or so. Mostly follow [Filebeat] Journald causes Filebeat to crash #34077 (comment)
2. Start Filebeat with the config from the above link
3. Wait until Journald reaches its maximum number of files and starts deleting old entries
4. Filebeat might crash due to [Filebeat] Journald causes Filebeat to crash #34077, it's ok. Ignore it
5. Let the logs flowing for a while (I waited for hours)
6. Start Filebeat again
7. Journald input will fail with:

   {"log.level":"error","@timestamp":"2024-05-01T19:29:01.010Z","log.logger":"input.journald","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/v2/compat.(*runner).Start.func1","file.name":"compat/compat.go","file.line":132},"message":"Input 'journald' failed with: input.go:130: input journald-input failed (id=journald-input)\n\tfailed to read message field: cannot allocate memory","service.name":"filebeat","id":"journald-input","ecs.version":"1.6.0"}
   

Sometimes Filebeat might just crash again. I also saw it failing once or twice with the same message as in #32782.

Both seem to be relates with Filebeat being too far behind reading the journal, probably further behind than what journald has got stored in disk.

On both cases the error is coming from the Journald library we use, github.com/coreos/go-systemd/v22

[elasticmachine]

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)

[belimawr]

Even after merging #40061, I can still reproduce this "cannot allocate memory" error.

Here is how the new log error look:

{
  "log.level": "error",
  "@timestamp": "2024-08-08T21:02:16.242Z",
  "log.logger": "input.journald",
  "log.origin": {
    "function": "github.com/elastic/beats/v7/filebeat/input/journald/pkg/journalctl.(*Reader).Close",
    "file.name": "journalctl/reader.go",
    "file.line": 256
  },
  "message": "Journalctl wrote to stderr: Failed to get journal fields: Cannot allocate memory\n",
  "service.name": "filebeat",
  "id": "PR-testing",
  "input_source": "LOCAL_SYSTEM_JOURNAL",
  "path": "LOCAL_SYSTEM_JOURNAL",
  "ecs.version": "1.6.0"
}

This seems to be happening in journalctl itself, it's reproducible in the same way, but it takes longer to happen. I noticed it happening more often when the system is under pressure (VM with all CPUs at 100% and 2Gb of ram).

Interestingly enough this situation is also reproducible when running the Otel journald receiver that also calls journalctl and reads it's JSON output.

I believe the easiest solution for this on Filebeat is to be more resilient to journalctl crashes, restarting it instead of stopping the input.

[belimawr]

@pierrehilbert I changed the status to 'need technical definition' because we need to decide how to handle this error, at the moment the best option seems to make the journald input resilient to journalctl crashes and then validate whether this is still an issue that needs to be addressed directly.

[cmacknz]

Same as #32782 essentially.

We need to automatically recover from this if we aren't already.

[cmacknz]

This one seems more like system memory exhaustion though, how much memory is available on the host when it happens? Can other programs allocate memory?

[belimawr]

This one seems more like system memory exhaustion though, how much memory is available on the host when it happens? Can other programs allocate memory?

IIRC increasing the VM's memory helped, but I didn't see the memory reach 100% in any of my tests. The CPUs were at 100%. I didn't see the whole system crashing, nor the system became unresponsive.

Once I start working on those issues I'll properly collect system metrics, probably with Metricbeat.

[belimawr]

I'll start working on recovering if journalctl crashes, for this case simply restarting should suffice and should not create any problems with offset tracking.

[belimawr]

This is not fixed by #40558

[belimawr]

I managed to reproduce this issue by just calling journalctl and the machine seems to have plenty of memory available:

[root@aws-test-journald ~]# journalctl --utc --output=json --follow --after-cursor "s=922eeded44734fd9b2fe892ceb4ec2df;i=2e21e0;b=5d68f7c3ebf040879a4ab3ccbb2d965b;m=2e2762073e;t=62206b43c435e;x=46e90e97a06137ad">journal4.ndjson
Failed to read journal: Cannot allocate memory
[root@aws-test-journald ~]# free -h
               total        used        free      shared  buff/cache   available
Mem:            15Gi       1.0Gi       7.9Gi       120Mi       6.7Gi        14Gi
Swap:             0B          0B          0B
[root@aws-test-journald ~]# 

CPU usage is not low with some cores hitting 100%, but not all at the same time.

I believe the best we can do here is to make sure the input does not get stuck, which is done by #40558.

I'll close this issue as solved.