Skip to content

Suppress known git progress logs - #259

Open
candleindark wants to merge 19 commits into
datalad:masterfrom
candleindark:suppress-git-progress-logs
Open

Suppress known git progress logs#259
candleindark wants to merge 19 commits into
datalad:masterfrom
candleindark:suppress-git-progress-logs

Conversation

@candleindark

Copy link
Copy Markdown
Collaborator

This PR suppresses known git progress logs in the worker.

The logging of the cloning operation in Datalad is hardcorded, https://github.com/datalad/datalad/blob/adcfcb6ae6e423a1860b7dde203c8caad32d6fb3/datalad/support/gitrepo.py#L1075, so I think by filtering the logs is a good way to removing git progress logs from the Celery worker's logs.

Let me know if there is a better way to remove git progress logs from the Celery worker's logs.

@candleindark
candleindark marked this pull request as draft October 18, 2023 05:45
@codecov

codecov Bot commented Oct 18, 2023

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 97.29730% with 1 line in your changes missing coverage. Please review.
✅ Project coverage is 98.93%. Comparing base (523963d) to head (195ffd2).
⚠️ Report is 518 commits behind head on master.

Files with missing lines Patch % Lines
datalad_registry/__init__.py 80.00% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##           master     #259      +/-   ##
==========================================
+ Coverage   98.73%   98.93%   +0.19%     
==========================================
  Files          47       48       +1     
  Lines        2215     2247      +32     
==========================================
+ Hits         2187     2223      +36     
+ Misses         28       24       -4     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Comment thread datalad_registry/make_celery.py Outdated
@yarikoptic

Copy link
Copy Markdown
Member

this sounds a little too complicated... could you please point me to one of those logs? I wonder if we know for sure that it is going through that DataLad's GitProgress handler -- i.e. does it have all the normal prefixes for Datalad's logger?

@candleindark

Copy link
Copy Markdown
Collaborator Author

this sounds a little too complicated... could you please point me to one of those logs? I wonder if we know for sure that it is going through that DataLad's GitProgress handler -- i.e. does it have all the normal prefixes for Datalad's logger?

Here are a few examples of the logs.

[2023-10-06 18:18:02,384: INFO/ForkPoolWorker-33] Start counting objects
[2023-10-06 18:18:02,385: INFO/ForkPoolWorker-33] remote: Counting objects:   0% (1/111165)
[2023-10-06 18:18:02,393: INFO/ForkPoolWorker-33] remote: Counting objects:   1% (1112/111165)
[2023-10-06 18:18:02,393: INFO/ForkPoolWorker-33] remote: Counting objects:   2% (2224/111165)
[2023-10-06 18:18:02,393: INFO/ForkPoolWorker-33] remote: Counting objects:   3% (3335/111165)
[2023-10-06 18:18:02,393: INFO/ForkPoolWorker-33] remote: Counting objects:   4% (4447/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:   5% (5559/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:   6% (6670/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:   7% (7782/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:   8% (8894/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:   9% (10005/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:  10% (11117/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:  11% (12229/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:  12% (13340/111165)
[2023-10-06 18:18:02,394: INFO/ForkPoolWorker-33] remote: Counting objects:  13% (14452/111165)
[2023-10-06 18:18:02,395: INFO/ForkPoolWorker-33] remote: Counting objects:  14% (15564/111165)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   0% (1/111150)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   1% (1112/111150)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   2% (2223/111150)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   3% (3335/111150)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   4% (4446/111150)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   5% (5558/111150)
[2023-10-06 18:18:02,428: INFO/ForkPoolWorker-33] remote: Compressing objects:   6% (6669/111150)
[2023-10-06 18:18:02,429: INFO/ForkPoolWorker-33] remote: Compressing objects:   7% (7781/111150)
[2023-10-06 18:18:02,429: INFO/ForkPoolWorker-33] remote: Compressing objects:   8% (8892/111150)
[2023-10-06 18:18:02,429: INFO/ForkPoolWorker-33] remote: Compressing objects:   9% (10004/111150)
[2023-10-06 18:18:02,429: INFO/ForkPoolWorker-33] remote: Compressing objects:  10% (11115/111150)
[2023-10-06 18:18:02,429: INFO/ForkPoolWorker-33] remote: Compressing objects:  11% (12227/111150)
[2023-10-06 18:18:02,429: INFO/ForkPoolWorker-33] remote: Compressing objects:  12% (13338/111150)
2023-10-06 18:18:02,879: INFO/ForkPoolWorker-33] Receiving objects:  20% (89427/447132)
[2023-10-06 18:18:02,899: INFO/ForkPoolWorker-33] Receiving objects:  21% (93898/447132)
[2023-10-06 18:18:02,921: INFO/ForkPoolWorker-33] Receiving objects:  22% (98370/447132)
[2023-10-06 18:18:02,942: INFO/ForkPoolWorker-33] Receiving objects:  23% (102841/447132)
[2023-10-06 18:18:02,961: INFO/ForkPoolWorker-33] Receiving objects:  24% (107312/447132), 9.80 MiB | 19.59 MiB/s
[2023-10-06 18:18:02,976: INFO/ForkPoolWorker-33] Receiving objects:  25% (111783/447132), 9.80 MiB | 19.59 MiB/s
[2023-10-06 18:18:02,993: INFO/ForkPoolWorker-33] Receiving objects:  26% (116255/447132), 9.80 MiB | 19.59 MiB/s
[2023-10-06 18:18:03,012: INFO/ForkPoolWorker-33] Receiving objects:  27% (120726/447132), 9.80 MiB | 19.59 MiB/s
[2023-10-06 18:18:03,045: INFO/ForkPoolWorker-33] Receiving objects:  28% (125197/447132), 9.80 MiB | 19.59 MiB/s

You can find more examples of these logs by checking out /srv/registry/logs/2023-10-16/worker-crashed-logs/datalad-registry_worker_1.log in Typhon.

The logic of this filter is based on the logic implemented by Datalad to recognized a git progress report. You can find this logic at https://github.com/datalad/datalad/blob/adcfcb6ae6e423a1860b7dde203c8caad32d6fb3/datalad/support/gitrepo.py#L496-L629.

@candleindark
candleindark marked this pull request as ready for review October 20, 2023 01:17
@yarikoptic

Copy link
Copy Markdown
Member

ok, we troubleshoot it until its death -- PR against datalad: datalad/datalad#7521 .

So, looking forward do following

# in future - this should be sufficient
import datalad
datalad.enable_librarymode()

# for now:
import logging
datalad_lgr = logging.getLogger("datalad")
for h in datalad_lgr.handlers:
    datalad_lgr.removeHandler(h)

dl_gitrepo_lgr = logging.getLogger("datalad.gitrepo")

# Add a filter to the "datalad.gitrepo" logger to suppress known git progress reports
dl_gitrepo_lgr.addFilter(SuppressKnownGitProgressReport())

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

This isn't need any longer right?

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

Currently, it is still needed. I added the solution in your previous comment. However, it only removed the duplications of the "start messages" such as "Start counting objects".

I also discovered that the log level setting,

"celery -A datalad_registry.make_celery:celery_app worker --loglevel INFO --pool prefork"
, of the logger seemingly has not affect on what messages are logged in execution.

This PR requires further digging. I will come back to this PR after #252 which is more important.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

ok, so here, I guess, now we are having log_progress still causing logging of the progress... complimentary issue I guess. I guess we need to dig deeper, most likely adding a way to completely disable log_progress. It might be that some workaround like

def no_log_progress(*args, **kwargs):
     pass

from datalad.support import gitrepo
gitrepo.log_progress = no_log_progress

would do the drill.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

This solution would take away the logs we want to take away and more. I think I still have to "start" and "finishing" logs, for example, to remain.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

Additionally, I still want an explanation for why changing the log level of the Celery worker command doesn't change the behavior of the worker's logger.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I think it is again datalad to blame: I added a note (see "edit 1") to datalad/datalad#7521

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Michael also pointed to the fact that we might want to use .propagate to avoid propagation of messages from our datalad logger: https://docs.python.org/3/library/logging.html#logging.Logger

@candleindark

candleindark commented Sep 25, 2024

Copy link
Copy Markdown
Collaborator Author

Findings in linkml/linkml#2323 (comment) can be useful in solving this problem. Particularly, setting the propagate attribute of a logger to False can prevent logged events being passed to handles of loggers at higher level in the hierarchy.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants