Pulp

Hi,

While testing Katello 3.0/Pulp 2.8.6 we've discovered an issue in the pulp_streamer.service file. This unit file contains the following dependency:

After=network-online.target
Wants=network-online.target

However, this can result in a race condition where pulp_streamer gets started before mongod is fully operational as can be observed in the following log:

# journalctl -u pulp_streamer -u mongod
-- Logs begin at Tue 2016-11-22 09:31:22 CET, end at Tue 2016-11-22 10:18:13 CET. --
Nov 22 09:31:34 katello.infoplus-local.ris systemd[1]: Starting High-performance, schema-free document-oriented database...
Nov 22 09:31:34 katello.infoplus-local.ris systemd[1]: Started The Pulp lazy content loading streamer.
Nov 22 09:31:34 katello.infoplus-local.ris systemd[1]: Starting The Pulp lazy content loading streamer...
Nov 22 09:31:35 katello.infoplus-local.ris mongod[1124]: about to fork child process, waiting until server is ready for connections.
Nov 22 09:31:35 katello.infoplus-local.ris mongod[1124]: forked process: 1460
Nov 22 09:31:38 katello.infoplus-local.ris pulp_streamer[1129]: pulp.server.db.connection:INFO: Attempting to connect to localhost:27017
Nov 22 09:32:08 katello.infoplus-local.ris pulp_streamer[1129]: pulp.server.db.connection:CRITICAL: Database initialization failed: localhost:27017: [Errno 111] Connection refused
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: Unhandled Error
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: Traceback (most recent call last):
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/application/app.py", line 652, in run
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: runApp(config)
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/scripts/twistd.py", line 23, in runApp
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: _SomeApplicationRunner(config).run()
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/application/app.py", line 386, in run
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: self.application = self.createOrGetApplication()
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/application/app.py", line 451, in createOrGetApplication
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: application = getApplication(self.config, passphrase)
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: --- <exception caught here> ---
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/application/app.py", line 462, in getApplication
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: application = service.loadApplication(filename, style, passphrase)
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/application/service.py", line 405, in loadApplication
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: application = sob.loadValueFromFile(filename, 'application', passphrase)
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/twisted/persisted/sob.py", line 210, in loadValueFromFile
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: exec fileObj in d, d
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/share/pulp/wsgi/streamer.tac", line 53, in <module>
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: mongo_initialize()
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib/python2.7/site-packages/pulp/server/db/connection.py", line 119, in initialize
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: db_version = semantic_version.Version(_CONNECTION.server_info()['version'])
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/pymongo/mongo_client.py", line 1017, in server_info
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: read_preference=ReadPreference.PRIMARY)
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/pymongo/database.py", line 478, in command
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: with client._socket_for_reads(read_preference) as (sock_info, slave_ok):
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: return self.gen.next()
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/pymongo/mongo_client.py", line 748, in _socket_for_reads
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: with self._get_socket(read_preference) as sock_info:
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: return self.gen.next()
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/pymongo/mongo_client.py", line 712, in _get_socket
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: server = self._get_topology().select_server(selector)
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/pymongo/topology.py", line 141, in select_server
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: address))
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: File "/usr/lib64/python2.7/site-packages/pymongo/topology.py", line 117, in select_servers
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: self._error_message(selector))
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: pymongo.errors.ServerSelectionTimeoutError: localhost:27017: [Errno 111] Connection refused
Nov 22 09:32:09 katello.infoplus-local.ris pulp_streamer[1129]: Failed to load application: localhost:27017: [Errno 111] Connection refused
Nov 22 09:32:09 katello.infoplus-local.ris systemd[1]: pulp_streamer.service: main process exited, code=exited, status=1/FAILURE
Nov 22 09:32:09 katello.infoplus-local.ris systemd[1]: Unit pulp_streamer.service entered failed state.
Nov 22 09:32:09 katello.infoplus-local.ris systemd[1]: pulp_streamer.service failed.
Nov 22 09:32:09 katello.infoplus-local.ris systemd[1]: Started High-performance, schema-free document-oriented database.

What can be seen here is that systemd tries to start both mongod and pulp_streamer at the same time (Nov 22 09:31:34), but it takes mongod service until Nov 22 09:32:09 to get fully started. By that time the pulp_streamer service already failed to start.

This race condition can be resolved easily by adding the following explicit dependency to the pulp_streamer.service file:

After=mongod.service
Wants=mongod.service