Description of problem: The Pulp logger divides log messages with newline characters in them into multiple log messages. This can create an interleaving issue where multiple processes all report the same traceback at the same time and it is difficult to read. Loggers can use the PID setting which helps resolve this issue, but that is not on by default, and it also cannot solve cases where multiple threads interleave tracebacks. This RFE requests that when the Pulp logger splits a log message into multiple independent lines, a short but unique identifier be added to the front of each multi-line message so that the user can easily determine which lines go together Potentially the object ID of the original, long message could be used.
The fix will be in server/pulp/server/logs.py in the CompliantSysLogHandler class. Use process_id-thread_id as the identifier. Be aware that there are two ways that messages can get split: 1) For having newlines. Each newline split needs this identifier. 2) For having lines that are too long (>2041 bytes). Each split message also needs this identifier. 1 and 2 can happen in the same message, so watch out for that. The tests for that module are in server/test/unit/server/test_logs.py.
Addressed with pull request https://github.com/pulp/pulp/pull/1159
fixed in pulp 2.6.0-0.2.beta
verified [root@cloud-qe-4 ~]# rpm -qa pulp-server pulp-server-2.6.0-0.5.beta.el7.noarch checked in the log messages for both rhel6 & rhel7 For example el7 Jan 29 10:07:52 cloud-qe-4.idmqe.lab.eng.bos.redhat.com pulp[28902]: celery.worker.job:ERROR: (28902-87040) raise MissingResource(repository=repo_id) Jan 29 10:07:52 cloud-qe-4.idmqe.lab.eng.bos.redhat.com pulp[28902]: celery.worker.job:ERROR: (28902-87040) MissingResource: Missing resource(s): repository=1234foo Jan 29 10:0 el6 Jan 29 10:45:17 gizmo pulp: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[d933ccd8-4d4b-49fd-b5fb-8f4ed251796c] Jan 29 10:45:17 gizmo pulp: celery.worker.job:INFO: Task pulp.server.tasks.repository.sync_with_auto_publish[abdd1e8c-7a6d-4959-be32-6738ac2eb10e] succeeded in 116.79131452s: <pulp.server.async.tasks.TaskResult object at 0x26df450>
Moved to https://pulp.plan.io/issues/245