Bug 977269

Summary: Handle keep-alive for XML-RPC connections in lab controller daemons in Fedora (18+)/Python 2.7
Product: [Retired] Beaker Reporter: Amit Saha <asaha>
Component: lab controllerAssignee: Amit Saha <asaha>
Status: CLOSED CURRENTRELEASE QA Contact: tools-bugs <tools-bugs>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: developCC: aigao, asaha, dcallagh, ebaak, llim, qwan, rmancy, xjia
Target Milestone: 0.14   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-08-09 03:23:51 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 Amit Saha 2013-06-24 08:06:49 UTC 
Description of problem:

Python 2.7 introduced a few changes to the way XML-RPC client server connections are handled by supporting HTTP/1.1 keep-alive (http://docs.python.org/dev/whatsnew/2.7.html).

This causes problems in Beaker lab controller daemons (beaker-proxy and beaker-provision) since it python-daemon DaemonContext closes all the open descriptors. Hence, when an attempt is made to use the proxy object (Which was supposed to be open due to keep-alive) it crashes:

hub.py:338:switch:SystemError: (libev) epoll_wait: Invalid argument
 
Traceback (most recent call last):
  File "/bin/beaker-provision", line 9, in <module>
    load_entry_point('bkr.labcontroller==0.13.1', 'console_scripts', 'beaker-provision')()
  File "/usr/lib/python2.7/site-packages/bkr/labcontroller/provision.py", line 258, in main
    main_loop(poller=poller, conf=conf, foreground=False)
  File "/usr/lib/python2.7/site-packages/bkr/labcontroller/provision.py", line 217, in main_loop
    poller.clear_running_commands(u'Stale command cleared on startup')
  File "/usr/lib/python2.7/site-packages/bkr/labcontroller/provision.py", line 44, in clear_running_commands
    self.hub.labcontrollers.clear_running_commands(message)
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1224, in __call__
    return self.__send(self.__name, args)
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1578, in __request
    verbose=self.__verbose
  File "/usr/lib/python2.7/site-packages/kobo/xmlrpc.py", line 572, in request
    result = transport_class.request(self, *args, **kwargs)
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1264, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/lib/python2.7/site-packages/kobo/xmlrpc.py", line 450, in _single_request
    self.send_content(h, request_body)
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1439, in send_content
    connection.endheaders(request_body)
  File "/usr/lib64/python2.7/httplib.py", line 954, in endheaders
    self._send_output(message_body)
  File "/usr/lib64/python2.7/httplib.py", line 814, in _send_output
    self.send(msg)
  File "/usr/lib64/python2.7/httplib.py", line 776, in send
    self.connect()
  File "/usr/lib64/python2.7/httplib.py", line 757, in connect
    self.timeout, self.source_address)
  File "/usr/lib64/python2.7/site-packages/gevent/socket.py", line 592, in create_connection
    sock.connect(sa)
  File "/usr/lib64/python2.7/site-packages/gevent/socket.py", line 338, in connect
    self._wait(self._write_event)
  File "/usr/lib64/python2.7/site-packages/gevent/socket.py", line 289, in _wait
    self.hub.wait(watcher)
  File "/usr/lib64/python2.7/site-packages/gevent/hub.py", line 349, in wait
    result = self.switch()
  File "/usr/lib64/python2.7/site-packages/gevent/hub.py", line 338, in switch
    return greenlet.switch(self)
SystemError: (libev) epoll_wait: Invalid argument


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


How reproducible:

Always, run beaker server in Apache and attempt to start beaker-provision using service beaker-provision start.


Steps to Reproduce:
1.
2.
3.

Actual results:

Crash

Expected results:

Running as expected.


Additional info:

If the  connection is closed before daemonizing, the crash doesn't occur. 
dcallagh suggested the following fix which works:

if sys.version_info >= (2, 7):
       # force xmlrpclib.ServerProxy's persistent HTTP connection to be
       # closed, it will be reopened on the next call after daemonizing
       proxy.hub._hub('close')()
Comment 1 Amit Saha 2013-06-25 03:19:51 UTC 
On Gerrit: http://gerrit.beaker-project.org/#/c/2056/
Comment 5 Amit Saha 2013-07-16 00:25:34 UTC 
I think the only way to verify this is to actually set up a Beaker test environment on Fedora (Python 2.7): 

http://gerrit.beaker-project.org/#/c/2072/1/dev/guide/virtual-fedora/virtual-fedora.rst

Not sure if there are any less involved ways..
Comment 6 Amit Saha 2013-07-16 00:29:18 UTC 
(In reply to Amit Saha from comment #5)
> I think the only way to verify this is to actually set up a Beaker test
> environment on Fedora (Python 2.7): 
> 
> http://gerrit.beaker-project.org/#/c/2072/1/dev/guide/virtual-fedora/virtual-
> fedora.rst
> 
> Not sure if there are any less involved ways..

To be clearer, to verify you need to make sure that the lab controller daemons: beaker-provision, beaker-watchdog and beaker-proxy are all running (and do not die after starting). beaker-proxy needs the Beaker server to be running, which needs Apache and MySql server to be running...
Comment 7 xjia 2013-07-17 03:23:28 UTC 
Will verify it until I can setup beaker env locally.
Comment 8 xjia 2013-07-22 10:09:59 UTC 
[root@jasontest ~]# ssh 10.66.8.148
Last login: Fri Jul 19 21:09:27 2013 from dhcp-65-98.nay.redhat.com
[root@dhcp-8-148 ~]#
[root@dhcp-8-148 ~]#
[root@dhcp-8-148 ~]#
[root@dhcp-8-148 ~]# ssh 192.168.122.102
root.122.102's password:
Last login: Fri Jul 19 09:09:34 2013 from 192.168.122.1
[root@beaker-server-lc ~]# service mysqld status
Redirecting to /bin/systemctl status  mysqld.service
mysqld.service - MySQL database server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled)
   Active: active (running) since Wed 2013-07-17 17:43:42 EDT; 4 days ago
 Main PID: 1543 (mysqld_safe)
   CGroup: name=systemd:/system/mysqld.service
           ├─1543 /bin/sh /usr/bin/mysqld_safe --basedir=/usr
           └─1736 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql...

Jul 17 17:43:40 beaker-server-lc.beaker systemd[1]: Starting MySQL database s...
Jul 17 17:43:40 beaker-server-lc.beaker mysqld_safe[1543]: 130717 17:43:40 my...
Jul 17 17:43:40 beaker-server-lc.beaker mysqld_safe[1543]: 130717 17:43:40 my...
Jul 17 17:43:42 beaker-server-lc.beaker systemd[1]: Started MySQL database se...
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# service beaker-provision status
beaker-provision.service - SYSV: This service acts on queued commands from the Beaker server by
   Loaded: loaded (/etc/rc.d/init.d/beaker-provision)
   Active: active (running) since Fri 2013-07-19 01:45:10 EDT; 3 days ago
  Process: 18387 ExecStop=/etc/rc.d/init.d/beaker-provision stop (code=exited, status=0/SUCCESS)
  Process: 18395 ExecStart=/etc/rc.d/init.d/beaker-provision start (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/beaker-provision.service
           `-18407 /usr/bin/python /bin/beaker-provision

Jul 22 05:59:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 05:59:45 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:00:05 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:00:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:00:45 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:01:05 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:01:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:01:45 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:02:05 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:02:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# service beaker-watchdog status
beaker-watchdog.service - SYSV: This service handles watchdogs
   Loaded: loaded (/etc/rc.d/init.d/beaker-watchdog)
   Active: active (running) since Fri 2013-07-19 01:45:16 EDT; 3 days ago
  Process: 18450 ExecStop=/etc/rc.d/init.d/beaker-watchdog stop (code=exited, status=0/SUCCESS)
  Process: 18455 ExecStart=/etc/rc.d/init.d/beaker-watchdog start (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/beaker-watchdog.service
           `-18461 /usr/bin/python /bin/beaker-watchdog

Jul 22 06:01:23 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:01:44 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:01:44 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:01:44 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:02:04 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:02:04 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:02:04 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:02:24 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:02:24 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
Jul 22 06:02:24 beaker-server-lc.beaker beaker-watchdog[18461]: bkr.labcontro...
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# service beaker-proxy status
beaker-proxy.service - SYSV: This service proxies unauthenticated requests from the lab
   Loaded: loaded (/etc/rc.d/init.d/beaker-proxy)
   Active: active (running) since Fri 2013-07-19 01:45:35 EDT; 3 days ago
  Process: 18506 ExecStop=/etc/rc.d/init.d/beaker-proxy stop (code=exited, status=0/SUCCESS)
  Process: 18511 ExecStart=/etc/rc.d/init.d/beaker-proxy start (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/beaker-proxy.service
           `-18516 /usr/bin/python /bin/beaker-proxy

Jul 21 21:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 21 22:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 21 23:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 00:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 01:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 02:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 03:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 04:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 05:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
Jul 22 06:01:01 beaker-server-lc.beaker beaker-proxy[18516]: bkr.labcontrolle...
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# service beakerd status
beakerd.service - SYSV: This service is the core of the Beaker Scheduler
   Loaded: loaded (/etc/rc.d/init.d/beakerd)
   Active: active (running) since Fri 2013-07-19 01:44:55 EDT; 3 days ago
  Process: 18301 ExecStop=/etc/rc.d/init.d/beakerd stop (code=exited, status=0/SUCCESS)
  Process: 18308 ExecStart=/etc/rc.d/init.d/beakerd start (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/beakerd.service
           `-18323 /usr/bin/python /bin/beakerd

Jul 19 09:28:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:28:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:28:36 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:28:36 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:28:36 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:29:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:29:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
Jul 19 09:29:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.model D...
Jul 19 09:29:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.mail WARNI...
Jul 19 09:29:16 beaker-server-lc.beaker beakerd[18323]: bkr.server.tools.beak...
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# cat /etc/redhat-release
Fedora release 19 (Schrödinger’s Cat)
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# service beaker-provision start
Starting beaker-provision (via systemctl):                 [  OK  ]
[root@beaker-server-lc ~]#
[root@beaker-server-lc ~]# service beaker-provision status
beaker-provision.service - SYSV: This service acts on queued commands from the Beaker server by
   Loaded: loaded (/etc/rc.d/init.d/beaker-provision)
   Active: active (running) since Fri 2013-07-19 01:45:10 EDT; 3 days ago
  Process: 18387 ExecStop=/etc/rc.d/init.d/beaker-provision stop (code=exited, status=0/SUCCESS)
  Process: 18395 ExecStart=/etc/rc.d/init.d/beaker-provision start (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/beaker-provision.service
           `-18407 /usr/bin/python /bin/beaker-provision

Jul 22 06:01:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:01:45 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:02:05 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:02:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:02:45 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:03:05 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:03:25 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:03:45 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
Jul 22 06:03:50 beaker-server-lc.beaker systemd[1]: Started SYSV: This servic...
Jul 22 06:04:05 beaker-server-lc.beaker beaker-provision[18407]: bkr.labcontr...
[root@beaker-server-lc ~]# vim /var/log/beaker/
beakerd.log                server-debug.log
beaker-provision.log       server-debug.log-20130720
beaker-proxy.log           server-errors.log
beaker-watchdog.log
[root@beaker-server-lc ~]# vim /var/log/beaker/beaker-provision.log
[root@beaker-server-lc ~]# vim /var/log/beaker/beakerd.log
[root@beaker-server-lc ~]# rpm -qa | grep beaker
beaker-server-0.13.2-1.git.34.98aec4c.fc18.noarch
beaker-0.13.2-1.git.34.98aec4c.fc18.noarch
beaker-lab-controller-0.13.2-1.git.34.98aec4c.fc18.noarch
[root@beaker-server-lc ~]# cd  /usr/lib/python2.7/site-packages/bkr/labcontroller/
[root@beaker-server-lc labcontroller]# grep -R "close()" * --color
distro_import.py:            f.close()
distro_import.py:                f.close()
log_storage.py:            self.f.close()
log_storage.py:        self.f.close()
main.py:        proxy.close()
provision.py:        poller.close()
proxy.py:            file.close()
transfer.py:        transfer.close()
watchdog.py:        watchdog.close()
Comment 9 Dan Callaghan 2013-08-09 03:23:51 UTC 
Beaker 0.14.1 has been released.