Description of problem: The Pulp logging does not include an unique task_id in the log record. Therefor it is impossible to see which log messages belong to a certain task. Especially with the many messages that are generic: [crash] root@li-lc-1578:~# grep -c 'pulp: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading additional units.' /var/log/messages 171 [crash] root@li-lc-1578:~# grep -c 'pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com' /var/log/messages 1593 [crash] root@li-lc-1578:~# grep -c 'pulp: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS' /var/log/messages 1167 Below is a use case, which logging records belong to task_id 38c30954-c2bd-4a85-b6c6-951a0b23bee2 that is still not completed after 6 hours? Sep 18 02:00:46 li-lc-1578 pulp: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[a621987c-8a96-4fb7-bcc3-33ac4d4d1e1a] succeeded in 0.054187147005s: None Sep 18 02:00:47 li-lc-1578 pulp: pulp.plugins.pulp_rpm.plugins.distributors.yum.metadata.metadata:WARNING: Overwriting existing metadata file [/var/lib/pulp/working/repos/Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_7_Server_-_Oracle_Java_RPMs_x86_64_7_1/distributors/yum_distributor/repodata/repomd.xml] Sep 18 02:00:47 li-lc-1578 pulp: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading 0 RPMs. Sep 18 02:00:47 li-lc-1578 pulp: pulp.plugins.pulp_rpm.plugins.distributors.yum.metadata.metadata:WARNING: Overwriting existing metadata file [/var/lib/pulp/working/repos/Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_6_Server_-_Oracle_Java_RPMs_x86_64_6_5/distributors/yum_distributor/repodata/repomd.xml] Sep 18 02:00:47 li-lc-1578 pulp: pulp_rpm.plugins.importers.yum.sync:INFO: Sync complete. Sep 18 02:00:47 li-lc-1578 pulp: pulp.server.event.http:INFO: (29212-74560) {'call_report': {u'exception': None, u'task_type': u'pulp.server.managers.repo.sync.sync', u'task_id': u'38c30954-c2bd-4a85-b6c6-951a0b23bee2', u'tags': [u'pulp:repository:Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_6_Server_-_Oracle_Java_RPMs_x86_64_6Server', u'pulp:action:sync'], u'finish_time': None, u'_ns': u'task_status', u'start_time': u'2015-09-18T02:00:23Z', u'traceback': None, u'spawned_tasks': [], u'progress_report': {u'yum_importer': {u'content': {u'size_total': 0, u'items_left': 0, u'items_total': 0, u'state': u'FINISHED', u'size_left': 0, u'details': {u'rpm_total': 0, u'rpm_done': 0, u'drpm_total': 0, u'drpm_done': 0}, u'error_details': []}, u'comps': {u'state': u'FINISHED'}, u'distribution': {u'items_total': 0, u'state': u'FINISHED', u'error_details': [], u'items_left': 0}, u'errata': {u'state': u'FINISHED'}, u'metadata': {u'state': u'FINISHED'}}}, u'state': u'running', u'worker_name': u'reserved_resource_worker-5@li-lc-1578', u'result': None, u'error': None, u'_id': ObjectId('55fb7037874b58303c5d7e5b'), u'id': u'55fb70370586fe0ea2c21ceb'}, 'event_type': 'repo.sync.finish', 'payload': {'importer_id': u'yum_importer', 'exception': None, 'repo_id': u'Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_6_Server_-_Oracle_Java_RPMs_x86_64_6Server', 'traceback': None, 'started': '2015-09-18T02:00:23Z', '_ns': u'repo_sync_results', 'completed': '2015-09-18T02:00:47Z', 'importer_type_id': u'yum_importer', 'error_message': None, 'summary': {'content': {'state': 'FINISHED'}, 'comps': {'state': 'FINISHED'}, 'distribution': {'state': 'FINISHED'}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'added_count': 0, 'result': 'success', 'updated_count': 17, 'details': {'content': {'size_total': 0, 'items_left': 0, 'items_total': 0, 'state': 'FINISHED', 'size_left': 0, 'details': {'rpm_total': 0, 'rpm_done': 0, 'drpm_total': 0, 'drpm_done': 0}, 'error_details': []}, 'comps': {'state': 'FINISHED'}, 'distribution': {' Sep 18 02:00:47 li-lc-1578 pulp: pulp.server.event.http:INFO: (29212-74560) items_total': 0, 'state': 'FINISHED', 'error_details': [], 'items_left': 0}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'id': '55fb704f0586fe721c0b836b', 'removed_count': 0}} Sep 18 02:00:48 li-lc-1578 pulp: pulp_rpm.plugins.importers.yum.repomd.alternate:INFO: The content container reported: {'downloads': {}, 'total_sources': 0} for base URL: https://cdn.redhat.com/content/dist/rhel/server/6/6.7/x86_64/oracle-java/os/ Sep 18 02:00:48 li-lc-1578 pulp: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading additional units. Sep 18 02:00:48 li-lc-1578 pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com Version-Release number of selected component (if applicable): How reproducible: Steps to Reproduce: 1. Sync 100 RedHat repositories 2. Find all pulp logging messages for a single task_id 3. Actual results: Impossible to correlate pulp logging messages Expected results: Have a unique key (task_id) prefix in the pulp logging messages to be able to correlate the logging messages Additional info:
I agree this could be much better, but it is possible to establish which task generated specific messages. I will create an upstream issue to make this easier, but in the mean time, here is how you can figure it out. At least on el7, using journald for logging, you see the PID for each log statement. I don't recall if that's visible by default on el6. It's helpful to know that each pulp worker consists of a parent process to manage acceptance and tracking of work, and a child process to do the work. A simple sync task's log output looks like this: Aug 05 16:00:28 dev pulp[15035]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS Aug 05 16:00:28 dev pulp[14997]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[340f5972-29a1-4b63-b51c-d6e48c94eeda] Aug 05 16:00:29 dev pulp[15164]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS Aug 05 16:00:29 dev pulp[15010]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.sync.sync[88daa089-9823-49ec-94c5-735cbf458a22] Aug 05 16:00:29 dev pulp[15010]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[e4fffe06-9ec5-461d-9bc9-006760ac6d98] Aug 05 16:00:29 dev pulp[14997]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[340f5972-29a1-4b63-b51c-d6e48c94eeda] succeeded in 0.0648464679834s: None Aug 05 16:00:29 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/repos/pulp/pulp/demo_repos/zoo/. Aug 05 16:00:29 dev pulp[15160]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org Aug 05 16:00:30 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Parsing metadata. Aug 05 16:00:30 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/repos/pulp/pulp/demo_repos/zoo/. Aug 05 16:00:30 dev pulp[15160]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org Aug 05 16:00:31 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Parsing metadata. Aug 05 16:00:31 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/repos/pulp/pulp/demo_repos/zoo/. Aug 05 16:00:31 dev pulp[15160]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org Aug 05 16:00:32 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Parsing metadata. Aug 05 16:00:32 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: upstream repo metadata has not changed. Skipping steps. Aug 05 16:00:32 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading additional units. Aug 05 16:00:32 dev pulp[15160]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org Aug 05 16:00:33 dev pulp[15160]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org Aug 05 16:00:34 dev pulp[15160]: pulp_rpm.plugins.importers.yum.sync:INFO: Sync complete. Aug 05 16:00:34 dev pulp[15010]: celery.worker.job:INFO: Task pulp.server.managers.repo.sync.sync[88daa089-9823-49ec-94c5-735cbf458a22] succeeded in 5.21712172095s: <pulp.server.async.tasks.TaskResult object at 0x7f0424639fd0> Aug 05 16:00:34 dev pulp[15010]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[e4fffe06-9ec5-461d-9bc9-006760ac6d98] succeeded in 0.0448788729846s: None We see that PID 15160 did some work. If you want to know what task ID it was working on, that info gets logged by its parent at the beginning and end. There are many ways to figure out the parent PID, but in this case I did: $ cat /proc/15160/status| grep PPid PPid: 15010 We see that the parent process is 15010, and we can see in the log output that it was managing sync task "88daa089-9823-49ec-94c5-735cbf458a22".
The inclusion of the PID is a small step, but still to complex for quick filtering. I still recommend to add the task as prefix E.g. move the task between the [] to the front and make sure it is included in every log statement done by pulp: Aug 05 16:00:34 dev pulp[15010]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[e4fffe06-9ec5-461d-9bc9-006760ac6d98] succeeded in 0.0448788729846s: None Will then become: Aug 05 16:00:34 dev pulp[15010]: celery.worker.job:INFO:[e4fffe06-9ec5-461d-9bc9-006760ac6d98] pulp.server.async.tasks._release_resource succeeded in 0.0448788729846s: None We are using standard rsyslog for logging on both el6 and el7. For standard syslog it is an application option to include the PID. See "man 3 syslog" with the openlog() funciton that includes option parameter that can include the LOG_PID to include PID with each message. E.g. the puppet-master includes the PID, but pulp does not. vrempet@li-lc-1017 ~ $ grep puppet-master /var/log/messages | tail -n1 Aug 8 07:08:07 li-lc-1017 puppet-master[10476]: Compiled catalog for li-lc-1311.hag.hilti.com in environment KT_Hilti_Library_hg_crash_27 in 3.48 seconds vrempet@li-lc-1017 ~ $ grep pulp /var/log/messages | tail -n1 Aug 8 06:11:12 li-lc-1017 pulp: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
The Pulp upstream bug status is at NEW. Updating the external tracker on this bug.
The Pulp upstream bug priority is at Normal. Updating the external tracker on this bug.
The Pulp upstream bug status is at ASSIGNED. Updating the external tracker on this bug.
The Pulp upstream bug status is at POST. Updating the external tracker on this bug.
The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug.
All upstream Pulp bugs are at MODIFIED+. Moving this bug to POST.
The Pulp upstream bug status is at ON_QA. Updating the external tracker on this bug.
The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug.
Any plans to add this also to 6.2.z? To match also the sessionid improvements of Foreman logging doen in 6.2.9?
VERIFIED, i see the logging: pulp_rpm.plugins.importers.yum.sync:INFO: [4b917109] Generating metadata databases. pulp_rpm.plugins.importers.yum.sync:INFO: [4b917109] Determining which units need to be downloaded. py.warnings:WARNING: [4b917109] (19573-05056) /usr/lib/python2.7/site-packages/mongoengine/document.py:324: Deprecation ead py.warnings:WARNING: [4b917109] (19573-05056) object_id = collection.save(doc, **write_concern) py.warnings:WARNING: [4b917109] (19573-05056) pulp_rpm.plugins.importers.yum.purge:INFO: [4b917109] Removing missing units. pulp_rpm.plugins.importers.yum.sync:INFO: [4b917109] Downloading additional units. for the task id 4b917109-ed65-4469-bdc2-f2a0ce7c2347
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. > > For information on the advisory, and where to find the updated files, follow the link below. > > If the solution does not work for you, open a new bug report. > > https://access.redhat.com/errata/RHSA-2018:0336