eventutilities-python manager should set up python logging with ECS format
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	Ottomata
	May 2 2023, 5:48 PM

Description

Our flink helm charts configure ECS for Java logging. We should do this for python logs as well.

https://www.elastic.co/guide/en/ecs-logging/python/current/installation.html

To do this, eventutililties-python manager should support log configuration from a file. We should add a param --log_config=path/to/log.config that is passed to logging.config.fileConfig, and set the defaults to use ECS logging (basically this but in configparser format).

Done is

evenutilities_python.manager.load_config supports configuring python logging from config file
Either: default logging format is set to ECS, or our helm chart provides a logging config file that sets logging format to ECS.

Details

	Subject	Repo	Branch	Lines +/-
	Add flink-app default log config and use it in page_content_change	operations/deployment-charts	master	+24 -3

Customize query in gerrit

	Title	Reference	Author	Source Branch	Dest Branch
	Upgrade eventutilities-python to 0.7.0	repos/data-engineering/mediawiki-event-enrichment!55	otto	eventutilities-0.7.0	main
	Add Log Configuration Support	repos/data-engineering/eventutilities-python!48	tchin	log-config	main

Customize query in GitLab

Related Objects

Mentioned Here: T234565: Standardize the logging format
T292881: Mutate mmkubernetes k8s fields into ECS fields

Event Timeline

Ottomata created this task.May 2 2023, 5:48 PM

Restricted Application added a project: Data-Engineering. · View Herald TranscriptMay 2 2023, 5:48 PM

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

Ottomata updated the task description. (Show Details)May 2 2023, 5:56 PM

Ottomata updated the task description. (Show Details)

tchin opened https://gitlab.wikimedia.org/repos/data-engineering/eventutilities-python/-/merge_requests/48

Draft: Add Log Configuration Support

gerritbot added a project: Patch-For-Review.May 3 2023, 7:02 PM

tchin claimed this task.May 4 2023, 1:13 PM

tchin moved this task from Backlog to Sprint 12 on the Event-Platform board.May 4 2023, 1:17 PM

tchin edited projects, added Event-Platform (Sprint 12); removed Event-Platform.

tchin moved this task from Next Up to In progress on the Event-Platform (Sprint 12) board.May 4 2023, 1:28 PM

Hm, @tchin! I'm looking more closely at the python production logs, and um, they look like they are in ECS format already!

{"@timestamp":"2023-05-04T20:00:57.977Z","log.level":"ERROR","message":"Failed requesting wiki content from de.wikipedia.org for page_id 12658243, rev_id 233363787: {'badrevids': {'233363787': {'revid': 233363787, 'missing': True}}} ", "ecs.version": "1.2.0","process.thread.name":"grpc-default-executor-587","log.logger":"/srv/app/mediawiki_event_enrichment/page_content_change.py:84"}

EEK. Sorry. So, okay I don't know how this works then. I would like to be able to use the extra param and extra context in actual ECS/logstash fields though, so maybe ecs-python will still help us. But, I'm not sure what happens here, if the logging is already coming in ECS format. Might require some experimentation.

Okay, I deployed with this logging message, and the message looks like:

{"@timestamp":"2023-05-04T20:20:29.983Z","log.level":"ERROR","message":"Failed requesting ar.wikipedia.org content from https://api-ro.discovery.wmnet/w/api.php?action=query&format=json&formatversion=2&prop=revisions&revids=62328001&rvprop=content&rvslots=* ", "ecs.version": "1.2.0","process.thread.name":"grpc-default-executor-1","log.logger":"/srv/app/mediawiki_event_enrichment/page_content_change.py:112"}

None of the extra stuff is there as I'd like it to be. So hopefully the python ecs-logging formatter will help us. I just hope it doesn't double format?

Do we know what's turning them into ecs format in the first place?

Not 100% but pretty sure it is our k8s stdout -> logstash stuff. We should ask ServiceOps I guess? @JMeybohm what is taking stdout from a container process and turning it into ECS/JSON formatted logs I see in kubectl logs and logstash?

We set up an ECS specific logging format for Flink Java logs, and were about to for python logs as well.

The logging pipeline on k8s is described here https://wikitech.wikimedia.org/wiki/Kubernetes/Logging

There is nothing fully "converting" or "normalizing" the logs into ECS, though.

Okay, so, from reading those docs and looking at app logs in logstash, e.g. this from java and this from python, it looks like no matter what format we configure our loggers, the configured docker json-file logging driver will consume each stdout/stderr line as single log message and stick it in its own json format. That means that even though we log in ECS json, our log message is being consumed as a json string and sent as that. E.g.

{"log":"{\"@timestamp\":\"2023-05-04T20:20:05.877Z\",\"log.level\": \"INFO\",\"message\":\"Source: kafka__rc1.mediawiki.page_change -\u003e kafka__rc1.mediawiki.page_change__row_to_dict, filter_remove_canary_events, _stream_key_by_map_operator (1/1) (37c3c06bae61447af0395b811a5695bb_cbc357ccb763df2852fee8c4fc7d55f2_0_0) switched from CREATED to SCHEDULED.\", \"ecs.version\": \"1.2.0\",\"process.thread.name\":\"flink-akka.actor.default-dispatcher-16\",\"log.logger\":\"org.apache.flink.runtime.executiongraph.ExecutionGraph\"}\n","stream":"stdout","time":"2023-05-04T20:20:05.877993509Z"}

It'd be nice to have our ECS log messages consumed as is, instead of reformatted, but I'm not sure if this is possible.

Maybe @colewhite could advise us here? Is T292881: Mutate mmkubernetes k8s fields into ECS fields related?

Ottomata added a subscriber: colewhite.May 8 2023, 1:34 PM

@tchin I think we should move forward with this python ECS logging as planned. At the very least it makes reading logs via kubectl logs much easier to read. We'll have to figure out how to ship them to logstash as is outside of this ticket.

In T335802#8833411, @Ottomata wrote:

It'd be nice to have our ECS log messages consumed as is, instead of reformatted, but I'm not sure if this is possible.

We extract the structured logs from the "log"field when shipped by rsyslog input-file. The logs should show up in logstash in the appropriate format.

Is T292881: Mutate mmkubernetes k8s fields into ECS fields related?

~~I will close that task. We added this capability as part of T234565.~~ There are still some fields to define in the comments, but the major ones are there.

@colewhite we are logging in ECS format for Java logs, so the log field from docker json-file format should be an ECS json string. Maybe I'm not looking in the right place, but I haven't been able to find a log message in logstash with the expected other fields, e.g. process.thread.name: flink-akka.actor.default-dispatcher-16

But I'm also not great at using logstash, so maybe I just failed finding this log message?

We extract the structured logs from the "log"field when shipped by rsyslog input-file

@tchin IIUC, this means that we should just use ecs-python then, cuz even though the log output will look a little funky in kubectl logs, logstash should do the right thing and use the ECS log message.