Change in vdsm[master]: virt: Avoid timeout log spam due to channel timeouts

[Vinzenz Feenstra]

Vinzenz Feenstra has uploaded a new change for review.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

virt: Avoid timeout log spam due to channel timeouts

Currently vmchannels.Listener is logging every timeout events every
30 seconds (based on guest_agent_timeout config value):
vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 106.

This patch changes this behaviour to keep track if a timeout has
been logged before and in that case wouldn't log it again until
a new event (like incoming data) has been received.

Change-Id: I82e868ce7c0ab28a9f7983887a097f760c3d0f69
Bug-Url: https://bugzilla.redhat.com/1096312
Signed-off-by: Vinzenz Feenstra 
---
M vdsm/virt/vmchannels.py
1 file changed, 5 insertions(+), 1 deletion(-)

git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/27/27627/1

diff --git a/vdsm/virt/vmchannels.py b/vdsm/virt/vmchannels.py
index d31cd47..b053a64 100644
--- a/vdsm/virt/vmchannels.py
+++ b/vdsm/virt/vmchannels.py
@@ -59,6 +59,7 @@
                                event)
         elif (event & select.EPOLLIN):
             obj = self._channels[fileno]
+            obj['timeout_seen'] = False
             obj['reconnects'] = 0
             try:
                 if obj['read_cb'](obj['opaque']):
@@ -73,6 +74,7 @@

def _prepare_reconnect(self, fileno):
             obj = self._channels.pop(fileno)
+            obj['timeout_seen'] = False
             try:
                 fileno = obj['create_cb'](obj['opaque'])
             except:
@@ -89,7 +91,9 @@
         now = time.time()
         for (fileno, obj) in self._channels.items():
             if (now - obj['read_time']) >= self._timeout:
-                self.log.debug("Timeout on fileno %d.", fileno)
+                if not obj.get('timeout_seen', False):
+                    self.log.debug("Timeout on fileno %d.", fileno)
+                    obj['timeout_seen'] = True
                 try:
                     obj['timeout_cb'](obj['opaque'])
                     obj['read_time'] = now

[Jenkins CI RO]

oVirt Jenkins CI Server has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 1:

Build Successful

http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8780/ : SUCCESS

http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8916/ : SUCCESS

http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7990/ : SUCCESS

Francesco Romani has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 1: Code-Review+1

I like the idea, and looks OK.

[Dan Kenigsberg]

Dan Kenigsberg has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 1:

(1 comment)

http://gerrit.ovirt.org/#/c/27627/1/vdsm/virt/vmchannels.py
File vdsm/virt/vmchannels.py:

Line 90:         """
Line 91:         now = time.time()
Line 92:         for (fileno, obj) in self._channels.items():
Line 93:             if (now - obj['read_time']) >= self._timeout:
Line 94:                 if not obj.get('timeout_seen', False):
I think that the code could be cleaner if we make sure that 'timeout_seen' is always there (with an initial value of False). However, we already have this tristate for 'cooldown'.

So it's your call, Vinzenz.
Line 95:                     self.log.debug("Timeout on fileno %d.", fileno)
Line 96:                     obj['timeout_seen'] = True
Line 97:                 try:
Line 98:                     obj['timeout_cb'](obj['opaque'])

Itamar Heim has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 1:

ping

[Jenkins CI RO]

oVirt Jenkins CI Server has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 2:

Build Failed

http://jenkins.ovirt.org/job/vdsm_master_virt_functional_tests_gerrit/1489/ : There was an infra issue, please contact [e-mail]

http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/10944/ : SUCCESS

http://jenkins.ovirt.org/job/vdsm_master_unit-tests_created/11886/ : SUCCESS

http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/11729/ : SUCCESS

[Vinzenz Feenstra]

Vinzenz Feenstra has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 2: Verified+1

[Vinzenz Feenstra]

Vinzenz Feenstra has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 2:

Verified on RHEL6. Everything still works as expected and timeouts aren't after the first occurrence.

[Dan Kenigsberg]

Dan Kenigsberg has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 2: Code-Review+2

Your call...

[Dan Kenigsberg]

Dan Kenigsberg has submitted this change and it was merged.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

virt: Avoid timeout log spam due to channel timeouts

Currently vmchannels.Listener is logging every timeout events every
30 seconds (based on guest_agent_timeout config value):
vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 106.

This patch changes this behaviour to keep track if a timeout has
been logged before and in that case wouldn't log it again until
a new event (like incoming data) has been received.

Change-Id: I82e868ce7c0ab28a9f7983887a097f760c3d0f69
Bug-Url: https://bugzilla.redhat.com/1096312
Signed-off-by: Vinzenz Feenstra 
Reviewed-on: http://gerrit.ovirt.org/27627
Reviewed-by: Dan Kenigsberg 
---
M vdsm/virt/vmchannels.py
1 file changed, 5 insertions(+), 1 deletion(-)

Approvals:
  Vinzenz Feenstra: Verified
  Dan Kenigsberg: Looks good to me, approved

[Jenkins CI RO]

oVirt Jenkins CI Server has posted comments on this change.

Change subject: virt: Avoid timeout log spam due to channel timeouts
......................................................................

Patch Set 3:

Build Failed

http://jenkins.ovirt.org/job/vdsm_master_verify-error-codes_merged/5710/ : FAILURE

http://jenkins.ovirt.org/job/vdsm_master_create-rpms_merged_test_debug/75/ : SUCCESS

http://jenkins.ovirt.org/job/vdsm_master_unit-tests_merged/3868/ : SUCCESS

http://jenkins.ovirt.org/job/vdsm_master_create-rpms_merged/1733/ : SUCCESS