Project

Profile

Help

Issue #2906

closed

Level INFO messages not being logged in worker processes.

Added by jortel@redhat.com over 7 years ago. Updated about 5 years ago.

Status:
CLOSED - CURRENTRELEASE
Priority:
Normal
Assignee:
Category:
-
Sprint/Milestone:
Start date:
Due date:
Estimated time:
Severity:
2. Medium
Version:
Platform Release:
OS:
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Sprint:
Sprint 23
Quarter:

Description

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


Related issues

Has duplicate Pulp - Task #2971: enable celery workers to log at levels below WARNCLOSED - WONTFIX

Actions
Actions #1

Updated by bmbouter over 7 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?

Actions #2

Updated by mhrivnak over 7 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/

Actions #3

Updated by bmbouter over 7 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)?

Actions #4

Updated by bmbouter over 7 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?

Actions #5

Updated by mhrivnak over 7 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?

Actions #6

Updated by bmbouter over 7 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.

Actions #7

Updated by ttereshc over 7 years ago

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

Updated by mhrivnak over 7 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

Actions #9

Updated by bmbouter over 7 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.

Actions #10

Updated by mhrivnak over 7 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.

Actions #11

Updated by bmbouter over 7 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?

Actions #12

Updated by mhrivnak over 7 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.

Actions #13

Updated by bmbouter over 7 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.

Actions #14

Updated by mhrivnak over 7 years ago

  • Sprint/Milestone set to 42
Actions #15

Updated by bizhang over 7 years ago

  • Status changed from NEW to ASSIGNED
  • Assignee set to bizhang
Actions #16

Updated by bizhang over 7 years ago

  • Status changed from ASSIGNED to POST

Added by werwty over 7 years ago

Revision ebd36ab6 | View on GitHub

Pulp logger should log at an INFO level to syslog

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

Added by werwty over 7 years ago

Revision ebd36ab6 | View on GitHub

Pulp logger should log at an INFO level to syslog

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

Actions #17

Updated by werwty over 7 years ago

  • Status changed from POST to MODIFIED

Added by mhrivnak over 7 years ago

Revision 97afd6d8 | View on GitHub

removes an import of logging code that no longer exists

re #2906

Added by mhrivnak over 7 years ago

Revision 97afd6d8 | View on GitHub

removes an import of logging code that no longer exists

re #2906

Actions #18

Updated by mhrivnak over 7 years ago

  • Has duplicate Task #2971: enable celery workers to log at levels below WARN added
Actions #19

Updated by bmbouter about 7 years ago

  • Tags deleted (Pulp 3 Plugin Writer Alpha)

Cleaning up Redmine tags

Actions #20

Updated by dalley almost 7 years ago

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

This issue has regressed.

Actions #21

Updated by dalley almost 7 years 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

Actions #22

Updated by bmbouter almost 7 years ago

  • Sprint set to Sprint 23
Actions #23

Updated by bmbouter almost 7 years ago

  • Sprint/Milestone deleted (42)
Actions #24

Updated by daviddavis over 5 years ago

  • Sprint/Milestone set to 3.0.0
Actions #25

Updated by bmbouter over 5 years ago

  • Tags deleted (Pulp 3)
Actions #26

Updated by bmbouter about 5 years ago

  • Status changed from MODIFIED to CLOSED - CURRENTRELEASE

Also available in: Atom PDF