Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1084716

Summary: Plugins don't seem to be using our CompliantSysLogHandler
Product: [Retired] Pulp Reporter: Randy Barlow <rbarlow>
Component: z_otherAssignee: Randy Barlow <rbarlow>
Status: CLOSED CURRENTRELEASE QA Contact: pulp-qe-list
Severity: medium Docs Contact:
Priority: high    
Version: MasterCC: igulina, mkovacik, pthomas, rbarlow, skarmark
Target Milestone: ---Keywords: Triaged
Target Release: 2.4.0   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-08-09 06:56:15 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
log for rpm sync
none
log for iso sync none

Description Randy Barlow 2014-04-05 21:43:23 UTC 
I noticed when working on the ISOImporter today that the log messages from the ISOImporter.sync() method do not go through Pulp's CompliantSysLogHandler, but through Celery's built-in log handler. This is likely due to the fact that pulp_rpm and other plugins are loaded after Pulp loads, and the root logger appears not to be higher on the heirarchy than the pulp_rpm logger.

One solution may be to capture all loggers whenever we load a plugin. Another option may be to have getLogger always return our root logger.
Comment 1 Randy Barlow 2014-04-11 20:25:42 UTC 
https://github.com/pulp/pulp/pull/896
Comment 2 Randy Barlow 2014-04-24 20:28:36 UTC 
The fix for this bug is included in the 2.4.0-0.10.beta build that was just published to the Pulp fedorapeople.org repository.
Comment 3 Preethi Thomas 2014-04-29 19:11:23 UTC 
Created attachment 890899 [details]
log for rpm sync
Comment 4 Preethi Thomas 2014-04-29 19:12:17 UTC 
Created attachment 890900 [details]
log for iso sync
Comment 5 mkovacik 2014-05-06 11:55:50 UTC 
Randy, could you please specify what the old log entry looked like?

Thanks,
milan
Comment 6 Randy Barlow 2014-05-06 13:51:53 UTC 
I don't believe I have any logs that I can easily find from back when this was a problem, but if you see the word "pulp" as the first part of log messages, that means the CompliantSysLogHandler is being used as it's the only handler that gets the formatter that does that.

Without our formatter/handler, you might see log messages that start with the string "celery", or "nectar". With our formatter, the message will start with "pulp[<PID>]: celery…" for example.

Does that help?
Comment 7 Irina Gulina 2014-05-12 13:40:29 UTC 
confirmed in pulp-server-2.4.0-0.11.beta.fc20.noarch

with:

>>sudo journalctl --since 2014-05-09 SYSLOG_IDENTIFIER=pulp + SYSLOG_IDENTIFIER=nectar + SYSLOG_IDENTIFIER=httpd + SYSLOG_IDENTIFIER=celery | tail -1
May 12 13:23:51 ec2-54-73-49-210.eu-west-1.compute.amazonaws.com pulp[3526]: celery.beat:ERROR: SchedulingError: Couldn't apply scheduled task babysit: [Errno 110] Connection timed out

>>sudo journalctl --since 2014-05-09 SYSLOG_IDENTIFIER=pulp + SYSLOG_IDENTIFIER=nectar + SYSLOG_IDENTIFIER=httpd + SYSLOG_IDENTIFIER=celery | grep "celery\["
May 12 09:33:51 ec2-54-73-49-210.eu-west-1.compute.amazonaws.com celery[3528]: Exception in thread Thread-13:
May 12 09:33:51 ec2-54-73-49-210.eu-west-1.compute.amazonaws.com celery[3528]: Traceback (most recent call last):
May 12 09:33:51 ec2-54-73-49-210.eu-west-1.compute.amazonaws.com celery[3528]: File "/usr/lib64/python2.7/threading.py", line 811, in __bootstrap_inner

>>sudo journalctl --since 2014-05-09 SYSLOG_IDENTIFIER=pulp + SYSLOG_IDENTIFIER=nectar + SYSLOG_IDENTIFIER=httpd + SYSLOG_IDENTIFIER=celery | grep "nectar\["| wc -l
0

>>sudo journalctl --since 2014-05-09 SYSLOG_IDENTIFIER=pulp + SYSLOG_IDENTIFIER=nectar + SYSLOG_IDENTIFIER=httpd
-- Logs begin at Fri 2014-05-02 12:29:19 UTC, end at Mon 2014-05-12 13:37:41 UTC. --
May 09 00:00:39 ec2-54-73-49-210.eu-west-1.compute.amazonaws.com pulp[3526]: celery.beat:INFO: Scheduler: Sending due task babysit (pulp.server.async.tasks.babysit)
May 09 00:01:39 ec2-54-73-49-210.eu-west-1.compute.amazonaws.com pulp[3526]: celery.beat:INFO: Scheduler: Sending due task babysit (pulp.server.async.tasks.babysit)
Comment 8 Randy Barlow 2014-08-09 06:56:15 UTC 
This has been fixed in Pulp 2.4.0-1.