Issue #2906
closedLevel INFO messages not being logged in worker processes.
Description
Level INFO messages not being logged in worker processes in Pulp3. Something with logging not setup?
Related issues
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?
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:
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)?
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?
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?
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.
Updated by ttereshc over 7 years ago
- Triaged changed from No to Yes
- Tags Pulp 3 Plugin Writer Alpha added
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
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.
Updated by mhrivnak over 7 years ago
Pulp 3 currently is configured to use the stream handler, not the syslog handler.
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.
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?
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.
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.
Updated by bizhang over 7 years ago
- Status changed from NEW to ASSIGNED
- Assignee set to bizhang
Updated by bizhang over 7 years ago
- Status changed from ASSIGNED to POST
Added by werwty over 7 years ago
Added by werwty over 7 years ago
Revision ebd36ab6 | View on GitHub
Pulp logger should log at an INFO level to syslog
Updated by werwty over 7 years ago
- Status changed from POST to MODIFIED
Applied in changeset pulp|ebd36ab6a0f40bb5c0563a1e36bece9968ed470f.
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
Updated by mhrivnak over 7 years ago
- Has duplicate Task #2971: enable celery workers to log at levels below WARN added
Updated by bmbouter about 7 years ago
- Tags deleted (
Pulp 3 Plugin Writer Alpha)
Cleaning up Redmine tags
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.
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
Updated by bmbouter about 5 years ago
- Status changed from MODIFIED to CLOSED - CURRENTRELEASE
Pulp logger should log at an INFO level to syslog
closes #2906 https://pulp.plan.io/issues/2906