Bug 1129817

Summary:	RFE: Add Log Message Identifier for Multi-line Log Messages
Product:	[Retired] Pulp	Reporter:	Brian Bouterse <bmbouter>
Component:	z_other	Assignee:	amacdona <austin>
Status:	CLOSED UPSTREAM	QA Contact:	Preethi Thomas <pthomas>
Severity:	medium	Docs Contact:
Priority:	low
Version:	Master	CC:	pthomas, rbarlow
Target Milestone:	---	Keywords:	Triaged
Target Release:	2.6.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2015-02-19 01:18:52 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:

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