DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.327 was not provided by any .service files

[Moumoutaru]

Ansible Version: 2.7.5 (tried 2.7.9 as well)
Ansible Patched: No
Custom Modules: Yes (albeit not likely related to issue)
Have you tried the latest master version from Git?: No
Host and Target Python Versions: 2.7.5
Target OS: CentOS 7.5.1804 (Core)

Base error message:

    "module_stderr": "Traceback (most recent call last):\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/runner.py\", line 883, in _run\n    self._run_code(code, mod)\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/runner.py\", line 862, in _run_code\n    exec('exec code in vars(mod)')\n  File \"<string>\", line 1, in <module>\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py\", line 715, in <module>\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py\", line 605, in main\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py\", line 171, in __init__\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/module_utils/firewalld.py\", line 75, in __init__\n    self.zone = fw.getDefaultZone()\n  File \"<string>\", line 2, in getDefaultZone\n  File \"/usr/lib/python2.7/site-packages/slip/dbus/polkit.py\", line 103, in _enable_proxy\n    return func(*p, **k)\n  File \"<string>\", line 2, in getDefaultZone\n  File \"/usr/lib/python2.7/site-packages/firewall/client.py\", line 53, in handle_exceptions\n    return func(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/firewall/client.py\", line 2903, in getDefaultZone\n    return dbus_to_python(self.fw.getDefaultZone())\n  File \"/usr/lib/python2.7/site-packages/slip/dbus/proxies.py\", line 50, in __call__\n    return dbus.proxies._ProxyMethod.__call__(self, *args, **kwargs)\n  File \"/usr/lib64/python2.7/site-packages/dbus/proxies.py\", line 145, in __call__\n    **keywords)\n  File \"/usr/lib64/python2.7/site-packages/dbus/connection.py\", line 651, in call_blocking\n    message, timeout)\nDBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.435 was not provided by any .service files\n", 
    "module_stdout": "", 
    "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", 
    "rc": 1
}

verbose-log-output-dbus-exception.txt

Ansible Config Dump:

ANSIBLE_PIPELINING(/home/amurphy/configuration-management/ansible.cfg) = True
ANSIBLE_SSH_ARGS(/home/amurphy/configuration-management/ansible.cfg) = -o ForwardAgent=yes
ANSIBLE_SSH_CONTROL_PATH(/home/amurphy/configuration-management/ansible.cfg) = %(directory)s/%%h-%%r
DEFAULT_ACTION_PLUGIN_PATH(/home/amurphy/configuration-management/ansible.cfg) = [u'/var/lib/awx/venv/awx/lib/python2.7/site-packages/ara/plugins/actions']
DEFAULT_CALLBACK_PLUGIN_PATH(/home/amurphy/configuration-management/ansible.cfg) = [u'/home/amurphy/configuration-management/plugins/callback_plugins']
DEFAULT_CALLBACK_WHITELIST(/home/amurphy/configuration-management/ansible.cfg) = [u'rc', u'profile_tasks', u'es_annotations']
DEFAULT_LOG_PATH(/home/amurphy/configuration-management/ansible.cfg) = /home/amurphy/ansible.log
DEFAULT_LOOKUP_PLUGIN_PATH(/home/amurphy/configuration-management/ansible.cfg) = [u'/home/amurphy/configuration-management/plugins/lookup']
DEFAULT_MANAGED_STR(/home/amurphy/configuration-management/ansible.cfg) = !! Ansible managed: This file was created by ansible. Do not modify by hand! Changes will be overwritten. !!
DEFAULT_MODULE_PATH(/home/amurphy/configuration-management/ansible.cfg) = [u'/home/amurphy/configuration-management/playbooks/library']
DEFAULT_ROLES_PATH(/home/amurphy/configuration-management/ansible.cfg) = [u'/home/amurphy/configuration-management/playbooks/roles', u'/home/amurphy/roles']
DEFAULT_STRATEGY(/home/amurphy/configuration-management/ansible.cfg) = mitogen_linear
DEFAULT_STRATEGY_PLUGIN_PATH(/home/amurphy/configuration-management/ansible.cfg) = [u'/usr/lib/python2.7/site-packages/ansible_mitogen/plugins/strategy', u'/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/plugins/strategy', u'/srv
DEFAULT_VAULT_IDENTITY_LIST(env: ANSIBLE_VAULT_IDENTITY_LIST) = [u'/******']
INVENTORY_UNPARSED_IS_FAILED(/home/amurphy/configuration-management/ansible.cfg) = True
MAX_FILE_SIZE_FOR_DIFF(/home/amurphy/configuration-management/ansible.cfg) = 204800
RETRY_FILES_ENABLED(/home/amurphy/configuration-management/ansible.cfg) = False

So this error has been occurring when we try to enable a service after restarting firewalld. Reload comes back as changed, going to the enable custom service task and bombs out. This is the task order with the last throwing the error:

- name: Template firewalld configuration
  template:
    src: firewalld.conf.j2
    dest: /etc/firewalld/services/{{ item.name }}.xml
    mode: '0600'
    owner: root
    group: root
  with_items: '{{ firewalld_custom_services }}'
  register: firewall_services_installed

- name: Reload firewalld configuration
  service:
    name: firewalld
    state: restarted
    enabled: yes
  when: firewall_services_installed.changed == true

- name: Enable custom service
  firewalld:
    service: "{{ item.name }}"
    permanent: true
    immediate: true
    state: enabled
  with_items:
    - '{{ firewalld_custom_services }}'

[dw]

This is definitely a new one! Thanks for the clear report.

Exception:

Traceback (most recent call last):
  File "master:/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/runner.py", line 883, in _run
    self._run_code(code, mod)
  File "master:/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/runner.py", line 862, in _run_code
    exec('exec code in vars(mod)')
  File "<string>", line 1, in <module>
  File "master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py", line 715, in <module>
  File "master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py", line 605, in main
  File "master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py", line 171, in __init__
  File "master:/srv/ansible/lib/python2.7/site-packages/ansible/module_utils/firewalld.py", line 75, in __init__
    self.zone = fw.getDefaultZone()
  File "<string>", line 2, in getDefaultZone
  File "/usr/lib/python2.7/site-packages/slip/dbus/polkit.py", line 103, in _enable_proxy
    return func(*p, **k)
  File "<string>", line 2, in getDefaultZone
  File "/usr/lib/python2.7/site-packages/firewall/client.py", line 53, in handle_exceptions
    return func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/firewall/client.py", line 2903, in getDefaultZone
    return dbus_to_python(self.fw.getDefaultZone())
  File "/usr/lib/python2.7/site-packages/slip/dbus/proxies.py", line 50, in __call__
    return dbus.proxies._ProxyMethod.__call__(self, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/dbus/proxies.py", line 145, in __call__
    **keywords)
  File "/usr/lib64/python2.7/site-packages/dbus/connection.py", line 651, in call_blocking
    message, timeout)
DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.435 was not provided by any .service files

[dw]

Have you noticed if that ":1.435" name varies across runs? I haven't touched DBUS in a while, so wondering if the '435' is maybe a PID

[dw]

This seems to work fine with 2.7.9 against CentOS 7, I'll need to grab a 7.5 VM to try again.

I doubt it's relevant, but does your service XML use any fancy firewalld modules etc? This looks like a DBUS configuration error (clearly), so probably it's not related to the contents of your config at all

[dw]

https://github.com/firewalld/firewalld/blob/v0.5.3/src/firewall/client.py appears to be the version shipped with 7.5

[dw]

multiple suggestions (here: http://gnome-evolution-general.1774414.n4.nabble.com/The-name-1-157-was-not-provided-by-any-service-files-td4668022.html#a4668037 and flatpak/flatpak#1845 here) the error might relate to the backing service going away somehow

[Moumoutaru]

@dw The :1.435 section seems to vary for me across runs. Haven't taken a look at your links yet. I am noticing, however, that it doesn't seem to happen all the time. For example, the first time calling the template, reload, and enable tasks steps for a service worked but the second time did not.

TASK [firewalld-custom-service : Template firewalld configuration] **********************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:46 -0400 (0:00:00.197)       0:01:21.376 ******** 
changed: [testhost.test.mydomain.io] => (item={u'ports': [{u'protocol': u'tcp', u'name': u'node_exporter', u'port': u'9100'}], u'name': u'node_exporter', u'description': u'node_exporter '})

TASK [firewalld-custom-service : Reload firewalld configuration] ************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:46 -0400 (0:00:00.209)       0:01:21.586 ******** 
changed: [testhost.test.mydomain.io]

TASK [firewalld-custom-service : Enable custom service] *********************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:47 -0400 (0:00:01.057)       0:01:22.643 ******** 
changed: [testhost.test.mydomain.io] => (item={u'ports': [{u'protocol': u'tcp', u'name': u'node_exporter', u'port': u'9100'}], u'name': u'node_exporter', u'description': u'node_exporter '})

TASK [firewalld-custom-service : Status firewalld] **************************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:48 -0400 (0:00:00.543)       0:01:23.187 ******** 
ok: [testhost.test.mydomain.io]

TASK [prometheus_exporters : Download the exporter binary] ******************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:48 -0400 (0:00:00.126)       0:01:23.314 ******** 
changed: [testhost.test.mydomain.io]

TASK [prometheus_exporters : Update Firewall Rules] *************************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:48 -0400 (0:00:00.731)       0:01:24.046 ******** 
ok: [testhost.test.mydomain.io]

TASK [prometheus_exporters : Template systemd unit file] ********************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:49 -0400 (0:00:00.111)       0:01:24.157 ******** 
changed: [testhost.test.mydomain.io]

TASK [prometheus_exporters : Create exporter optional config files] *********************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:49 -0400 (0:00:00.253)       0:01:24.411 ******** 

TASK [prometheus_exporters : Add runtime options] ***************************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:49 -0400 (0:00:00.092)       0:01:24.504 ******** 
changed: [testhost.test.mydomain.io]

TASK [prometheus_exporters : Start exporter] ********************************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:49 -0400 (0:00:00.152)       0:01:24.657 ******** 
changed: [testhost.test.mydomain.io]

TASK [firewalld-custom-service : Template firewalld configuration] **********************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:49 -0400 (0:00:00.199)       0:01:24.856 ******** 
changed: [testhost.test.mydomain.io] => (item={u'ports': [{u'protocol': u'tcp', u'name': u'process_exporter_ops', u'port': u'9113'}], u'name': u'process_exporter_ops', u'description': u'process_exporter '})

TASK [firewalld-custom-service : Reload firewalld configuration] ************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:49 -0400 (0:00:00.130)       0:01:24.987 ******** 
changed: [testhost.test.mydomain.io]

TASK [firewalld-custom-service : Enable custom service] *********************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:50 -0400 (0:00:01.063)       0:01:26.050 ******** 
An exception occurred during task execution. To see the full traceback, use -vvv. The error was: DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.29 was not provided by any .service files
failed: [testhost.test.mydomain.io] (item={u'ports': [{u'protocol': u'tcp', u'name': u'process_exporter_ops', u'port': u'9113'}], u'name': u'process_exporter_ops', u'description': u'process_exporter '}) => {"changed": false, "item": {"description": "process_exporter ", "name": "process_exporter_ops", "ports": [{"name": "process_exporter_ops", "port": "9113", "protocol": "tcp"}]}, "module_stderr": "Traceback (most recent call last):\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/runner.py\", line 883, in _run\n    self._run_code(code, mod)\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible_mitogen/runner.py\", line 862, in _run_code\n    exec('exec code in vars(mod)')\n  File \"<string>\", line 1, in <module>\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py\", line 718, in <module>\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py\", line 608, in main\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/modules/system/firewalld.py\", line 171, in __init__\n  File \"master:/srv/ansible/lib/python2.7/site-packages/ansible/module_utils/firewalld.py\", line 75, in __init__\n    self.zone = fw.getDefaultZone()\n  File \"<string>\", line 2, in getDefaultZone\n  File \"/usr/lib/python2.7/site-packages/slip/dbus/polkit.py\", line 103, in _enable_proxy\n    return func(*p, **k)\n  File \"<string>\", line 2, in getDefaultZone\n  File \"/usr/lib/python2.7/site-packages/firewall/client.py\", line 53, in handle_exceptions\n    return func(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/firewall/client.py\", line 2903, in getDefaultZone\n    return dbus_to_python(self.fw.getDefaultZone())\n  File \"/usr/lib/python2.7/site-packages/slip/dbus/proxies.py\", line 50, in __call__\n    return dbus.proxies._ProxyMethod.__call__(self, *args, **kwargs)\n  File \"/usr/lib64/python2.7/site-packages/dbus/proxies.py\", line 145, in __call__\n    **keywords)\n  File \"/usr/lib64/python2.7/site-packages/dbus/connection.py\", line 651, in call_blocking\n    message, timeout)\nDBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.29 was not provided by any .service files\n", "module_stdout": "", "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", "rc": 1}

RUNNING HANDLER [time : restart chronyd] ************************************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:50 -0400 (0:00:00.087)       0:01:26.137 ******** 

RUNNING HANDLER [prometheus_exporters : systemctl daemon-reload] ************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:50 -0400 (0:00:00.005)       0:01:26.143 ******** 

RUNNING HANDLER [prometheus_exporters : restart exporter] *******************************************************************************************************************************************************************************************************************************************************************
Thursday 21 March 2019  12:17:51 -0400 (0:00:00.004)       0:01:26.148 ******** 

PLAY RECAP ******************************************************************************************************************************************************************************************************************************************************************************************************************
testhost.test.mydomain.io : ok=45   changed=24   unreachable=0    failed=1   

[Moumoutaru]

This seems to work fine with 2.7.9 against CentOS 7, I'll need to grab a 7.5 VM to try again.

I doubt it's relevant, but does your service XML use any fancy firewalld modules etc? This looks like a DBUS configuration error (clearly), so probably it's not related to the contents of your config at all

Service files are pretty basic:

[root@l-docker101 ~]# cat /etc/firewalld/services/*exporter*.xml
<?xml version="1.0" encoding="utf-8"?>
<service>
    <short>node_exporter</short>
    <description>node_exporter </description>
        <port port="9100" protocol="tcp"/>
    </service>
<?xml version="1.0" encoding="utf-8"?>
<service>
    <short>process_exporter_ops</short>
    <description>process_exporter </description>
        <port port="9113" protocol="tcp"/>
    </service>
[root@l-docker101 ~]# 

[Moumoutaru]

Also, changing mitogen_linear to linear seems to resolve the issue.. albeit it's painfully slow. Let me know if there are any debugging steps you'd like me to go through as I am able to reproduce this fairly easily.

[dw]

I haven't figured out what's broken yet (haven't reproduced yet either!), but the rough guess is that the glib dbus client in the persistent interpreter is being broken somehow. I notice some ugly looking initialization code, it's possible it's being partially reinitialized twice, or similar.

This stuff has a fairly mature design, so whatever the problem I'm pretty sure the fix will be straightforwrad :)

[Moumoutaru]

https://github.com/firewalld/firewalld/blob/v0.5.3/src/firewall/client.py appears to be the version shipped with 7.5

That is the file present on my installation of Centos 7.5

[dw]

Reproduced it.. doesn't happen on first module invocation, but on second. So there is some shared component that is getting trashed somehow

[dw]

Hah! Real stupid bug. We restart firewalld, but keep a copy of the old firewall client around, which knows firewalld by a different name -- that ":1:123" crap is a needlessly cryptic unique name generated by dbus on initial connection by any app. So on second invocation, the cached client tries to talk to a dbus client that no longer exists.

Should be an easy fix, but for the time being, you can simply run the firewalld in isolated mode:

- name: Enable custom service
  firewalld:
    service: foo
    permanent: true
    immediate: true
    state: enabled 
  vars:
    mitogen_task_isolation: fork