Bug 1639054

Summary:	Repeating traceback in the journal on fresh deployment
Product:	Red Hat OpenStack	Reporter:	Robin Cernin <rcernin>
Component:	openstack-octavia	Assignee:	Assaf Muller <amuller>
Status:	CLOSED DUPLICATE	QA Contact:	Bruna Bonguardo <bbonguar>
Severity:	high	Docs Contact:
Priority:	high
Version:	13.0 (Queens)	CC:	bdobreli, bshephar, cgoncalves, dh3, emacchi, ihrachys, jslagle, lpeer, majopela, m.andre, michael.carden, mschuppe, nchandek, njohnston, ojanas, owalsh, rcernin, rhos-maint, sandyada, scohen
Target Milestone:	---	Keywords:	ZStream
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2019-05-23 18:21:31 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:

Description Robin Cernin 2018-10-14 21:30:15 UTC

Description of problem:

After fresh OSP 13 deployment, we can see following tracebacks in the docker.service (dockerd-current)

Oct 14 18:01:41 controller-0 dockerd-current[19433]: time="2018-10-14T18:01:41.362357121Z" level=debug msg="attach: stderr: end"
Oct 14 18:01:41 controller-0 dockerd-current[19433]: time="2018-10-14T18:01:41.362368298Z" level=debug msg="attach: stdout: end"
Oct 14 18:01:41 controller-0 dockerd-current[19433]: time="2018-10-14T18:01:41.362386363Z" level=debug msg="Health check for container b8f19dbbead048030bb1682cf68e3336d0bec09567060d3f2de0b4c7760c255a done (exitCode=0)"
Oct 14 18:01:41 controller-0 dockerd-current[19433]: x.x.x.x - - [14/Oct/2018 18:01:41] "OPTIONS / HTTP/1.0" 200 0
Oct 14 18:01:41 controller-0 dockerd-current[19433]: Traceback (most recent call last):
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/wsgiref/handlers.py", line 86, in run
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.finish_response()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/wsgiref/handlers.py", line 128, in finish_response
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.write(data)
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/wsgiref/handlers.py", line 212, in write
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.send_headers()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/wsgiref/handlers.py", line 270, in send_headers
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.send_preamble()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/wsgiref/handlers.py", line 194, in send_preamble
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     'Date: %s\r\n' % format_date_time(time.time())
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/socket.py", line 324, in write
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.flush()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/socket.py", line 303, in flush
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self._sock.sendall(view[write_offset:write_offset+buffer_size])
Oct 14 18:01:41 controller-0 dockerd-current[19433]: error: [Errno 104] Connection reset by peer
Oct 14 18:01:41 controller-0 dockerd-current[19433]: x.x.x.x - - [14/Oct/2018 18:01:41] "OPTIONS / HTTP/1.0" 500 59
Oct 14 18:01:41 controller-0 dockerd-current[19433]: Traceback (most recent call last):
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 295, in _handle_request_noblock
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.process_request(request, client_address)
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 321, in process_request
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.finish_request(request, client_address)
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.RequestHandlerClass(request, client_address, self)
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.finish()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.wfile.close()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/socket.py", line 279, in close
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self.flush()
Oct 14 18:01:41 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/socket.py", line 303, in flush
Oct 14 18:01:41 controller-0 dockerd-current[19433]:     self._sock.sendall(view[write_offset:write_offset+buffer_size])
Oct 14 18:01:41 controller-0 dockerd-current[19433]: error: [Errno 32] Broken pipe

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

OSP13
nova version
openstack-nova-common-17.0.5-3.d7864fbgit.el7ost.noarch

We have not identified from which container it's coming from.


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

We think this is coming from health checks as it's written out to logs periodically. There are two containers unhealthy:

[root@controller-0 ~]# docker ps | grep unhealthy
3f3506aad44a        192.168.24.1:8787/rhosp13/openstack-gnocchi-statsd:2018-09-28.1              "kolla_start"            12 days ago         Up 12 days (unhealthy)                       gnocchi_statsd
9b77211048c1        192.168.24.1:8787/rhosp13/openstack-nova-placement-api:2018-09-28.1          "kolla_start"            12 days ago         Up 12 days (unhealthy)                       nova_placement

This is coming from:

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

Comment 1 Robin Cernin 2018-10-14 21:38:52 UTC

systemctl status docker.service
..

Oct 14 21:35:33 controller-0 dockerd-current[19433]:     self.RequestHandlerClass(request, client_address, self)
Oct 14 21:35:33 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Oct 14 21:35:33 controller-0 dockerd-current[19433]:     self.finish()
Oct 14 21:35:33 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Oct 14 21:35:33 controller-0 dockerd-current[19433]:     self.wfile.close()
Oct 14 21:35:33 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/socket.py", line 279, in close
Oct 14 21:35:33 controller-0 dockerd-current[19433]:     self.flush()
Oct 14 21:35:33 controller-0 dockerd-current[19433]:   File "/usr/lib64/python2.7/socket.py", line 303, in flush
Oct 14 21:35:33 controller-0 dockerd-current[19433]:     self._sock.sendall(view[write_offset:write_offset+buffer_size])
Oct 14 21:35:33 controller-0 dockerd-current[19433]: error: [Errno 32] Broken pipe


in `/var/log/messages`:


Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 50782)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 50828)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 50882)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 50936)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 51004)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 51332)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 51400)
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: ----------------------------------------
Oct 13 23:24:58 controller-0 journal: Exception happened during processing of request from ('x.x.x.x', 52240)