Journalbeat Stops Reading Journals on Journald Rotation #9533

joelika · 2018-12-13T18:41:01Z

I've been evaluating journalbeat to send data to logstash, and journalbeat stops sending data daily, which I am assuming is tied to when journald is rotating journals. A quick restart of journalbeat gets data sending again.

Version: 6.5.2
Operating System: RHEL 7.6

My journald storage mode is set to auto, and I've tried it both with setting up the persistent storage, and without. I've also tried it where I specified the journal location in journalbeat and without.

kfalconer · 2018-12-14T14:11:44Z

Also seeing same issue with

Version: 6.5.3
Operating System: Ubuntu 16.04

kristinn · 2018-12-17T16:00:50Z

I'm able to reproduce using master with 952d922 as the newest commit.

This has been causing us lots of issues since we are processing around 10 million records a day. The "workaround" is to restart journalbeat every 5 minutes.

cachedout · 2018-12-18T19:30:08Z

Possibly related to this: coreos/go-systemd#233

If that's the case, they were waiting on the 1.11 release of golang earlier this year and they may be able to merge their pending fix. I bumped the upstream maintainers just to see.

Previously sd_journal_wait was not used. From now on all changes to journals are detected. I also added custom seccomp policy to Journalbeat. Closes #9533

Previously sd_journal_wait was not used. From now on all changes to journals are detected. I also added custom seccomp policy to Journalbeat. Closes elastic#9533 (cherry picked from commit cead4b6)

SpComb · 2019-02-04T12:51:07Z

Currently testing this as a workaround, installed in /etc/cron.hourly/journalbeat-rotate:

#!/bin/sh

set -ue

SYSTEM_JOURNAL_FILE_ID=$(journalctl --file /var/log/journal/*/system.journal --header | awk -F ': ' '/File ID/ { print $2 }')

if [ ! -e /var/lib/journalbeat/system-journal.id ] || [ "$SYSTEM_JOURNAL_FILE_ID" != "$(cat /var/lib/journalbeat/system-journal.id)" ]; then
  systemctl try-restart journalbeat && echo "$SYSTEM_JOURNAL_FILE_ID" > /var/lib/journalbeat/system-journal.id
fi

…entries change (#10485) Cherry-pick of PR #9994 to 6.x branch. Original message: Previously sd_journal_wait was not used. From now on all changes to journals are detected. I also added custom seccomp policy to Journalbeat. Closes #9533

kvch · 2019-02-12T15:55:47Z

After testing journalbeat on several systemd versions, it turns out that it is not a journalbeat bug. The beat was affected by the same issue as journalctl as it uses the same C API: systemd/systemd#474
This issue is fixed and released in v233. So currently journalbeat requires at least systemd v233.

JustinHead · 2019-02-12T17:27:16Z

We are experiencing this or some other issue that causes journalbeat to stop sending logs on Ubuntu 18.04 which uses systemd v237. Like the other posts, restarting journalbeat causes it to move along again.

mickymiek · 2019-02-14T09:19:28Z

Same issue here with systemd v238. Restarting journalbeat "solves" the issue.

kvch · 2019-02-14T10:26:07Z

@JustinHead @mickymiek Do you know what triggers the stopping of shipping logs (e.g. rotate, vacuum)?
I would like to track down whether the issue you are facing is due to a bug in the C API or in Journalbeat.

jbguerraz · 2019-02-14T11:58:32Z

Hello @kvch ,

@mickymiek and I are now investigating the case. We believe it could be related to rotate but have no evidence yet.

During investigations, and probably after deleting journal files, then running journalctl --vacuum-time=1seconds, we started to see tons of [input] input/input.go:167 Error while reading event: error while waiting for event: operation not permitted in logs due to inotify_init1(O_NONBLOCK|O_CLOEXEC) = -1 EPERM (Operation not permitted)

kvch · 2019-02-14T12:01:14Z

This might be due to incorrect seccomp policy. Could you please try to turn seccomp policy to test this theory?

seccomp.enabled: false

jbguerraz · 2019-02-14T12:06:23Z

Yes, this is related to seccomp, and disabling it workaround that permission issue.
BTW, we're running CoreOS, same case than #10605 so probably covered by your #10593
We're now monitoring it, to make sure the "stop reading journals" is really related tot hat seccomp issue.

This removes the journalbeat restart cron job for prometheus only. My goal is to let it run for a bit and observe if we're actually hitting this issue: elastic/beats#9533 ie I plan to see if we stop sending logs, and see if it coincides with journal rotation I picked prometheus for this because a) it has a different cloudinit file, and b) it's less critical than everything else

philandstuff · 2019-02-16T08:48:59Z

I'm experiencing this issue. I'm running ubuntu 18.04.2 (systemd v237).

Could the issue be that the journalbeat binaries are built on a debian stretch image, and stretch has libsystemd v232? I wonder if it might be possible to use libsystemd from backports (which is v239) to get the fixed version?

suhailpatel · 2019-02-17T18:42:04Z

👋, we faced a similar issue (operation not permitted) on CoreOS Systemd (we reported #10605) and found the result was because the seccomp policy was missing ppoll (confirmed using strace).

We've been running with #10593 which fixes the issue 🙌

jbguerraz · 2019-02-18T09:33:36Z

@kvch confirmed, no more issue since we disabled seccomp. Gonna go with the master branch since #10593 got merged. Thx!

tovern · 2019-02-22T09:28:44Z

I'm having the same trouble with Journalbeat 6.6.1 on Ubuntu 16.04. Setting "seccomp.enabled: false" has made no difference for me unfortunately. The debug logs show nothing useful, but the journal timestamps indicate that this is happening whenever the journal is rotated.

kvch · 2019-02-22T12:08:37Z

What do you mean by same issue? In this issue, two problem is reported.
What is your systemd version? If it is v232 or below, journalbeat fails to read entries after rotation, because of a bug in systemd.
If you are seeing operation not permitted errors, that is due to a bug in journalbeat, which is going to be fixed in the next release. As a workaround you can set seccomp.enabled to false.

kvch · 2019-03-06T11:27:58Z

I have opened an issue to track the two problems in different issues: #11110

hamelg · 2019-03-06T12:17:19Z

Unfortunately, not. The systemd API call we are using right now has the bug. But in a future release, we would like to refactor the code to remove this dependency.

Sorry, but my question was about the bug in API systemd <=v232 using by journalbeat.
Centos/RHEL 7.6 runs systemd v219. Is there a chance to see a fix in a near future ?

kvch · 2019-03-06T12:21:07Z

This is the issue to track that problem. It is definitely something we want to fix in an upcoming release.

hamelg · 2019-03-06T12:29:34Z

So, its status shouldn't be closed.

kvch · 2019-03-06T12:32:11Z

Reopened.

liqw33d · 2019-03-18T11:05:22Z

It looks like that: coreos/go-systemd#279 is fixing this problem.
I re-compiled journald with this patch applied and now there are no problems when systemd journal is rotated. Test is running ~2days and all messages were processed.
No other regressions were found during this testing.
Tested system is Ubuntu 16.04 (xenial) and Go is 1.11.

kvch · 2019-03-19T14:18:19Z

How did you apply the patch? We use github.com/coreos/go-systemd/sdjournal not github.com/coreos/go-systemd/journal. Did you copy the latter package also?
In the meantime I am looking into it.

kvch · 2019-03-19T14:23:59Z

Also, what's your systemd version?

kvaps · 2019-03-19T15:18:55Z

@kvch I was just replaced whole go-systemd directory with newer version.
You can try one of my docker image:

kvaps/journalbeat:7.0.0-fix9533
kvaps/journalbeat:8.0.0-fix9533

kvaps · 2019-03-19T23:04:36Z

Agree. This fix is working fine for me!

what's your systemd version?

- systemd 229 (xenial)
- systemd 232 (stretch)
- systemd 237 (bionic)
- systemd 241 (stretch)

go version go1.11.5 linux/amd64

journalbeat version 8.0.0 (amd64), libbeat 8.0.0 [258c1c8419ec945967f8a9e8e9d92e166f0bb3f7 built 2019-03-19 01:41:30 +0000 UTC]

liqw33d · 2019-03-20T09:17:46Z

Also, what's your systemd version?

systemd version is:
229-4ubuntu21.17 (xenial)
I applied mentioned diff to go-systemd (master) and compiled journalbeat (master) with it's dependencies.
I don't have exact steps to reproduce it now.

  "system_info": {
    "build": {
      "commit": "005bb608b010fa777db527738ad27b5f40086986",
      "libbeat": "8.0.0",
      "time": "2019-03-16T22:51:04.000Z",
      "version": "8.0.0"
    }
  }

vquie · 2019-03-20T21:09:27Z

When will this be available through the official elastic repo?

kvch · 2019-03-21T17:03:53Z

@liqw33d @kvaps Thank you for verifying the fix!

@vquiering Once the fix is released in a new version of github.com/coreos/go-systemd, I am updating the vendored folder.

hamelg · 2019-03-21T21:28:19Z

I re-compiled journald with this patch applied and now there are no problems when systemd journal is rotated. Test is running ~2days and all messages were processed.

Does it mean the fix consists to recompile journald ? The patch you mentioned is only related to github.com/coreos/go-systemd/journal (for writing to systemd's logging service, journald), journalbeat uses github.com/coreos/go-systemd/sdjournal (for reading from journald by wrapping its C API). Please, can you clarify ?

kvaps · 2019-03-21T22:43:18Z

@hamelg yes it is, you just need to recompile journalbeat with updated go-systemd

stanxing · 2019-03-22T04:36:38Z

yes it is, you just need to recompile journalbeat with updated go-systemd

@kvaps I feel a little confused. Why it can work when updating the package that has not been depended by journalbeat?

kvch · 2019-03-22T08:00:34Z

This is what I am investigating. My hunch is that the init function of that package connects to the FD of systemd journal, thus it lets Journalbeat read when and what changes are being made to the journal it is reading from.

kvch · 2019-03-22T15:13:11Z

I did more investigation on the matter. It turns out that the problem was fixed in Journalbeat not in its dependency github.com/coreos/go-systemd/sdjournal. The upcoming 6.7 and 7.0.0-rc release works with systemd v232.

Do you mind verifying my findings once the release is available?

stanxing · 2019-03-27T05:06:39Z

The upcoming 6.7 and 7.0.0-rc release works with systemd v232.

Take the liberty to ask, when is the 6.7 and 7.0.0-rc release date ?

praseodym · 2019-03-27T07:28:26Z

6.7 has just been released.

stanxing · 2019-03-27T10:04:11Z

the release of 6.7 works fine for me on ubuntu 16.04 with systemd version 229. But I found some erros as follows:

2019-03-27T17:52:36.001+0800    ERROR   [input] input/input.go:167      Error while reading event: failed to get realtime timestamp: 99  {"id": "a6a84c06-f11d-4f37-9d8f-3251d731d235"}

Does anyone have ideas ? My feeling is that it happened when rotating.

hamelg · 2019-03-27T10:27:25Z

I confirm 6.7 has fixed the issue on centos 7.6 with systemd version 219.

hamelg · 2019-03-27T10:41:16Z

But I found some erros as follows:

2019-03-27T17:52:36.001+0800    ERROR   [input] input/input.go:167      Error while reading event: failed to get realtime timestamp: 99  {"id": "a6a84c06-f11d-4f37-9d8f-3251d731d235"}

The same here, I see this error each time the journal is rotating.

kvch · 2019-03-27T15:09:36Z

@hamelg Do you mind opening a separate issue for that? Thanks for the confirmation.

kvch · 2019-03-27T15:09:56Z

Fixed in 6.7 and on master.

This should no longer be necessary with the 6.7.0 release, per elastic/beats#9533.

Previously sd_journal_wait was not used. From now on all changes to journals are detected. I also added custom seccomp policy to Journalbeat. Closes elastic#9533

…ournal entries change (elastic#10485) Cherry-pick of PR elastic#9994 to 6.x branch. Original message: Previously sd_journal_wait was not used. From now on all changes to journals are detected. I also added custom seccomp policy to Journalbeat. Closes elastic#9533

joelika mentioned this issue Dec 13, 2018

Initialize Journalbeat #8277

Merged

2 tasks

ph added bug Journalbeat labels Dec 13, 2018

cachedout mentioned this issue Dec 18, 2018

journal: use a connection-less socket coreos/go-systemd#279

Merged

kvch mentioned this issue Jan 10, 2019

Do not stop collecting events when journal entries change #9994

Merged

kvch closed this as completed in #9994 Jan 28, 2019

kvch added a commit that referenced this issue Jan 28, 2019

Do not stop collecting events when journal entries change (#9994)

cead4b6

Previously sd_journal_wait was not used. From now on all changes to journals are detected. I also added custom seccomp policy to Journalbeat. Closes #9533

kvch mentioned this issue Feb 1, 2019

Cherry-pick #9994 to 6.x: Do not stop collecting events when journal entries change #10485

Merged

This was referenced Feb 14, 2019

remove journalbeat cron for prometheus alphagov/verify-infrastructure#124

Merged

[Journalbeat] loses TCP connection to elasticsearch and stops shipping logs #10716

Closed

kvch reopened this Mar 6, 2019

kvch closed this as completed Mar 27, 2019

NicholasPCole added a commit to NicholasPCole/droplet-connectivity-testing that referenced this issue Mar 29, 2019

Disable Journalbeat debug logging

bf122b2

This should no longer be necessary with the 6.7.0 release, per elastic/beats#9533.

Journalbeat Stops Reading Journals on Journald Rotation #9533

Journalbeat Stops Reading Journals on Journald Rotation #9533

Comments

joelika commented Dec 13, 2018

kfalconer commented Dec 14, 2018

kristinn commented Dec 17, 2018

cachedout commented Dec 18, 2018

SpComb commented Feb 4, 2019

kvch commented Feb 12, 2019

JustinHead commented Feb 12, 2019 • edited Loading

mickymiek commented Feb 14, 2019

kvch commented Feb 14, 2019

jbguerraz commented Feb 14, 2019

kvch commented Feb 14, 2019

jbguerraz commented Feb 14, 2019 • edited Loading

philandstuff commented Feb 16, 2019

suhailpatel commented Feb 17, 2019 • edited Loading

jbguerraz commented Feb 18, 2019

tovern commented Feb 22, 2019

kvch commented Feb 22, 2019

kvch commented Mar 6, 2019

hamelg commented Mar 6, 2019

kvch commented Mar 6, 2019

hamelg commented Mar 6, 2019

kvch commented Mar 6, 2019

liqw33d commented Mar 18, 2019

kvch commented Mar 19, 2019

kvch commented Mar 19, 2019

kvaps commented Mar 19, 2019

kvaps commented Mar 19, 2019 • edited Loading

liqw33d commented Mar 20, 2019

vquie commented Mar 20, 2019

kvch commented Mar 21, 2019

hamelg commented Mar 21, 2019

kvaps commented Mar 21, 2019

stanxing commented Mar 22, 2019 • edited Loading

kvch commented Mar 22, 2019

kvch commented Mar 22, 2019

stanxing commented Mar 27, 2019

praseodym commented Mar 27, 2019

stanxing commented Mar 27, 2019 • edited Loading

hamelg commented Mar 27, 2019

hamelg commented Mar 27, 2019

kvch commented Mar 27, 2019

kvch commented Mar 27, 2019

JustinHead commented Feb 12, 2019 •

edited

Loading

jbguerraz commented Feb 14, 2019 •

edited

Loading

suhailpatel commented Feb 17, 2019 •

edited

Loading

kvaps commented Mar 19, 2019 •

edited

Loading

stanxing commented Mar 22, 2019 •

edited

Loading

stanxing commented Mar 27, 2019 •

edited

Loading