Bug 1639054 - Repeating traceback in the journal on fresh deployment
Summary: Repeating traceback in the journal on fresh deployment
Keywords:
Status: CLOSED DUPLICATE of bug 1647409
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-octavia
Version: 13.0 (Queens)
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: ---
Assignee: Assaf Muller
QA Contact: Bruna Bonguardo
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-10-14 21:30 UTC by Robin Cernin
Modified: 2022-03-13 15:50 UTC (History)
20 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-05-23 18:21:31 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker OSP-13668 0 None None None 2022-03-13 15:50:40 UTC
Red Hat Knowledge Base (Solution) 3652811 0 None None None 2018-10-14 21:39:41 UTC

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)


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