Bug 1608217

Summary: goferd prints reconnect error whenever qdrouterd is restarted
Product: Red Hat Satellite Reporter: Pavel Moravec <pmoravec>
Component: katello-agentAssignee: satellite6-bugs <satellite6-bugs>
Status: CLOSED CURRENTRELEASE QA Contact: Jan Hutaƙ <jhutar>
Severity: medium Docs Contact:
Priority: medium    
Version: 6.3.2CC: chris.snell, egolov, hmore, janarula, jcrumple, jhutar, jortel, mmccune, pcreech, pmoravec, ramsingh
Target Milestone: ReleasedKeywords: Triaged
Target Release: Unused   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Satellite 6.4.1 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-12-11 16:20:34 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:

Description Pavel Moravec 2018-07-25 06:45:49 UTC
Description of problem:
Whenever qdrouterd is restarted (i.e. due to katello-service restart or just to solely restart qdrouterd), all goferd clients directly connected to that qdrouterd log error messages, despite their connection is bounced only and they are successfully re-connected in a while. That ridiculously raises alarms "some error happens on all these hundreds/thousands of systems" that an operator must manually checked on some monitoring tool.

I think this can have a simple "code workaround" where goferd will try first reconnect not immediately, but after 10 seconds (i.e. follow the same retry scheme like after 1st connection attempt failure). qdrouterd should be already up and should have (I hope) routing table propagated in case of Capsule (at least per my testing).


Version-Release number of selected component (if applicable):
Sat 6.3.2 tools:
- gofer 2.7.7-3
- katello-agent 3.1.0-2


How reproducible:
100%


Steps to Reproduce:
1. Have a goferd connected to qdrouterd on a system registered to Sat or Caps
2. Restart qdrouterd on that Sat / Caps
3. Monitor /var/log/messages (and check if/when goferd re-creates connection to qdrouterd to port 5647)


Actual results:
error like below appears before successful reconnect:
Jul 25 08:41:51 pmoravco-rhel7 goferd: [ERROR][pulp.agent.6be25b22-1aec-4175-b708-a44f2242d22a] gofer.messaging.adapter.proton.reliability:53 - Connection amqps://pmoravec-caps63.gsslab.brq2.redhat.com:5647 disconnected: Condition('amqp:connection:framing-error', 'SSL Failure: Unknown error.')


Expected results:
no such error, successful reconnect


Additional info:

Comment 1 Pavel Moravec 2018-07-25 08:01:33 UTC
goferd already waits the 10 seconds and the error:

Jul 25 09:45:04 pmoravec-caps63 goferd: [ERROR][pulp.agent.d79cc595-3b70-4e8b-8b72-d8482f4b66e9] gofer.messaging.adapter.proton.reliability:53 - Connection amqps://pmoravec-sat63.gsslab.brq2.redhat.com:5647 disconnected: Condition('amqp:connection:framing-error', 'SSL Failure: Unknown error')

is printed by /usr/lib/python2.7/site-packages/gofer/messaging/adapter/proton/reliability.py :

def reliable(fn):
    def _fn(messenger, *args, **kwargs):
        repair = lambda: None
        while not Thread.aborted():
            try:
                repair()
                return fn(messenger, *args, **kwargs)
            except LinkDetached, le:
                if le.condition != NOT_FOUND:
                    log.error(utf8(le))
                    repair = messenger.repair
                    sleep(DELAY)
                else:
                    raise NotFound(*le.args)
            except ConnectionException, pe:
                log.error(utf8(pe))               ###### this line
                repair = messenger.repair
                sleep(DELAY)
    return _fn


Both "log.error(utf8(le))" are called here just when connection has been successfully established but some link or connection error (other than missing pulp.agent.* queue, that is important) is hit. Since goferd will try to reconnect in 10s, these events shall be warning instead of error.

Only missing queue event is worth to be of error verbosity as that means something fishy happening on Satellite qpidd. But that is logged either way via explicit "raise NotFound(*le.args)" and logged as error in gofer.messaging.consumer:74 .

So I suggest both "log.error(utf8(le))" in proton/reliability.py to be changed to warning verbosity.

Jeff, do you agree?

Comment 2 Jeff Ortel 2018-07-25 12:35:03 UTC
Agreed.

Comment 3 Jeff Ortel 2018-07-25 14:19:32 UTC
Requested change completed/merged in the upstream project.  It will be tagged and released in Fedora (updates) and Copr shortly.

https://github.com/jortel/gofer/pull/90
https://github.com/jortel/gofer/pull/92

Comment 4 Brad Buckingham 2018-07-27 19:55:29 UTC
Moving to POST as the 2 PRs referenced in comment 3 have been merged upstream.

Comment 16 Mike McCune 2018-12-11 16:20:34 UTC
We shipped this in 6.4.1 with the update here:

https://bugzilla.redhat.com/show_bug.cgi?id=1646736

I tested the updated builds and see the switch to WARNING vs ERROR.

Closing as CURRENTRELEASE.