Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add log message indicating finishing projects initialization #671

Merged
merged 2 commits into from
Feb 7, 2023

Conversation

juhoinkinen
Copy link
Member

By looking at the logs from e.g. OpenShift environment it can be hard to see if Annif pod/container has booted or models are still being loaded. In error situations while Annif is in boot loop (or it seems so) it would be good to easily know from the logs if/when Annif has started.

This PR adds an info level message finished initializing projects to log stream for addressing the mentioned concern. For this, it was necessary to also do the basic configuration for the root logger and set log level to "info" (was "unset") for "annif" logger. This makes all log messages from Annif to show also the level and the logger name.

For example:

[2023-02-07 16:12:22 +0200] [460823] [INFO] Starting gunicorn 20.1.0
[2023-02-07 16:12:22 +0200] [460823] [INFO] Listening at: http://0.0.0.0:8000 (460823)
[2023-02-07 16:12:22 +0200] [460823] [INFO] Using worker: sync
[2023-02-07 16:12:22 +0200] [460825] [INFO] Booting worker with pid: 460825
2023-02-07T14:12:26.030Z INFO [omikuji::model] Loading model from data/projects/omikuji-parabel-fi/omikuji-model...
2023-02-07T14:12:26.030Z INFO [omikuji::model] Loading model settings from data/projects/omikuji-parabel-fi/omikuji-model/settings.json...
2023-02-07T14:12:26.030Z INFO [omikuji::model] Loaded model settings Settings { n_features: 329277, classifier_loss_type: Hinge }...
2023-02-07T14:12:26.030Z INFO [omikuji::model] Loading tree from data/projects/omikuji-parabel-fi/omikuji-model/tree2.cbor...
2023-02-07T14:12:28.830Z INFO [omikuji::model] Loading tree from data/projects/omikuji-parabel-fi/omikuji-model/tree0.cbor...
2023-02-07T14:12:31.534Z INFO [omikuji::model] Loading tree from data/projects/omikuji-parabel-fi/omikuji-model/tree1.cbor...
2023-02-07T14:12:34.281Z INFO [omikuji::model] Loaded model with 3 trees; it took 8.25s
WARNING:annif:Couldn't initialize backend 'omikuji': vectorizer file 'data/projects/omikuji-parabel-sv/vectorizer' not found
WARNING:annif:Couldn't initialize backend 'omikuji': vectorizer file 'data/projects/omikuji-parabel-en/vectorizer' not found
INFO:annif:finished initializing projects

The gunicorn and Omikuji log messages have also timestamps, but they are actually more distracting than helpful when logs are read in Kibana (especially), because there is a dedicated timestamp field for every message.

@juhoinkinen juhoinkinen added this to the 0.61 milestone Feb 7, 2023
Copy link
Member

@osma osma left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems like a useful feature. 👍

As you noted, the different log messages are in different formats and some of them are less useful than others. We also have an old issue #451 which is somewhat related to the problem of handling log messages. IIRC Omikuji does its own logging from within Rust code, and it can be difficult or impossible to control that. Not sure about if and how gunicorn logging could be controlled.

@sonarqubecloud
Copy link

sonarqubecloud bot commented Feb 7, 2023

SonarCloud Quality Gate failed.    Quality Gate failed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot E 1 Security Hotspot
Code Smell A 0 Code Smells

No Coverage information No Coverage information
0.0% 0.0% Duplication

@codecov
Copy link

codecov bot commented Feb 7, 2023

Codecov Report

Base: 99.56% // Head: 99.12% // Decreases project coverage by -0.44% ⚠️

Coverage data is based on head (2ed3f03) compared to base (1c587bd).
Patch coverage: 100.00% of modified lines in pull request are covered.

Additional details and impacted files
@@            Coverage Diff             @@
##           master     #671      +/-   ##
==========================================
- Coverage   99.56%   99.12%   -0.44%     
==========================================
  Files          87       87              
  Lines        6142     6145       +3     
==========================================
- Hits         6115     6091      -24     
- Misses         27       54      +27     
Impacted Files Coverage Δ
annif/__init__.py 89.65% <100.00%> (+1.19%) ⬆️
tests/test_backend_fasttext.py 100.00% <100.00%> (ø)
annif/analyzer/voikko.py 10.52% <0.00%> (-89.48%) ⬇️
tests/test_analyzer_voikko.py 25.00% <0.00%> (-75.00%) ⬇️
annif/analyzer/__init__.py 90.32% <0.00%> (-3.23%) ⬇️

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report at Codecov.
📢 Do you have feedback about the report comment? Let us know in this issue.

@juhoinkinen juhoinkinen merged commit 8a194c4 into master Feb 7, 2023
@juhoinkinen juhoinkinen deleted the log-msg-for-projects-loaded branch February 7, 2023 14:58
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants