[8.0] iptables system test: found 0 hits in logs-iptables.log-ep data stream

[mtojek]

Hi,

while reviewing daily CI jobs I found this flaky problem with iptables:

[2022-01-26T05:06:50.986Z] 2022/01/26 05:06:50 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:51.921Z] 2022/01/26 05:06:51 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:52.858Z] 2022/01/26 05:06:52 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:53.798Z] 2022/01/26 05:06:53 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:54.736Z] 2022/01/26 05:06:54 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:56.115Z] 2022/01/26 05:06:55 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:57.052Z] 2022/01/26 05:06:56 DEBUG found 0 hits in logs-iptables.log-ep data stream
[2022-01-26T05:06:57.991Z] 2022/01/26 05:06:57 DEBUG reassigning original policy back to agent...
[2022-01-26T05:06:57.991Z] 2022/01/26 05:06:57 DEBUG PUT http://127.0.0.1:5601/api/fleet/agents/c75c33c6-df61-417e-a6fc-585e51bef85e/reassign
[2022-01-26T05:06:58.929Z] 2022/01/26 05:06:58 DEBUG GET http://127.0.0.1:5601/api/fleet/agents/c75c33c6-df61-417e-a6fc-585e51bef85e
[2022-01-26T05:06:58.929Z] 2022/01/26 05:06:58 DEBUG Agent data: {"id":"c75c33c6-df61-417e-a6fc-585e51bef85e","policy_id":"2016d7cc-135e-5583-9758-3ba01f5a06e5","local_metadata":{"host":{"name":"docker-fleet-agent"}}}
[2022-01-26T05:06:58.929Z] 2022/01/26 05:06:58 DEBUG Wait until the policy (ID: 2016d7cc-135e-5583-9758-3ba01f5a06e5, revision: 1) is assigned to the agent (ID: c75c33c6-df61-417e-a6fc-585e51bef85e)...

It looks like the iptables integration doesn't produce any metrics/logs? cc @andrewkroh

[andrewkroh]

A breaking change in the journald input is breaking all integrations that use the input.

@kvch I left you a few comments about making the change in a compatible manner. WDYT adding an automatic translation to keep old configs working? elastic/beats#29294 (comment)

There's another bug that will likely break integrations after the config issue is resolved - elastic/beats#30031. The field validation tests should fail because there would be a bunch of unexpected key names.

[andrewkroh]

The config breaking change doesn't seem to be the culprit. Filebeat 8.1.0-SNAPSHOT appears to ignore the filters specified in the old config format and read all journald logs. If I follow the Filebeat log I can see it publishing the 3 expected logs, but then Filebeat appears to crash.

2022-01-26T18:40:10Z - message: Application: filebeat--8.1.0-SNAPSHOT[d4a6c4ea-0e00-4882-b65c-d0be7534282f]: State changed to RESTARTING: exited with code: 2 - type: 'STATE' - sub_type: 'STARTING'

It's not possible to observe the stdout of the Filebeat process run by Agent so I cannot see if there is a panic.

---

I've tested Filebeat standalone with the console output and it does not crash. But it also does not add a cursor to registry. That seems odd. This is what I see under 8.1.

{"k":"journald::iptables::/home/vagrant/go/src/github.com/elastic/beats/filebeat/iptables.journal","v":{"cursor":null,"ttl":1800000000000,"updated":[33042222,1643224698]}}

And this is what I see under 7.17.

{"k":"journald::old::/home/vagrant/go/src/github.com/elastic/beats/filebeat/iptables.journal","v":{"ttl":1800000000000,"updated":[675663316,1643225792],"cursor":{"monotonictimestamp":1840880826380,"version":1,"position":"s=bc466f462aa64ffdb17ecc1f266e6fb3;i=3;b=c2f79f985830406a9e08241d015eff05;m=1ac9d0c380c;t=5d56b9afbd2ae;x=a38a1756ce1c8f62","realtimetimestamp":1642033021964974}}}

[andrewkroh]

I think the problem is related to https://github.com/elastic/beats/pull/29070/files#diff-839f58c64b7063f75769a4d945fca4efb1e7f103cd6217a90c2363490f918dd0L144-R151.

@belimawr can you take a look at Filebeat. I think the change you made lost both the translation of journald field names to ECS (eventFromFields is an unused function) and the cursor state (Private is not passed through to the Event here).

[mtojek]

Yup, journald is also affected: https://beats-ci.elastic.co/blue/organizations/jenkins/Ingest-manager%2Fintegrations/detail/main/67/tests

[belimawr]

I think the problem is related to https://github.com/elastic/beats/pull/29070/files#diff-839f58c64b7063f75769a4d945fca4efb1e7f103cd6217a90c2363490f918dd0L144-R151.

@belimawr can you take a look at Filebeat. I think the change you made lost both the translation of journald field names to ECS (eventFromFields is an unused function) and the cursor state (Private is not passed through to the Event here).

This data should now be set directly into the event here: https://github.com/belimawr/beats/blob/67b5ba70ed05ac3b6085ef023375dbcb48ad4b69/filebeat/input/journald/input.go#L239-L244

Anyways, I'm looking into it.

[mtojek]

@andrewkroh

It's not possible to observe the stdout of the Filebeat process run by Agent so I cannot see if there is a panic.

You can do this, you have to log in to the special internal bucket: beats-ci-temp-internal. Anyway, I checked there and no panic, or we haven't logged it :)

{"log.level":"info","@timestamp":"2022-01-27T03:30:51.927Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":150},"message":"Status change to Configuring: Updating configuration","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.928Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for filebeat.inputs","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"warn","@timestamp":"2022-01-27T03:30:51.928Z","log.logger":"input","log.origin":{"file.name":"v2/loader.go","file.line":102},"message":"EXPERIMENTAL: The journald input is experimental","service.name":"filebeat","input":"journald","stability":"Experimental","deprecated":false,"ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.928Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for output","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.928Z","log.logger":"input.journald","log.origin":{"file.name":"compat/compat.go","file.line":111},"message":"Input journald starting","service.name":"filebeat","id":"journald-journald.log-a8e2ab6d-b4f1-4ea5-b80a-2e6d994d869e","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.929Z","log.logger":"esclientleg","log.origin":{"file.name":"eslegclient/connection.go","file.line":102},"message":"elasticsearch url: http://elasticsearch:9200","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.929Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for filebeat.modules","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.929Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":213},"message":"retryer: send wait signal to consumer","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.929Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":217},"message":"  done","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.929Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":219},"message":"retryer: send unwait signal to consumer","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-27T03:30:51.929Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":223},"message":"  done","service.name":"filebeat","ecs.version":"1.6.0"}