Bug 1287309 - Undercloud ironic-api fails to restart when updating from 7.1 to 7.2
Summary: Undercloud ironic-api fails to restart when updating from 7.1 to 7.2
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-ironic
Version: 7.0 (Kilo)
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: async
: 7.0 (Kilo)
Assignee: Lucas Alvares Gomes
QA Contact: Toure Dunnon
URL:
Whiteboard:
: 1246525 1291387 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-12-01 23:02 UTC by Marius Cornea
Modified: 2019-10-10 10:36 UTC (History)
12 users (show)

Fixed In Version:
Doc Type: Known Issue
Doc Text:
Cause: Due a bug in the Python SocketServer when the client disconnects suddently it will raise that exception (see http://bugs.python.org/issue14574). New versions of Ironic switched to using oslo.service (https://review.openstack.org/#/c/219298/), so this isn't an issue any more. Consequence: The automatic restart of the service will fail. Workaround (if any): Manually restart the service with "systemctl restart openstack-ironic-api" Result:
Clone Of:
Environment:
Last Closed: 2016-03-02 12:19:34 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
ironic-api.log (3.28 MB, text/plain)
2015-12-01 23:02 UTC, Marius Cornea 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1299854 0 unspecified CLOSED launch-fusor-undercloud-installer aborts with "neutron subnet-update: error: too few arguments" 2021-02-22 00:41:40 UTC

Internal Links: 1299854

Description Marius Cornea 2015-12-01 23:02:18 UTC 
Created attachment 1101139 [details]
ironic-api.log

Description of problem:
The ironic-api service doesn't get restart when updating the undercloud from 7.1 to 7.2.

Version-Release number of selected component (if applicable):
pre-update: openstack-ironic-api-2015.1.1-4.el7ost.noarch
post-update: openstack-ironic-api-2015.1.2-2.el7ost.noarch

How reproducible:
100%

Steps to Reproduce:
1. yum update on the undercloud node 
2. systemctl status openstack-ironic-api.service


Actual results:
● openstack-ironic-api.service - OpenStack Ironic API service
   Loaded: loaded (/usr/lib/systemd/system/openstack-ironic-api.service; enabled; vendor preset: disable
   Active: failed (Result: exit-code) since Tue 2015-12-01 17:47:12 EST; 1min 44s ago
 Main PID: 1118 (code=exited, status=1/FAILURE)

Expected results:
The service is restarted.

Additional info:
Attaching ironic-api.log
Comment 2 James Slagle 2015-12-02 20:38:46 UTC 
as we're just doing a straightforward yum update to update the undercloud, this is likely a bug in the ironic packaging. the systemd macros need to be in place to make sure the ironic services are restarted.
Comment 3 Mike Burns 2015-12-03 20:14:43 UTC 
Just a note here, ironic-api does have the correct systemd restart on %postun.

There is an error in the attached log:

2015-12-01 17:46:58.354 1118 DEBUG keystonemiddleware.auth_token [-] Received request from user: user_id 15b5e215f5764b18819c613347271bf7, project_id f6085570ad754f22b8236b3b7d3aac38, roles _member_,admin service: user_id None, project_id None, roles None __call__ /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:632
2015-12-01 17:46:58.360 1118 DEBUG oslo_policy.openstack.common.fileutils [-] Reloading cached file /etc/ironic/policy.json read_cached_file /usr/lib/python2.7/site-packages/oslo_policy/openstack/common/fileutils.py:64
2015-12-01 17:46:58.362 1118 DEBUG oslo_policy.policy [-] Reloaded policy file: /etc/ironic/policy.json _load_policy_file /usr/lib/python2.7/site-packages/oslo_policy/policy.py:403
2015-12-01 17:47:11.964 1118 CRITICAL ironic [-] IOError: [Errno 32] Broken pipe
2015-12-01 17:47:11.964 1118 TRACE ironic Traceback (most recent call last):
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/bin/ironic-api", line 10, in <module>
2015-12-01 17:47:11.964 1118 TRACE ironic     sys.exit(main())
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib/python2.7/site-packages/ironic/cmd/api.py", line 60, in main
2015-12-01 17:47:11.964 1118 TRACE ironic     wsgi.serve_forever()
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib64/python2.7/SocketServer.py", line 238, in serve_forever
2015-12-01 17:47:11.964 1118 TRACE ironic     self._handle_request_noblock()
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib64/python2.7/SocketServer.py", line 297, in _handle_request_noblock
2015-12-01 17:47:11.964 1118 TRACE ironic     self.handle_error(request, client_address)
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib64/python2.7/SocketServer.py", line 354, in handle_error
2015-12-01 17:47:11.964 1118 TRACE ironic     traceback.print_exc() # XXX But this goes to stderr!
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib64/python2.7/traceback.py", line 232, in print_exc
2015-12-01 17:47:11.964 1118 TRACE ironic     print_exception(etype, value, tb, limit, file)
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib64/python2.7/traceback.py", line 124, in print_exception
2015-12-01 17:47:11.964 1118 TRACE ironic     _print(file, 'Traceback (most recent call last):')
2015-12-01 17:47:11.964 1118 TRACE ironic   File "/usr/lib64/python2.7/traceback.py", line 13, in _print
2015-12-01 17:47:11.964 1118 TRACE ironic     file.write(str+terminator)
2015-12-01 17:47:11.964 1118 TRACE ironic IOError: [Errno 32] Broken pipe
2015-12-01 17:47:11.964 1118 TRACE ironic
Comment 4 Lucas Alvares Gomes 2015-12-04 12:21:57 UTC 
Hi Marius,

Thanks for the patch, I see IOError in the logs when the Ironic API tries to reload it.

Can you check if the /etc/ironic/policy.json exists ? And if so, what are the permissions on it? Does the ironic user can read that file?

Thanks
Comment 5 Lucas Alvares Gomes 2015-12-04 12:26:27 UTC 
Also, if you manually restart the API services, does it work?
Comment 6 Marius Cornea 2015-12-04 12:37:28 UTC 
Hi Lucas,

Here is the requested info. I haven't tried restarting it manually right after the update is complete but I can confirm it starts ok after rebooting the undercloud.

stack@instack:~>>> ls -l /etc/ironic/policy.json
-rw-r-----. 1 root ironic 115 Oct 13 13:53 /etc/ironic/policy.json
stack@instack:~>>> sudo -u ironic head -5 /etc/ironic/policy.json 
{
    "admin_api": "role:admin or role:administrator",
    "show_password": "!",
    "default": "rule:admin_api"
}

Thanks
Comment 7 Dmitry Tantsur 2015-12-08 12:08:01 UTC 
> as we're just doing a straightforward yum update to update the undercloud, this is likely a bug in the ironic packaging. the systemd macros need to be in place to make sure the ironic services are restarted.

FWIW this never worked for me, neither for ironic not for discoverd. But it didn't cause failures, just 'systemctl status' used to show "unit file has changed, you need to do systemctl reload".
Comment 8 Marius Cornea 2015-12-08 14:21:37 UTC 
The service does start after manually restarting it right after the update is completed but the journal still shows errors:

stack@instack:~>>> systemctl status openstack-ironic-api.service
● openstack-ironic-api.service - OpenStack Ironic API service
   Loaded: loaded (/usr/lib/systemd/system/openstack-ironic-api.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Tue 2015-12-08 09:10:07 EST; 7min ago
 Main PID: 28435 (code=exited, status=1/FAILURE)

stack@instack:~>>> sudo systemctl restart openstack-ironic-api.service

stack@instack:~>>> systemctl status openstack-ironic-api.service
● openstack-ironic-api.service - OpenStack Ironic API service
   Loaded: loaded (/usr/lib/systemd/system/openstack-ironic-api.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2015-12-08 09:18:16 EST; 1s ago
 Main PID: 25715 (ironic-api)
   CGroup: /system.slice/openstack-ironic-api.service
           └─25715 /usr/bin/python2 /usr/bin/ironic-api

stack@instack:~>>> sudo journalctl -f -u openstack-ironic-api.service
-- Logs begin at Tue 2015-12-08 05:48:02 EST. --
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: self.wfile.close()
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/socket.py", line 279, in close
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: self.flush()
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: tail = self.send(data, flags)
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: total_sent += fd.send(data[total_sent:], flags)
Dec 08 09:20:32 instack.localdomain ironic-api[25715]: error: [Errno 32] Broken pipe
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: 192.0.2.1 - - [08/Dec/2015 09:20:34] "GET / HTTP/1.0" 200 336
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: Traceback (most recent call last):
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 86, in run
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.finish_response()
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 128, in finish_response
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.write(data)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 212, in write
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.send_headers()
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 271, in send_headers
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self._write(str(self.headers))
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/socket.py", line 324, in write
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.flush()
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: tail = self.send(data, flags)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: total_sent += fd.send(data[total_sent:], flags)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: error: [Errno 104] Connection reset by peer
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: 192.0.2.1 - - [08/Dec/2015 09:20:34] "GET / HTTP/1.0" 500 59
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: Traceback (most recent call last):
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/SocketServer.py", line 593, in process_request_thread
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.finish_request(request, client_address)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.RequestHandlerClass(request, client_address, self)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.finish()
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.wfile.close()
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/socket.py", line 279, in close
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self.flush()
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: tail = self.send(data, flags)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: total_sent += fd.send(data[total_sent:], flags)
Dec 08 09:20:34 instack.localdomain ironic-api[25715]: error: [Errno 32] Broken pipe
Comment 9 Lucas Alvares Gomes 2015-12-09 12:00:22 UTC 
Hi @Marius,

Thanks for testing it, it seems that this is related to this bug upstream [0], we've also switched upstream to use oslo.service in the api [1] and this may sort out this problem (as indicate the last comment in the bug [0]).


[0] https://bugs.launchpad.net/ironic/+bug/1296833
[1] https://review.openstack.org/#/c/219298/
Comment 13 Raviv Bar-Tal 2015-12-15 12:51:20 UTC 
*** Bug 1246525 has been marked as a duplicate of this bug. ***
Comment 14 Mike Burns 2016-01-27 15:25:45 UTC 
*** Bug 1291387 has been marked as a duplicate of this bug. ***
Note You need to log in before you can comment on or make changes to this bug.