- some logs are multiline and broken into one line per log message (printed as plain text, instead of sent to the logger which would print them as single-line JSON)
- some logs are NOTICE level but obviously shouldn't be, e.g. exception traces (probably same issue)
- a huge amount of noise is getting logged, such as performance profiling output or API responses.
Description
Details
Status | Subtype | Assigned | Task | ||
---|---|---|---|---|---|
Open | None | T295935 Average logging ingest has doubled over the last 90 days | |||
Resolved | kostajh | T295628 linkrecommendation-internal logs appear to be multiline json | |||
Open | Tgr | T296334 Make linkrecommendation service logging more useful |
Event Timeline
The same method is used for web and CLI requests (both via @click and via __main__). For web the printing should be removed. For CLI indenting should be restored.
My understanding was that has_app_context() prevents printing in the web request context.
I have very limited experience with Flask but the documentation says "The application context keeps track of the application-level data during a request, CLI command, or other activity." so my read was that has_app_context() is basically always true, unless you are very early in the lifecycle or invoking the class in a strange way.
Change 757382 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):
[research/mwaddlink@main] Do not print to stdout for web requests
Change 757383 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):
[operations/deployment-charts@master] linkrecommendation: Disable FLASK_PROFILE for staging
Change 757383 merged by jenkins-bot:
[operations/deployment-charts@master] linkrecommendation: Disable FLASK_PROFILE for staging
Change 757382 merged by jenkins-bot:
[research/mwaddlink@main] Do not print to stdout for web requests
Change 757395 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):
[research/mwaddlink@main] Log exceptions and return JSON on internal error
Change 757395 merged by jenkins-bot:
[research/mwaddlink@main] Log exceptions and return JSON on internal error
Change 757429 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):
[research/mwaddlink@main] logger: Log to stderr instead of stdout
Change 757429 merged by jenkins-bot:
[research/mwaddlink@main] logger: Log to stderr instead of stdout
The logs linked from the task description are empty since Feb 1, 13:50 UTC which matches the latest deploy. The total number of notices didn't decrease that much though:
They are content-free events like this, type:request level:NOTICE, contain a bunch of web request/response details like response_time_ms which can with some grepping be attributed to this line.
On the other hand, I tried to trigger this warning and don't see anything in the logs, so we might have overshot a bit (although I don't know for sure if it worked before).
Change 759193 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):
[research/mwaddlink@main] Apply FLASK_LOGLEVEL to json_logging request logger
Change 759193 merged by jenkins-bot:
[research/mwaddlink@main] Apply FLASK_LOGLEVEL to json_logging request logger
Change 759498 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):
[operations/deployment-charts@master] linkrecommendation: Bump version
Change 759498 merged by jenkins-bot:
[operations/deployment-charts@master] linkrecommendation: Bump version
Compared to the state after T296334#7670150, half of the noise is gone. The other half is performance metrics from stdout. We have removed all non-CLI performance tracking, and the log volume is way too regular to come from web requests anyway. Something must be invoking flask query via the command line, with the FLASK_PROFILE environment variable set. I can't find any trace of that, not sure what's going on. The log entries are all from linkrecommendation-staging but that's probably just because the loglevel filter is higher in production.
There are a few logs like these:
Caused by the DB switchover, but split up into many lines. They come from the linkrecommendation-internal-load-datasets container. We need to set exception handlers for the job entry points as well. Maybe that will fix the profiling issue as well, although I still don't understand why it's happening.
All the profiling dumps start with PATH: '/healthz' which explains the regularity (there is a call every 10 seconds, and each outputs ~100 lines of profiling code, so about 40K events per hour). No clue why an empty endpoint would do that.
Change 760402 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):
[research/mwaddlink@main] load-datasets: Fix logging
Change 761586 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):
[operations/deployment-charts@master] [WIP] linkrecommendation: Use json output format for logging
Change 760402 merged by jenkins-bot:
[research/mwaddlink@main] load-datasets: Fix logging
Change 761586 merged by jenkins-bot:
[operations/deployment-charts@master] linkrecommendation: Use json output format for logging
Change 761595 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):
[operations/deployment-charts@master] linkrecommendation: Bump chart version
Change 761595 merged by jenkins-bot:
[operations/deployment-charts@master] linkrecommendation: Bump chart version
After deployment of this patch:
kubectl logs -f linkrecommendation-internal-load-datasets-1644494400-6jkwm
{"written_at": "2022-02-10T12:00:10.179Z", "written_ts": 1644494410179357000, "msg": "== Initializing ==_ [general] Ensuring checksum table exists...[OK]_ [general] Ensuring model table exists...[OK]_ [cswiki] Ensuring anchors table exists...[OK]_ [cswiki] Ensuring redirects table exists...[OK]_ [cswiki] Ensuring pageids table exists...[OK]_ [cswiki] Ensuring w2vfiltered table exists...[OK]_ [cswiki] Ensuring model table exists...[OK]_ [simplewiki] Ensuring anchors table exists...[OK]_ [simplewiki] Ensuring redirects table exists...[OK]_ [simplewiki] Ensuring pageids table exists...[OK]_ [simplewiki] Ensuring w2vfiltered table exists...[OK]_ [simplewiki] Ensuring model table exists...[OK]_ [arwiki] Ensuring anchors table exists...[OK]_ [arwiki] Ensuring redirects table exists...[OK]_ [arwiki] Ensuring pageids table exists...[OK]_ [arwiki] Ensuring w2vfiltered table exists...[OK]_ [arwiki] Ensuring model table exists...[OK]_ [viwiki] Ensuring anchors table exists...[OK]_ [viwiki] Ensuring redirects table exists...[OK]_ [viwiki] Ensuring pageids table exists...[OK]_ [viwiki] Ensuring w2vfiltered table exists...[OK]_ [viwiki] Ensuring model table exists...[OK]_ [bnwiki] Ensuring anchors table exists...[OK]_ [bnwiki] Ensuring redirects table exists...[OK]_ [bnwiki] Ensuring pageids table exists...[OK]_ [bnwiki] Ensuring w2vfiltered table exists...[OK]_ [bnwiki] Ensuring model table exists...[OK]_ [enwiki] Ensuring anchors table exists...[OK]_ [enwiki] Ensuring redirects table exists...[OK]_ [enwiki] Ensuring pageids table exists...[OK]_ [enwiki] Ensuring w2vfiltered table exists...[OK]_ [enwiki] Ensuring model table exists...[OK]_ [frwiki] Ensuring anchors table exists...[OK]_ [frwiki] Ensuring redirects table exists...[OK]_ [frwiki] Ensuring pageids table exists...[OK]_ [frwiki] Ensuring w2vfiltered table exists...[OK]_ [frwiki] Ensuring model table exists...[OK]_ [elwiki] Ensuring anchors table exists...[OK]_ [elwiki] Ensuring redirects table exists...[OK]_ [elwiki] Ensuring pageids table exists...[OK]_ [elwiki] Ensuring w2vfiltered table exists...[OK]_ [elwiki] Ensuring model table exists...[OK]_ [dewiki] Ensuring anchors table exists...[OK]_ [dewiki] Ensuring redirects table exists...[OK]_ [dewiki] Ensuring pageids table exists...[OK]_ [dewiki] Ensuring w2vfiltered table exists...[OK]_ [dewiki] Ensuring model table exists...[OK]_ [ptwiki] Ensuring anchors table exists...[OK]_ [ptwiki] Ensuring redirects table exists...[OK]_ [ptwiki] Ensuring pageids table exists...[OK]_ [ptwiki] Ensuring w2vfiltered table exists...[OK]_ [ptwiki] Ensuring model table exists...[OK]_ [eswiki] Ensuring anchors table exists...[OK]_ [eswiki] Ensuring redirects table exists...[OK]_ [eswiki] Ensuring pageids table exists...[OK]_ [eswiki] Ensuring w2vfiltered table exists...[OK]_ [eswiki] Ensuring model table exists...[OK]_ [huwiki] Ensuring anchors table exists...[OK]_ [huwiki] Ensuring redirects table exists...[OK]_ [huwiki] Ensuring pageids table exists...[OK]_ [huwiki] Ensuring w2vfiltered table exists...[OK]_ [huwiki] Ensuring model table exists...[OK]_ [fawiki] Ensuring anchors table exists...[OK]_ [fawiki] Ensuring redirects table exists...[OK]_ [fawiki] Ensuring pageids table exists...[OK]_ [fawiki] Ensuring w2vfiltered table exists...[OK]_ [fawiki] Ensuring model table exists...[OK]_ [rowiki] Ensuring anchors table exists...[OK]_ [rowiki] Ensuring redirects table exists...[OK]_ [rowiki] Ensuring pageids table exists...[OK]_ [rowiki] Ensuring w2vfiltered table exists...[OK]_ [rowiki] Ensuring model table exists...[OK]_ [plwiki] Ensuring anchors table exists...[OK]_ [plwiki] Ensuring redirects table exists...[OK]_ [plwiki] Ensuring pageids table exists...[OK]_ [plwiki] Ensuring w2vfiltered table exists...[OK]_ [plwiki] Ensuring model table exists...[OK]_ [ruwiki] Ensuring anchors table exists...[OK]_ [ruwiki] Ensuring redirects table exists...[OK]_ [ruwiki] Ensuring pageids table exists...[OK]_ [ruwiki] Ensuring w2vfiltered table exists...[OK]_ [ruwiki] Ensuring model table exists...[OK]_ [nlwiki] Ensuring anchors table exists...[OK]_ [nlwiki] Ensuring redirects table exists...[OK]_ [nlwiki] Ensuring pageids table exists...[OK]_ [nlwiki] Ensuring w2vfiltered table exists...[OK]_ [nlwiki] Ensuring model table exists...[OK]_ [cawiki] Ensuring anchors table exists...[OK]_ [cawiki] Ensuring redirects table exists...[OK]_ [cawiki] Ensuring pageids table exists...[OK]_ [cawiki] Ensuring w2vfiltered table exists...[OK]_ [cawiki] Ensuring model table exists...[OK]_ [hewiki] Ensuring anchors table exists...[OK]_ [hewiki] Ensuring redirects table exists...[OK]_ [hewiki] Ensuring pageids table exists...[OK]_ [hewiki] Ensuring w2vfiltered table exists...[OK]_ [hewiki] Ensuring model table exists...[OK]_ [ukwiki] Ensuring anchors table exists...[OK]_ [ukwiki] Ensuring redirects table exists...[OK]_ [ukwiki] Ensuring pageids table exists...[OK]_ [ukwiki] Ensuring w2vfiltered table exists...[OK]_ [ukwiki] Ensuring model table exists...[OK]_ [hiwiki] Ensuring anchors table exists...[OK]_ [hiwiki] Ensuring redirects table exists...[OK]_ [hiwiki] Ensuring pageids table exists...[OK]_ [hiwiki] Ensuring w2vfiltered table exists...[OK]_ [hiwiki] Ensuring model table exists...[OK]_ [nowiki] Ensuring anchors table exists...[OK]_ [nowiki] Ensuring redirects table exists...[OK]_ [nowiki] Ensuring pageids table exists...[OK]_ [nowiki] Ensuring w2vfiltered table exists...[OK]_ [nowiki] Ensuring model table exists...[OK]_ [kowiki] Ensuring anchors table exists...[OK]_ [kowiki] Ensuring redirects table exists...[OK]_ [kowiki] Ensuring pageids table exists...[OK]_ [kowiki] Ensuring w2vfiltered table exists...[OK]_ [kowiki] Ensuring model table exists...[OK]_ [svwiki] Ensuring anchors table exists...[OK]_ [svwiki] Ensuring redirects table exists...[OK]_ [svwiki] Ensuring pageids table exists...[OK]_ [svwiki] Ensuring w2vfiltered table exists...[OK]_ [svwiki] Ensuring model table exists...[OK]_ Beginning process to load datasets for cswiki, simplewiki, arwiki, viwiki, bnwiki, enwiki, frwiki, elwiki, dewiki, ptwiki, eswiki, huwiki, fawiki, rowiki, plwiki, ruwiki, nlwiki, cawiki, hewiki, ukwiki, hiwiki, nowiki, kowiki, svwiki_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for cswiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for cswiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for simplewiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for simplewiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for arwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for arwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for viwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for viwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for bnwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for bnwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for enwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for enwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for frwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for frwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for elwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for elwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for dewiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for dewiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for ptwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for ptwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for eswiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for eswiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for huwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for huwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for fawiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for fawiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for rowiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for rowiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for plwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for plwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for ruwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for ruwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for nlwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for nlwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for cawiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for cawiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for hewiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for hewiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for ukwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for ukwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for hiwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for hiwiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for nowiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for nowiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for kowiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for kowiki are up-to-date!_== Attempting to download datasets (anchors, redirects, pageids, w2vfiltered, model) for svwiki ==_ Checksum in database matches remote checksum, skipping download for anchors_ Checksum in database matches remote checksum, skipping download for redirects_ Checksum in database matches remote checksum, skipping download for pageids_ Checksum in database matches remote checksum, skipping download for w2vfiltered_ Checksum in database matches remote checksum, skipping download for model_ All datasets for svwiki are up-to-date!_Finished importing datasets for cswiki, simplewiki, arwiki, viwiki, bnwiki, enwiki, frwiki, elwiki, dewiki, ptwiki, eswiki, huwiki, fawiki, rowiki, plwiki, ruwiki, nlwiki, cawiki, hewiki, ukwiki, hiwiki, nowiki, kowiki, svwiki_", "type": "log", "logger": "__main__", "thread": "MainThread", "level": "INFO", "module": "load-datasets", "line_no": 427}
Yes although probably lower priority:
- it would be nice to get rid of the healthz endpoint profiling output (even if it can be filtered via severity), or at least understand why it's happening when profiling should be disabled for that endpoint.
- we have entries like this: which Logstash can't properly process. Not sure what's going on there but seems like a Python dict -> str conversion instead of proper JSON.