freeipa

Clone
Source Code
GIT

#7465 [F28] oddjobd not started, replica install fails with dbus error in conn check
Closed: fixed 5 years ago Opened 6 years ago by cheimes.

Closed: fixed
Reopen Issue

Issue

Installation of a replica fails in conn check because org.freeipa.server dbus service is not registered. The oddjobd was not started by ipa-server-install.

Replica:

2018-03-26T16:45:13Z INFO trying https://master.ipa.example/ipa/json
2018-03-26T16:45:13Z DEBUG Created connection context.rpcclient_140547406361880
2018-03-26T16:45:13Z DEBUG raw: ping(version='2.229')
2018-03-26T16:45:13Z DEBUG ping(version='2.229')
2018-03-26T16:45:13Z INFO [try 1]: Forwarding 'ping/1' to json server 'https://master.ipa.example/ipa/json'
2018-03-26T16:45:13Z DEBUG New HTTP connection (master.ipa.example)
2018-03-26T16:45:13Z DEBUG received Set-Cookie (<class 'list'>)'['ipa_session=MagBearerToken=pxlgTDZasegIuoHjde2tvMGt2zfAy0MkWkEwLXQXd97kN0I5RWf%2bruOi%2bbI6aaavPc%2f6q8TYABWqq2le6X2pELU3uRu%2bN8NFmtJekjv4P0CYaKCaKAd8p1E00xkb7oc65pKuxtKnadE3DDfe%2fw8t1s0nV6Qu80ry1W%2fQ9rcMD8RdLvO6xRvaY7nNvsXybfzd60hWHhJYxaE6FbWKbRtRWx3OVjDfrERGlXDasSfU6rHlGlWYNk80W5bEljdI86ClAcAaK16J8LkT%2fKGuXvhTb8mfxY%2bC4QN%2b9Wf1QBqYGxw%3d;path=/ipa;httponly;secure;']'
2018-03-26T16:45:13Z DEBUG storing cookie 'ipa_session=MagBearerToken=pxlgTDZasegIuoHjde2tvMGt2zfAy0MkWkEwLXQXd97kN0I5RWf%2bruOi%2bbI6aaavPc%2f6q8TYABWqq2le6X2pELU3uRu%2bN8NFmtJekjv4P0CYaKCaKAd8p1E00xkb7oc65pKuxtKnadE3DDfe%2fw8t1s0nV6Qu80ry1W%2fQ9rcMD8RdLvO6xRvaY7nNvsXybfzd60hWHhJYxaE6FbWKbRtRWx3OVjDfrERGlXDasSfU6rHlGlWYNk80W5bEljdI86ClAcAaK16J8LkT%2fKGuXvhTb8mfxY%2bC4QN%2b9Wf1QBqYGxw%3d;' for principal admin@IPA.EXAMPLE
2018-03-26T16:45:13Z INFO Execute check on remote master
2018-03-26T16:45:13Z INFO [try 1]: Forwarding 'server_conncheck' to json server 'https://master.ipa.example/ipa/json'
2018-03-26T16:45:13Z DEBUG HTTP connection keep-alive (master.ipa.example)
2018-03-26T16:45:13Z DEBUG received Set-Cookie (<class 'list'>)'['ipa_session=MagBearerToken=cINPnI9iqRBr7jztlE8EaCUIP3gHuv2Mcdg%2bVPd%2bJx5pjxANg4IoSkjO9W6acl2luJogGngzRhJ9C0%2fTOQnFxX6qUiV0zHSHAcCjhX78byClwUnVm9owB7FeWcYVMZu5q0EbS2IJiD5UsT8MA723JsyCRDNWorvCkCpKetRjIQH3Oxcl3T73001q%2fxFnQXMIBO1MlKdH0HFCvVGhVcoTuQHlN8DQhnnKzUksjxzSwUT80LyxpbvsYvCTjnw9Hd%2fmv%2fE54YNa7GcCbahF0wpl1fOp4RwCq4xhYsk9WSMjgMg%3d;path=/ipa;httponly;secure;']'
2018-03-26T16:45:13Z DEBUG storing cookie 'ipa_session=MagBearerToken=cINPnI9iqRBr7jztlE8EaCUIP3gHuv2Mcdg%2bVPd%2bJx5pjxANg4IoSkjO9W6acl2luJogGngzRhJ9C0%2fTOQnFxX6qUiV0zHSHAcCjhX78byClwUnVm9owB7FeWcYVMZu5q0EbS2IJiD5UsT8MA723JsyCRDNWorvCkCpKetRjIQH3Oxcl3T73001q%2fxFnQXMIBO1MlKdH0HFCvVGhVcoTuQHlN8DQhnnKzUksjxzSwUT80LyxpbvsYvCTjnw9Hd%2fmv%2fE54YNa7GcCbahF0wpl1fOp4RwCq4xhYsk9WSMjgMg%3d;' for principal admin@IPA.EXAMPLE
2018-03-26T16:45:13Z DEBUG Destroyed connection context.rpcclient_140547406361880
2018-03-26T16:45:13Z ERROR ERROR: Remote master check failed with following error message(s):
an internal error has occurred

Master:

 admin@IPA.EXAMPLE: ping/1(version='2.229'): SUCCESS
 ipa: ERROR: Introspect error on org.freeipa.server:/: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freeipa.server was not provided by any .service files
 ipa: ERROR: non-public: DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freeipa.server was not provided by any .service files
 Traceback (most recent call last):
   File "/usr/lib/python3.6/site-packages/ipaserver/rpcserver.py", line 367, in wsgi_execute
     result = command(*args, **options)
   File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 450, in __call__
     return self.__do_call(*args, **options)
   File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 478, in __do_call
     ret = self.run(*args, **options)
   File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 800, in run
     return self.execute(*args, **options)
   File "/usr/lib/python3.6/site-packages/ipaserver/plugins/server.py", line 935, in execute
)
   File "/usr/lib64/python3.6/site-packages/dbus/proxies.py", line 70, in __call__
     return self._proxy_method(*args, **keywords)
   File "/usr/lib64/python3.6/site-packages/dbus/proxies.py", line 145, in __call__
     **keywords)
   File "/usr/lib64/python3.6/site-packages/dbus/connection.py", line 651, in call_blocking
     message, timeout)
 dbus.exceptions.DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freeipa.server was not provided by any .service files

Steps to Reproduce

  1. install master
  2. enrol client on second machine
  3. upgrade second machine to replica

Actual behavior

conncheck fails with an internal error

Expected behavior

no error

Version/Release/Distribution

freeipa-server-4.6.90.pre1.dev201803261110+git1fe795b75-0.fc28.x86_64
freeipa-client-4.6.90.pre1.dev201803261110+git1fe795b75-0.fc28.x86_64
package ipa-server is not installed
package ipa-client is not installed
389-ds-base-1.4.0.6-2.fc28.x86_64
pki-ca-10.6.0-0.2.fc28.noarch
krb5-server-1.16-12.fc28.x86_64

Additional info:

systemctl restart dbus didn't fix the issue. I had to start oddjobd.service manually, then restart httpd to fix dbus.exceptions.DBusException: Connection is disconnected - unable to make method call problem.

Metadata Update from @cheimes:
- Issue priority set to: critical
- Issue set to the milestone: FreeIPA 4.7
6 years ago

Most likely an effect of changing dbus broker in F28 to a new one.

The test machine has

dbus-1.12.0-1.fc28.x86_64
oddjob-0.34.4-4.fc28.x86_64

then this is a different issue. Could you please make a journal available from the system?

I forgot to mention that I ran into bug #7464 two times before I installed the server. The machine had two unsuccessful ipa-server-install followed by ipa-server-install --uninstall -U. The third time, ipa-server-install was successful. Maybe previous installation or uninstallation left the system in an invalid state?

The last ipa-server-install finished 2018-03-26T16:32:04Z.

# journalctl --unit oddjobd
-- Logs begin at Sat 2018-03-17 23:41:07 CET, end at Mon 2018-03-26 18:59:31 CEST. --
Mar 26 18:24:56 master.ipa.example systemd[1]: Started privileged operations for unprivileged applications.
Mar 26 18:30:27 master.ipa.example systemd[1]: Stopping privileged operations for unprivileged applications...
Mar 26 18:30:27 master.ipa.example systemd[1]: Stopped privileged operations for unprivileged applications.
Mar 26 18:55:50 master.ipa.example systemd[1]: Started privileged operations for unprivileged applications.

At least sysrestore.state has recorded that oddjobd was not running and was not enabled before install:

[oddjobd]
running = False
enabled = False

I guess this is a reason. We have httpd.enable_and_start_oddjobd() in upgrade path, so it will be started if needed, but I guess we need to add the same in the replica code path.

We also need it in the master path. The oddjobd service on master wasn't available.

We have it in the master path as part of the configuration of HTTP instance:

ipaserver/install/httpinstance.py:        self.step("enabling oddjobd", self.enable_and_start_oddjobd)
ipaserver/install/httpinstance.py:    def enable_and_start_oddjobd(self):
ipaserver/install/httpinstance.py:        oddjobd = services.service('oddjobd', api)
ipaserver/install/httpinstance.py:        self.sstore.backup_state('oddjobd', 'running', oddjobd.is_running())
ipaserver/install/httpinstance.py:        self.sstore.backup_state('oddjobd', 'enabled', oddjobd.is_enabled())
ipaserver/install/httpinstance.py:            oddjobd.enable()
ipaserver/install/httpinstance.py:            oddjobd.start()
ipaserver/install/httpinstance.py:            logger.critical("Unable to start oddjobd: %s", str(e))
ipaserver/install/httpinstance.py:        # Restore oddjobd to its original state
ipaserver/install/httpinstance.py:        oddjobd = services.service('oddjobd', api)
ipaserver/install/httpinstance.py:        if not self.sstore.restore_state('oddjobd', 'running'):
ipaserver/install/httpinstance.py:                oddjobd.stop()
ipaserver/install/httpinstance.py:        if not self.sstore.restore_state('oddjobd', 'enabled'):
ipaserver/install/httpinstance.py:                oddjobd.disable()
ipaserver/install/ipa_restore.py:                logger.info('Restarting oddjobd')
ipaserver/install/ipa_restore.py:                oddjobd = services.service('oddjobd', api)
ipaserver/install/ipa_restore.py:                if not oddjobd.is_enabled():
ipaserver/install/ipa_restore.py:                    logger.info("Enabling oddjobd")
ipaserver/install/ipa_restore.py:                    oddjobd.enable()
ipaserver/install/ipa_restore.py:                oddjobd.start()
ipaserver/install/server/upgrade.py:    http.enable_and_start_oddjobd()

I'm running into more oddjobd related issues. ipa-replica-install is running into:

  [21/21]: enabling oddjobd
ipaserver.install.httpinstance: CRITICAL Unable to start oddjobd: CalledProcessError(Command ['/bin/systemctl', 'start', 'oddjobd.service'] returned non-zero exit status 1: "Failed to start oddjobd.serv
ice: Connection timed out\nSee system logs and 'systemctl status oddjobd.service' for details.\n")
Done configuring the web interface (httpd).

ipareplica install log:

2018-03-28T14:30:40Z DEBUG   [21/21]: enabling oddjobd
2018-03-28T14:30:40Z DEBUG Starting external process
2018-03-28T14:30:40Z DEBUG args=['/bin/systemctl', 'is-active', 'oddjobd.service']
2018-03-28T14:31:05Z DEBUG Process finished, return code=3
2018-03-28T14:31:05Z DEBUG stdout=inactive

2018-03-28T14:31:05Z DEBUG stderr=
2018-03-28T14:31:05Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2018-03-28T14:31:05Z DEBUG Saving StateFile to '/var/lib/ipa/sysrestore/sysrestore.state'
2018-03-28T14:31:05Z DEBUG Starting external process
2018-03-28T14:31:05Z DEBUG args=['/bin/systemctl', 'is-enabled', 'oddjobd.service']
2018-03-28T14:31:05Z DEBUG Process finished, return code=1
2018-03-28T14:31:05Z DEBUG stdout=disabled

2018-03-28T14:31:05Z DEBUG stderr=
2018-03-28T14:31:05Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2018-03-28T14:31:05Z DEBUG Saving StateFile to '/var/lib/ipa/sysrestore/sysrestore.state'
2018-03-28T14:31:05Z DEBUG Starting external process
2018-03-28T14:31:05Z DEBUG args=['/bin/systemctl', 'enable', 'oddjobd.service']
2018-03-28T14:31:05Z DEBUG Process finished, return code=0
2018-03-28T14:31:05Z DEBUG stdout=
2018-03-28T14:31:05Z DEBUG stderr=Created symlink /etc/systemd/system/multi-user.target.wants/oddjobd.service → /usr/lib/systemd/system/oddjobd.service.

2018-03-28T14:31:05Z DEBUG Starting external process
2018-03-28T14:31:05Z DEBUG args=['/bin/systemctl', 'start', 'oddjobd.service']
2018-03-28T14:32:35Z DEBUG Process finished, return code=1
2018-03-28T14:32:35Z DEBUG stdout=
2018-03-28T14:32:35Z DEBUG stderr=Failed to start oddjobd.service: Connection timed out
See system logs and 'systemctl status oddjobd.service' for details.

2018-03-28T14:32:35Z CRITICAL Unable to start oddjobd: CalledProcessError(Command ['/bin/systemctl', 'start', 'oddjobd.service'] returned non-zero exit status 1: "Failed to start oddjobd.service: Connection timed out\nSee system logs and 'systemctl status oddjobd.service' for details.\n")
2018-03-28T14:32:35Z DEBUG step duration: httpd enable_and_start_oddjobd 115.25 sec
2018-03-28T14:32:35Z DEBUG Done configuring the web interface (httpd).

I don't see a start operation in the journal. 16:38:22 is my manual start of oddjobd after installation.

# journalctl -u oddjobd.service
-- Logs begin at Sat 2018-03-17 23:41:07 CET, end at Wed 2018-03-28 16:41:07 CEST. --
Mar 28 16:38:22 vm-247.abc.idm.lab.eng.brq.redhat.com systemd[1]: Started privileged operations for unprivileged applications.
Edited 6 years ago by cheimes

Latest master is still affected

I found the culprit. authconfig is disabling oddjobd.service!

# journalctl -u oddjobd.service
-- Logs begin at Wed 2018-04-25 11:21:35 CEST, end at Wed 2018-04-25 15:34:28 CEST. --
Apr 25 12:54:23 vm-029.abc.idm.lab.eng.brq.redhat.com systemd[1]: Started privileged operations for unprivileged applications.
Apr 25 12:59:17 vm-029.abc.idm.lab.eng.brq.redhat.com systemd[1]: Stopping privileged operations for unprivileged applications...
Apr 25 12:59:17 vm-029.abc.idm.lab.eng.brq.redhat.com systemd[1]: Stopped privileged operations for unprivileged applications.
Apr 25 13:44:59 vm-029.abc.idm.lab.eng.brq.redhat.com systemd[1]: Started privileged operations for unprivileged applications.

# less /var/log/ipaclient-install.log
...
2018-04-25T10:59:16Z DEBUG args=['/usr/sbin/authconfig', '--enablesssd', '--enablesssdauth', '--update']
2018-04-25T10:59:17Z DEBUG Process finished, return code=0
2018-04-25T10:59:17Z DEBUG stdout=Running authconfig compatibility tool.

IMPORTANT: authconfig is replaced by authselect, please update your scripts.
See Fedora 28 Change Page: https://fedoraproject.org/wiki/Changes/AuthselectAsDefault
See man authselect-migration(7) to help you with migration to authselect

Executing: /usr/bin/authselect select sssd --force
Removing file: /etc/krb5.conf.d/authconfig-krb.conf
Executing: /usr/bin/systemctl disable winbind.service
Executing: /usr/bin/systemctl stop winbind.service
Executing: /usr/bin/systemctl disable oddjobd.service
Executing: /usr/bin/systemctl stop oddjobd.service

2018-04-25T10:59:17Z DEBUG stderr=
2018-04-25T10:59:17Z INFO SSSD enabled
2018-04-25T10:59:17Z DEBUG Starting external process
2018-04-25T10:59:17Z DEBUG args=['/bin/systemctl', 'restart', 'sssd.service']

Metadata Update from @cheimes:
- Issue assigned to cheimes
6 years ago

Metadata Update from @cheimes:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1571844
6 years ago

Metadata Update from @cheimes:
- Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/1863
6 years ago

FreeIPA master now requires authselect >= 0.4-2.

Metadata Update from @cheimes:
- Issue close_status updated to: fixed
5 years ago

Login to comment on this ticket.

Metadata
None
None
None
critical
None
None
None
None
None
None
None
None
None
https://github.com/freeipa/freeipa/pull/1863
None
None
None
None
https://bugzilla.redhat.com/show_bug.cgi?id=1571844
None
None
None
Powered by Pagure 5.13.3
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.