Bug 1383108

Summary: ovirt-ha-broker logs excessive amounts of information
Product: Red Hat Enterprise Virtualization Manager Reporter: Marcus West <mwest>
Component: vdsmAssignee: Simone Tiraboschi <stirabos>
Status: CLOSED DUPLICATE QA Contact: Pavel Stehlik <pstehlik>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 4.0.3CC: bazulay, bmcclain, gklein, lsurette, mkalinin, mperina, oourfali, pkliczew, srevivo, warlord, ycui, ykaul
Target Milestone: ovirt-4.2.0Keywords: Reopened
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard: infra
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-02-07 17:19:29 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Integration RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1349829, 1417708, 1417709    
Bug Blocks:    

Description Marcus West 2016-10-10 00:25:32 UTC
Description of problem:

Is it necessary for ovirt-ha-broker and ovirt-ha-agent to log so much information?

# grep ^Oct..9 /var/log/messages |grep ovirt-ha |wc -l
300946     # 40MB of data per day

An example of current ouptut:

Oct 10 09:50:40 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection established
Oct 10 09:50:40 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection closed
Oct 10 09:50:40 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection established
Oct 10 09:50:40 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection established
Oct 10 09:50:40 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection closed
Oct 10 09:50:40 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection closed
Oct 10 09:50:41 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:41 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 kernel: dd: sending ioctl 80306d02 to a partition!
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection established
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection closed
Oct 10 09:50:42 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection established
Oct 10 09:50:42 intelh6 kernel: dd: sending ioctl 80306d02 to a partition!
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection closed
Oct 10 09:50:42 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection established
Oct 10 09:50:42 intelh6 ovirt-ha-broker: INFO:ovirt_hosted_engine_ha.broker.listener.ConnectionHandler:Connection closed
Oct 10 09:50:42 intelh6 ovirt-ha-agent: /usr/lib/python2.7/site-packages/yajsonrpc/stomp.py:352: DeprecationWarning: Dispatcher.pending is deprecated. Use Dispatcher.socket.pending instead.
Oct 10 09:50:42 intelh6 ovirt-ha-agent: pending = getattr(dispatcher, 'pending', lambda: 0)
Oct 10 09:50:42 intelh6 kernel: dd: sending ioctl 80306d02 to a partition!

Information is not only excessive, but not helpful in resolving issues.

Versions:

ovirt-hosted-engine-ha-2.0.4-1.el7ev.noarch

Expected Results:

Ideally, should only log to /var/log/messages if there is an actual error.  We can keep the 'informational' logging in the specific application log if necessary (/var/log/ovirt-hosted-engine-ha/{agent,broker}.log)

Comment 2 Germano Veit Michel 2016-10-10 00:33:59 UTC
We need to get rid of that "DeprecationWarning" in the logs. It's really spamming logs in 4.0.

Comment 3 Marcus West 2016-10-10 05:31:40 UTC
These SSL errors in vdsm.log also seem to be related (or maybe not).  They stop when I switch off the agent and broker.

JsonRpc (StompReactor)::ERROR::2016-10-10 10:04:35,392::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:04:49,888::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:04:56,290::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:04,818::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:10,254::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:14,822::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:29,427::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:35,884::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:44,469::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:49,927::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:05:54,468::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:08,959::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:15,596::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:24,029::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:29,539::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:34,066::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:48,558::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:06:54,909::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:03,341::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:08,792::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:13,392::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:28,223::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:34,641::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:43,040::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:07:48,490::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof
JsonRpc (StompReactor)::ERROR::2016-10-10 10:08:01,131::betterAsyncore::113::vds.dispatcher::(recv) SSL error during reading data: unexpected eof

Comment 4 Martin Sivák 2016-10-17 10:52:52 UTC
This is all logged by the jsonrpc library. Hosted engine has no way to influence that.

Comment 5 Piotr Kliczewski 2016-10-18 09:29:59 UTC
The deprication was fixed by above patches and extensive ssl errors are due to not correct way of using the client BZ #1349829 so marking it as duplicate.

*** This bug has been marked as a duplicate of bug 1349829 ***

Comment 11 Piotr Kliczewski 2016-11-14 14:04:31 UTC
Marina,

It is correct. We need this bug to track it. I am reopening it add adding dependency.

Comment 15 Sandro Bonazzola 2017-02-07 17:19:29 UTC

*** This bug has been marked as a duplicate of bug 1417708 ***