Bug 1457468 - Broker logs need a major improvement
Summary: Broker logs need a major improvement
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-hosted-engine-ha
Classification: oVirt
Component: Broker
Version: 2.1.0.5
Hardware: Unspecified
OS: Unspecified
medium
high
Target Milestone: ovirt-4.2.0
: ---
Assignee: Denis Chaplygin
QA Contact: Nikolai Sednev
URL:
Whiteboard:
Depends On: 1487915
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-05-31 18:56 UTC by Yaniv Kaul
Modified: 2019-04-28 13:24 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: No Doc Update
Doc Text:
Broker logs have been streamlined by removing entries that provide no information.
Clone Of:
Environment:
Last Closed: 2017-12-20 11:38:44 UTC
oVirt Team: SLA
Embargoed:
rule-engine: ovirt-4.2+
gklein: testing_plan_complete-


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 81083 0 master MERGED rpc: Custom made RPC replaced with xmlrpc 2021-02-17 16:34:31 UTC

Description Yaniv Kaul 2017-05-31 18:56:34 UTC
Description of problem:
Currently, they provide very little value.
They need to through a major improvement, to provide value.
Example of current log:
Thread-3294582::INFO::2017-05-29 15:28:25,860::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294583::INFO::2017-05-29 15:28:25,860::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294583::INFO::2017-05-29 15:28:25,861::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-23::INFO::2017-05-29 15:28:25,879::mem_free::50::mem_free.MemFree::(action) memFree: 511353
Thread-3294584::INFO::2017-05-29 15:28:29,950::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294584::INFO::2017-05-29 15:28:30,045::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294585::INFO::2017-05-29 15:28:30,045::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294585::INFO::2017-05-29 15:28:30,163::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294586::INFO::2017-05-29 15:28:30,165::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294586::INFO::2017-05-29 15:28:30,167::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294587::INFO::2017-05-29 15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294587::INFO::2017-05-29 15:28:30,168::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294588::INFO::2017-05-29 15:28:30,168::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294588::INFO::2017-05-29 15:28:30,169::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294589::INFO::2017-05-29 15:28:30,170::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294589::INFO::2017-05-29 15:28:30,170::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294590::INFO::2017-05-29 15:28:30,171::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294590::INFO::2017-05-29 15:28:30,171::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294591::INFO::2017-05-29 15:28:30,172::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294591::INFO::2017-05-29 15:28:30,172::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294592::INFO::2017-05-29 15:28:30,173::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established


Or this:
Thread-23::INFO::2017-05-29 15:28:55,687::mem_free::50::mem_free.MemFree::(action) memFree: 511358
Thread-25::INFO::2017-05-29 15:28:59,684::engine_health::55::engine_health.CpuLoadNoEngine::(action) VM not on this host

Comment 1 Yaniv Kaul 2017-06-14 10:49:18 UTC
Targeting 4.2.

Comment 2 Moran Goldboim 2017-06-26 10:12:19 UTC
Yaniv, any specific items you would like to see there? it doesn't has any functional aspects, so medium priority from my side, unless certain critical info is missing.

Comment 3 Yaniv Kaul 2017-06-26 10:16:54 UTC
(In reply to Moran Goldboim from comment #2)
> Yaniv, any specific items you would like to see there? it doesn't has any
> functional aspects, so medium priority from my side, unless certain critical
> info is missing.

Today they provide no value whatsoever (see above). They flood and do not provide value. For example (note the time, all in the same 0.01 second!):
15:28:30,163::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294586::INFO::2017-05-29 15:28:30,165::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294586::INFO::2017-05-29 15:28:30,167::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294587::INFO::2017-05-29 15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294587::INFO::2017-05-29 15:28:30,168::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294588::INFO::2017-05-29 15:28:30,168::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294588::INFO::2017-05-29 15:28:30,169::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed
Thread-3294589::INFO::2017-05-29 

This is critical for supportability.

It may be that the underlying infra is wrong (why are we opening-closing connections that fast, with no sleep whatsoever, etc.).

Comment 4 Nikolai Sednev 2017-09-17 13:05:29 UTC
After successful deployment of ovirt-hosted-engine-setup-2.2.0-0.0.master.20170913082146.git120d800.el7.centos.noarch, while using ovirt-engine-appliance-4.2-20170916.1.el7.centos.noarch, I'm still getting the same type of logging from /var/log/ovirt-hosted-engine-ha/broker.log e.g.

Thread-3::INFO::2017-09-17 15:57:36,693::mem_free::50::mem_free.MemFree::(action) memFree: 23950
Thread-3::INFO::2017-09-17 15:57:46,739::mem_free::50::mem_free.MemFree::(action) memFree: 23925

Thread-5::INFO::2017-09-17 12:56:41,624::engine_health::55::engine_health.CpuLoadNoEngine::(action) VM not on this host

I didn't seen this type though: "15:28:30,173::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established", it didn't appeared on my environment after deployment.

Moving back to assigned, as I don't see the difference between logging in previous version vs. current.

Comment 5 Denis Chaplygin 2017-09-18 08:01:44 UTC
You should not see anymore useless lines like:

15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(setup) Connection established
Thread-3294587::INFO::2017-05-29 15:28:30,168::listener::186::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Connection closed

Could you please confirm, that they are still in logs?


Other lines, like monitors reporting their values, should stay in logs, as they contain important runtime information.

Comment 6 Nikolai Sednev 2017-09-18 09:13:06 UTC
(In reply to Denis Chaplygin from comment #5)
> You should not see anymore useless lines like:
> 
> 15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.
> ConnectionHandler::(setup) Connection established
> Thread-3294587::INFO::2017-05-29
> 15:28:30,168::listener::186::ovirt_hosted_engine_ha.broker.listener.
> ConnectionHandler::(handle) Connection closed
> 
> Could you please confirm, that they are still in logs?
> 
> 
> Other lines, like monitors reporting their values, should stay in logs, as
> they contain important runtime information.

As I already reported previously, these lines are not happening.
From initial bug report I saw that Yaniv also wanted to get better logging for these lines:
Thread-23::INFO::2017-05-29 15:28:55,687::mem_free::50::mem_free.MemFree::(action) memFree: 511358
Thread-25::INFO::2017-05-29 15:28:59,684::engine_health::55::engine_health.CpuLoadNoEngine::(action) VM not on this host

In case that current fix isolating only "15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.
> ConnectionHandler::(setup) Connection established" and this is fine, then we may move to verified.

Yaniv, may you provide your input on this please?

Comment 7 Yaniv Kaul 2017-09-18 10:24:41 UTC
(In reply to Nikolai Sednev from comment #6)
> (In reply to Denis Chaplygin from comment #5)
> > You should not see anymore useless lines like:
> > 
> > 15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.
> > ConnectionHandler::(setup) Connection established
> > Thread-3294587::INFO::2017-05-29
> > 15:28:30,168::listener::186::ovirt_hosted_engine_ha.broker.listener.
> > ConnectionHandler::(handle) Connection closed
> > 
> > Could you please confirm, that they are still in logs?
> > 
> > 
> > Other lines, like monitors reporting their values, should stay in logs, as
> > they contain important runtime information.
> 
> As I already reported previously, these lines are not happening.
> From initial bug report I saw that Yaniv also wanted to get better logging
> for these lines:
> Thread-23::INFO::2017-05-29
> 15:28:55,687::mem_free::50::mem_free.MemFree::(action) memFree: 511358
> Thread-25::INFO::2017-05-29
> 15:28:59,684::engine_health::55::engine_health.CpuLoadNoEngine::(action) VM
> not on this host
> 
> In case that current fix isolating only
> "15:28:30,167::listener::134::ovirt_hosted_engine_ha.broker.listener.
> > ConnectionHandler::(setup) Connection established" and this is fine, then we may move to verified.
> 
> Yaniv, may you provide your input on this please?

Per comment 5 they should stay in the logs. Moving to VERIFIED.
Thanks!

Comment 8 Sandro Bonazzola 2017-12-20 11:38:44 UTC
This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017.

Since the problem described in this bug report should be
resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.


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