Page MenuHomePhabricator

rdf-stream-updater / flink spam logs in DEBUG level, and possibly json parsing failure
Closed, ResolvedPublic5 Estimated Story Points

Description

Today the logging pipeline was spammed with DEBUG level logs from rdf-stream-updater / flink, we've reverted to a lesser log level (thank you @jijiki ) however it'd be good to investigate more on what's going on and how to prevent spam even in DEBUG.

Additionally, logstash was spamming its own logs due to JSON parsing failure on the messages, e.g.

1{
2 "level": "WARN",
3 "loggerName": "logstash.filters.json",
4 "timeMillis": 1629385188454,
5 "thread": "[main]>worker5",
6 "logEvent": {
7 "message": "Error parsing json",
8 "source": "log",
9 "raw": "{\"@timestamp\":\"2021-08-19T14:59:26,242\",\"log.level\":\"DEBUG\",\"message\":\"http-outgoing-22468 << \"[\\n]\"\",\"error.stack_trace\":\"\",\"process.thread.name\":\"GenerateEntityDiffPatchOperation-fetcher-15-2\",\"log.logger\":\"org.apache.http.wire\",\"ecs.version\":\"1.7.0\"}\n",
10 "exception": {
11 "metaClass": {
12 "metaClass": {
13 "metaClass": {
14 "exception": "Unexpected character ('[' (code 91)): was expecting comma to separate Object entries\n at [Source: (byte[])\"{\"@timestamp\":\"2021-08-19T14:59:26,242\",\"log.level\":\"DEBUG\",\"message\":\"http-outgoing-22468 << \"[\\n]\"\",\"error.stack_trace\":\"\",\"process.thread.name\":\"GenerateEntityDiffPatchOperation-fetcher-15-2\",\"log.logger\":\"org.apache.http.wire\",\"ecs.version\":\"1.7.0\"}\n\"; line: 1, column: 97]"
15 }
16 }
17 }
18 }
19 }
20}

But I haven't been able to identify exactly what's failing in the parsing and what piece is responsible. cc @zpapierski @colewhite (not sure what other project tags to add)

AC:

  • Valid json logs are produced regardless of a log level
  • exclude binary events from debug logs

Related Objects

Event Timeline

$ cat P17047.txt | jq '.logEvent.raw | fromjson'
jq: error (at <stdin>:20): Expected separator between values at line 1, column 96 (while parsing '{"@timestamp":"2021-08-19T14:59:26,242","log.level":"DEBUG","message":"http-outgoing-22468 << "[\n]"","error.stack_trace":"","process.thread.name":"GenerateEntityDiffPatchOperation-fetcher-15-2","log.logger":"org.apache.http.wire","ecs.version":"1.7.0"}

An improperly escaped quote, maybe? "message":"http-outgoing-22468 << "[\n]""

Change 714994 had a related patch set uploaded (by DCausse; author: DCausse):

[wikidata/query/flink-rdf-streaming-updater@master] Add support for elastic ECS logger

https://gerrit.wikimedia.org/r/714994

dcausse subscribed.

Will try to setup elastic ECS logger for flink.

Change 714997 had a related patch set uploaded (by DCausse; author: DCausse):

[operations/deployment-charts@master] flink-session-cluster: Add support for elastic ECS logger

https://gerrit.wikimedia.org/r/714997

Change 714994 merged by jenkins-bot:

[wikidata/query/flink-rdf-streaming-updater@master] Add support for elastic ECS logger

https://gerrit.wikimedia.org/r/714994

Change 714997 merged by jenkins-bot:

[operations/deployment-charts@master] flink-session-cluster: Add support for elastic ECS logger

https://gerrit.wikimedia.org/r/714997