Project

Profile

Help

Issue #2906

Level INFO messages not being logged in worker processes.

Added by jortel@redhat.com over 2 years ago. Updated 6 months ago.

Status:
MODIFIED
Priority:
Normal
Assignee:
Category:
-
Sprint/Milestone:
Start date:
Due date:
Severity:
2. Medium
Version:
Platform Release:
Blocks Release:
OS:
Backwards Incompatible:
No
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
QA Contact:
Complexity:
Smash Test:
Verified:
No
Verification Required:
No
Sprint:
Sprint 23

Description

Level INFO messages not being logged in worker processes in Pulp3. Something with logging not setup?


Checklist


Related issues

Duplicated by Pulp - Task #2971: enable celery workers to log at levels below WARN CLOSED - WONTFIX Actions

Associated revisions

Revision ebd36ab6 View on GitHub
Added by werwty about 2 years ago

Pulp logger should log at an INFO level to syslog

closes #2906
https://pulp.plan.io/issues/2906

Revision ebd36ab6 View on GitHub
Added by werwty about 2 years ago

Pulp logger should log at an INFO level to syslog

closes #2906
https://pulp.plan.io/issues/2906

Revision ebd36ab6 View on GitHub
Added by werwty about 2 years ago

Pulp logger should log at an INFO level to syslog

closes #2906
https://pulp.plan.io/issues/2906

Revision 97afd6d8 View on GitHub
Added by mhrivnak about 2 years ago

removes an import of logging code that no longer exists

re #2906

Revision 97afd6d8 View on GitHub
Added by mhrivnak about 2 years ago

removes an import of logging code that no longer exists

re #2906

Revision 97afd6d8 View on GitHub
Added by mhrivnak about 2 years ago

removes an import of logging code that no longer exists

re #2906

History

#1 Updated by bmbouter over 2 years ago

Supposedly this was working before, but it was hard to test because we were running workers in the foreground. We have configured the Django logger here

We should troubleshoot this while launching the workers with the systemd unit files in place and we can start/stop wokers not in the foreground. Maybe we need to configure logging on systemd?

#2 Updated by mhrivnak over 2 years ago

It looks like we need to enable the syslog handler as an option in addition to the stream handler. This Pulp 2 work from @ehelms may be helpful:

https://github.com/pulp/pulp/pull/3041/

#3 Updated by bmbouter over 2 years ago

Yes I agree we probably need to use the syslog handler. The Django docs say that you can use any Python provided log handler, so I think the one we want is this one: https://docs.python.org/3.5/library/logging.handlers.html#sysloghandler

@mhrivnak: so for the Pulp3 MVP are we to use syslog as our default and over time add the ability to configure other log handlers (aka stdout when running in docker)?

#4 Updated by bmbouter over 2 years ago

Quoting @jortel from IRC: "oddly enough, WARN+ do log to syslog. just not INFO."

So do we really need INFO to be sent to syslog?

#5 Updated by mhrivnak over 2 years ago

I'm hoping we can just re-use our pulp 2 logging code, which supports both syslog and stream. The latter is particularly valuable for containerized deployments.

Is there anything about logging we need to change from Pulp 2? Or any reason we can't re-use that code?

#6 Updated by bmbouter over 2 years ago

Early on in Pulp3, @smyers and I looked into this and we thought that the Pulp2 logger couldn't possibly be as good as the Django logger. It's at the very least not as well tested and something we have to maintain. Django supports both syslog and stream also.

I think we need to have a default (like syslog) and have a setting to use another logger. The existing settings "overlay" over the settings.py file at startup so we are well setup to allow the user to configure their logger the Django way. I don't think we want to bring along our custom logger from Pulp2.

#7 Updated by ttereshc about 2 years ago

  • Triaged changed from No to Yes
  • Tags Pulp 3 Plugin Writer Alpha added

#8 Updated by mhrivnak about 2 years ago

The content app handles logging in the "django way", as opposed to the rest of Pulp. Perhaps we can just use this for all of Pulp?

https://github.com/pulp/pulp/blob/master/server/pulp/server/content/web/settings.py#L27-L53

#9 Updated by bmbouter about 2 years ago

Yes I think we can use that logger everywhere and just have the settings.yaml overlay setting on top of it. I think the workers already are using those loggers even. For example, celery does all of that 'fixup django' strangeness due to it being Django aware.

The surprising thing to me is that the INFO log level is not sent to syslog with the default django logger as we have it configured. Maybe only routing WARN to syslog is normal? I'm really not sure.

#10 Updated by mhrivnak about 2 years ago

Pulp 3 currently is configured to use the stream handler, not the syslog handler.

https://github.com/pulp/pulp/blob/6474186055527a4c3ff41e2de9793d334296ace0/platform/pulpcore/app/settings.py#L176

So that presumably means log output is going to stdout, where systemd is collecting it. If that's true, you'd be able to see it in "systemctl status $service". It could be that systemd has a policy where any WARN or higher log statements sent to stdout get automatically put in the system log, which would explain what you see. But that's just speculation.

In any case, we need to support the syslog handler. The pulp 2 content app config, linked above, is a good model for that.

#11 Updated by bmbouter about 2 years ago

Given that we can use either and we can configure either, I'm wondering what the default logger should be.

So should pulp3 continue to default to syslog output?
Or should we adjust the systemd units we ship to send INFO+ to syslog also?

#12 Updated by mhrivnak about 2 years ago

I think we should continue to use the syslog handler by default, but make it configurable. I don't see a compelling reason to change this behavior.

#13 Updated by bmbouter about 2 years ago

After talking some in #systemd it sounds like it routes nothing to syslog by default but "some distros" do route to syslog. I think if we want logs to go to syslog we should send them to syslog. Given the varying behavior I think defaulting to syslog for Pulp3 as we did in Pulp2 would be good.

Also the enabling of other loggers is already done, we just need to add the example I think to the yaml file here

So to accomplish this idea I added these checklist items.

#14 Updated by mhrivnak about 2 years ago

  • Sprint/Milestone set to 42

#15 Updated by bizhang about 2 years ago

  • Status changed from NEW to ASSIGNED
  • Assignee set to bizhang

#16 Updated by bizhang about 2 years ago

  • Status changed from ASSIGNED to POST

#17 Updated by werwty about 2 years ago

  • Status changed from POST to MODIFIED

#18 Updated by mhrivnak about 2 years ago

  • Duplicated by Task #2971: enable celery workers to log at levels below WARN added

#19 Updated by bmbouter almost 2 years ago

  • Tags deleted (Pulp 3 Plugin Writer Alpha)

Cleaning up Redmine tags

#20 Updated by dalley over 1 year ago

  • Status changed from MODIFIED to NEW
  • Sprint/Milestone deleted (42)
  • Triaged changed from Yes to No

This issue has regressed.

#21 Updated by dalley over 1 year ago

  • Status changed from NEW to MODIFIED
  • Sprint/Milestone set to 42
  • Triaged changed from No to Yes

Restoring this one and reopening https://pulp.plan.io/issues/2971 instead

#22 Updated by bmbouter over 1 year ago

  • Sprint set to Sprint 23

#23 Updated by bmbouter over 1 year ago

  • Sprint/Milestone deleted (42)

#24 Updated by daviddavis 6 months ago

  • Sprint/Milestone set to 3.0

#25 Updated by bmbouter 6 months ago

  • Tags deleted (Pulp 3)

Please register to edit this issue

Also available in: Atom PDF