Bug 1129817 - RFE: Add Log Message Identifier for Multi-line Log Messages
Summary: RFE: Add Log Message Identifier for Multi-line Log Messages
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Pulp
Classification: Retired
Component: z_other
Version: Master
Hardware: Unspecified
OS: Unspecified
low
medium
Target Milestone: ---
: 2.6.0
Assignee: amacdona@redhat.com
QA Contact: Preethi Thomas
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-13 17:48 UTC by Brian Bouterse
Modified: 2015-02-28 23:42 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-02-19 01:18:52 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Pulp Redmine 245 None None None Never

Description Brian Bouterse 2014-08-13 17:48:46 UTC
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.

Comment 1 Randy Barlow 2014-09-12 15:13:07 UTC
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.

Comment 2 amacdona@redhat.com 2014-09-16 11:50:20 UTC
Addressed with pull request https://github.com/pulp/pulp/pull/1159

Comment 3 Chris Duryee 2014-12-23 20:52:35 UTC
fixed in pulp 2.6.0-0.2.beta

Comment 4 Preethi Thomas 2015-01-29 15:46:08 UTC
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>

Comment 5 Brian Bouterse 2015-02-19 01:18:52 UTC
Moved to https://pulp.plan.io/issues/245


Note You need to log in before you can comment on or make changes to this bug.