Bug 1095914

Summary:	Log messages are being interpolated by syslog_logger.rb, causing random app operation failures
Product:	OpenShift Online	Reporter:	Dan Mace <dmace>
Component:	Containers	Assignee:	Dan Mace <dmace>
Status:	CLOSED CURRENTRELEASE	QA Contact:	libra bugs <libra-bugs>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	2.x	CC:	bmeng, dakini, ryanj
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:
Clones:	1096900 (view as bug list)		Environment:
Last Closed:	2014-07-15 10:28:51 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:
Bug Depends On:
Bug Blocks:	1096900

Description Dan Mace 2014-05-08 20:00:17 UTC

Description of problem:

The syslog_logger.rb implementation in openshift-origin-node is making incorrect use of the Ruby syslog library. The code is treating the format string parameter as a formatted message parameter. This causes the raw input string (a log message) to be interpolated underneath in the syslog implementation. Any log messages dispatched via this code which contain the '%' character can result in exceptions unless followed by another character that happens to make the string conform to the printf substitution rules. These exceptions can occur anywhere in the openshift-origin-node code, or the MCollective agent.

The code should be changed to use a generic '%s' format string, passing the processed log message as the format args. This will make the call log the input verbatim.

Version-Release number of selected component (if applicable):

How reproducible:

Configure platform logging for syslog via /etc/openshift/node.conf:

PLATFORM_LOG_CLASS=SyslogLogger
PLATFORM_SYSLOG_THRESHOLD=LOG_INFO
PLATFORM_SYSLOG_TRACE_ENABLED=1
PLATFORM_LOG_FILE=/var/log/openshift/node/platform.log
PLATFORM_LOG_LEVEL=INFO
PLATFORM_TRACE_LOG_FILE=/var/log/openshift/node/platform-trace.log
PLATFORM_TRACE_LOG_LEVEL=DEBUG
PLATFORM_LOG_CONTEXT_ENABLED=1
PLATFORM_LOG_CONTEXT_ATTRS=request_id,app_uuid

One example that happens to easily produce the offending log messages is:

rhc app create sinkerror jbossas-7 -pp --no-git --noprompt --from-code=git://github.com/openshift/kitchensink-example.git

Steps to Reproduce:
1.
2.
3.

Actual results:

The MCollective agent will crash with an exception such as:

May 8 12:45:45 ex-std-node3 mcollectived[1965]: agents.rb:139:in `rescue in block in dispatch' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.23.9/lib/openshift-origin-node/utils/logger/syslog_logger.rb:61:in `log'
...

The app will fail to be created due to the crash.

Expected results:

Correct log output to Syslog and a successfully created application.

Additional info:

Comment 1 Dan Mace 2014-05-08 20:24:24 UTC

https://github.com/openshift/origin-server/pull/5401

Comment 2 Meng Bo 2014-05-09 03:36:26 UTC

Checked on devenv-stage_830, issue has been fixed.

With the platform log send to syslog set as comment#0 in node.conf, created the kitchensink jbossas app several times.

And no error found in /var/log/ruby193-mcollective.log

Move bug to verified.

Comment 3 ryanj 2014-05-12 20:29:12 UTC

This command is failing frequently for me in production (estimating 80%+ failure rate):

    rhc app create eapmongo jbosseap-6 mongodb-2.4

Please include it in your test cases.