ironic-inspector logs broken pipe errors on OPTIONS requests

Bug #1691971 reported by Thomas Herve
22
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Ironic Inspector
Fix Released
Low
Unassigned

Bug Description

I see that every couple of seconds in the undercloud logs:

May 19 08:26:37 undercloud ironic-inspector: 2017-05-19 08:26:37.837 6134 INFO werkzeug [-] 192.168.24.1 - - [19/May/2017 08:26:37] "OPTIONS / HTTP/1.0" 200 -
May 19 08:26:37 undercloud ironic-inspector: Traceback (most recent call last):
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 295, in _handle_request_noblock
May 19 08:26:37 undercloud ironic-inspector: self.process_request(request, client_address)
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 321, in process_request
May 19 08:26:37 undercloud ironic-inspector: self.finish_request(request, client_address)
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
May 19 08:26:37 undercloud ironic-inspector: self.RequestHandlerClass(request, client_address, self)
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
May 19 08:26:37 undercloud ironic-inspector: self.finish()
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
May 19 08:26:37 undercloud ironic-inspector: self.wfile.close()
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/socket.py", line 279, in close
May 19 08:26:37 undercloud ironic-inspector: self.flush()
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib64/python2.7/socket.py", line 303, in flush
May 19 08:26:37 undercloud ironic-inspector: self._sock.sendall(view[write_offset:write_offset+buffer_size])
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 385, in sendall
May 19 08:26:37 undercloud ironic-inspector: tail = self.send(data, flags)
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 379, in send
May 19 08:26:37 undercloud ironic-inspector: return self._send_loop(self.fd.send, data, flags)
May 19 08:26:37 undercloud ironic-inspector: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 366, in _send_loop
May 19 08:26:37 undercloud ironic-inspector: return send_method(data, *args)
May 19 08:26:37 undercloud ironic-inspector: error: [Errno 32] Broken pipe

It doesn't seem to be failing, but it'd be nice to remove the ugly traceback.

Revision history for this message
milan k (vetrisko) wrote :

Hi Thomas,

thanks for the report!
What log file exactly are you seeing this log in?
Could you probably attach more context to the bug?

Cheers,
milan

affects: ironic → ironic-inspector
Revision history for this message
Thomas Herve (therve) wrote :

I see that in tripleo undercloud /var/log/messages. ironic-inspect is behind haproxy, and haproxy has a periodic check request to see the service availability. You can see it in triple jobs log, eg http://logs.openstack.org/94/464094/3/check-tripleo/gate-tripleo-ci-centos-7-ovb-ha-oooq/1c37a38/logs/undercloud/var/log/messages.txt.gz

Revision history for this message
milan k (vetrisko) wrote :
Download full text (3.3 KiB)

Hi, just saw the same myself.
I did some searching and this in particular might happen if the other end has already closed the (TCP) connection while inspector is still sending data. Maybe HAProxy's "pings" indeed.

This indeed deserves some catching on the inspector side but may as well need some tuning on the HAProxy end.

Jun 02 12:31:51 undercloud ironic-inspector[7212]: Exception happened during processing of request from ('1Traceback (most recent call last):
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/SocketServer.py", line 295, in _handle_request_noblock
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self.process_request(request, client_address)
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/SocketServer.py", line 321, in process_request
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self.finish_request(request, client_address)
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self.RequestHandlerClass(request, client_address, self)
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self.finish()
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self.wfile.close()
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/socket.py", line 279, in close
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self.flush()
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Jun 02 12:31:51 undercloud ironic-inspector[7212]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 390, in sendall
Jun 02 12:31:51 undercloud ironic-inspector[7212]: tail = self.send(data, flags)
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 384, in send
Jun 02 12:31:51 undercloud ironic-inspector[7212]: return self._send_loop(self.fd.send, data, flags)
Jun 02 12:31:51 undercloud ironic-inspector[7212]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 371, in _send_loop
Jun 02 12:31:51 undercloud ironic-inspector[7212]: return send_method(data, *args)
Jun 02 12:31:51 undercloud ironic-inspector[7212]: error: [Errno 32] Broken pipe
Jun 02 12:31:51 undercloud ironic-inspector[7212]: 2017-06-02 12:31:51.702 7212 INFO werkzeug [-] 192.168.24.1 - - [02/Jun/2017 12:31:51] "OPTIONS / HTTP/1.0" 200 -
Jun 02 12:31:52 undercloud ironic-inspector[7212]: 2017-06-02 12:31:52.656 7212 DEBUG futurist.periodics [-] Submitting periodic callback 'ironic_inspector.main.periodic_update'
Jun 02 12:31:52 undercloud ironic-inspector[7212]: 2017-06-02 12:31:52.661 7212 DEBUG ironic_inspector.firewall [-] DHCP is already disabled, not updating _disable_dhcp /usr/lib/
...

Read more...

Changed in ironic-inspector:
status: New → Confirmed
Revision history for this message
milan k (vetrisko) wrote :

Done some more research on this issue.
The main reason is inspector runs the werkzeug.BaseWSGIServer which in turn uses socketserver.BaseServer that, upon connection error, prints(!!) the error and traceback in socketserver.BaseServer.handle_error.

Once inspector adopts proper WSGI server, this should be an issue no more.

On the bright side, similar issues were addressed in HAProxy configuration for OpenShift before[1][2]

[1] https://bugzilla.redhat.com/show_bug.cgi?id=923611
[2] https://github.com/openshift/origin-server/commit/7a338aeb518966d17193104a3d1b6acda5c101a1

Dmitry Tantsur (divius)
Changed in ironic-inspector:
importance: Undecided → Low
Revision history for this message
Thomas Herve (therve) wrote :

Can we raise the priority of this bug? I don't see any patch in progress for the WSGI server, so it should probably be fixed in haproxy for the itme being? Thanks.

Revision history for this message
Dan Trainor (dtrainor) wrote :

I'm seeing a similar traceback which may be related and provide more information:

Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: 2017-07-12 17:18:03.814 1301 INFO werkzeug [-] 192.168.24.1 - - [12/Jul/2017 17:18:03] "OPTIONS / HTTP/1.0" 200 -
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: Traceback (most recent call last):
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/SocketServer.py", line 295, in _handle_request_noblock
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self.process_request(request, client_address)
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/SocketServer.py", line 321, in process_request
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self.finish_request(request, client_address)
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self.RequestHandlerClass(request, client_address, self)
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self.finish()
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self.wfile.close()
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/socket.py", line 279, in close
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self.flush()
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 390, in sendall
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: tail = self.send(data, flags)
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 384, in send
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: return self._send_loop(self.fd.send, data, flags)
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 371, in _send_loop
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: return send_method(data, *args)
Jul 12 17:18:03 undercloud-split-stack.novalocal ironic-inspector[1301]: error: [Errno 32] Broken pipe

Revision history for this message
Victoria Martinez de la Cruz (vkmc) wrote :

This is affecting me too.

Aug 7 16:33:24 undercloud registry: 192.168.24.1 - - [07/Aug/2017:16:33:24 +0000] "OPTIONS / HTTP/1.0" 200 0 "" ""
Aug 7 16:33:25 undercloud ironic-inspector: 2017-08-07 16:33:25.589 6738 DEBUG futurist.periodics [-] Submitting periodic callback 'ironic_inspector.wsgi_service.periodic_update' _process_scheduled /usr/lib/python2.7/site-packages/futurist/periodics.py:639
Aug 7 16:33:25 undercloud ironic-inspector: 2017-08-07 16:33:25.592 6738 DEBUG ironic_inspector.firewall [-] DHCP is already disabled, not updating _disable_dhcp /usr/lib/python2.7/site-packages/ironic_inspector/firewall.py:143
Aug 7 16:33:25 undercloud registry: 192.168.24.1 - - [07/Aug/2017:16:33:25 +0000] "OPTIONS / HTTP/1.0" 200 0 "" ""
Aug 7 16:33:26 undercloud registry: 192.168.24.1 - - [07/Aug/2017:16:33:26 +0000] "OPTIONS / HTTP/1.0" 200 0 "" ""
Aug 7 16:33:26 undercloud ironic-inspector: 2017-08-07 16:33:26.723 6738 INFO werkzeug [-] 192.168.24.1 - - [07/Aug/2017 16:33:26] "OPTIONS / HTTP/1.0" 200 -
Aug 7 16:33:26 undercloud ironic-inspector: Traceback (most recent call last):
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 295, in _handle_request_noblock
Aug 7 16:33:26 undercloud ironic-inspector: self.process_request(request, client_address)
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 321, in process_request
Aug 7 16:33:26 undercloud ironic-inspector: self.finish_request(request, client_address)
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
Aug 7 16:33:26 undercloud ironic-inspector: self.RequestHandlerClass(request, client_address, self)
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Aug 7 16:33:26 undercloud ironic-inspector: self.finish()
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Aug 7 16:33:26 undercloud ironic-inspector: self.wfile.close()
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/socket.py", line 279, in close
Aug 7 16:33:26 undercloud ironic-inspector: self.flush()
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Aug 7 16:33:26 undercloud ironic-inspector: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 390, in sendall
Aug 7 16:33:26 undercloud ironic-inspector: tail = self.send(data, flags)
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 384, in send
Aug 7 16:33:26 undercloud ironic-inspector: return self._send_loop(self.fd.send, data, flags)
Aug 7 16:33:26 undercloud ironic-inspector: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 371, in _send_loop
Aug 7 16:33:26 undercloud ironic-inspector: return send_method(data, *args)
Aug 7 16:33:26 undercloud ironic-inspector: error: [Errno 32] Broken pipe

Revision history for this message
Michele Baldessari (michele) wrote :

I added the tripleo workaround in the meantime here: https://review.openstack.org/511462 feedback appreciated.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/puppet-tripleo 7.4.5

This issue was fixed in the openstack/puppet-tripleo 7.4.5 release.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/puppet-tripleo 8.1.0

This issue was fixed in the openstack/puppet-tripleo 8.1.0 release.

Changed in ironic-inspector:
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.