unable to start mirror registry

[jfblaine]

Ran into the following error when attempting to use mirror registry:

TASK [mirror_registry : Enable container-mirror-registry on boot and start it] ****************************************************************************************************************
fatal: [helper]: FAILED! => {"changed": false, "msg": "Unable to start service container-mirror-registry: Job for container-mirror-registry.service failed because the control process exited with error code.\nSee "systemctl status container-mirror-registry.service" and "journalctl -xe" for details.\n"}

PLAY RECAP ************************************************************************************************************************************************************************************
helper : ok=10 changed=0 unreachable=0 failed=1 skipped=6 rescued=0 ignored=0

[root@helper-host openshift-auto-upi]# systemctl status container-mirror-registry.service
● container-mirror-registry.service - Podman container-6e79cd4be0da3086a24806aa74851677040af5cbbc01b60cab5c9ff480a351e6.service
Loaded: loaded (/etc/systemd/system/container-mirror-registry.service; enabled; vendor preset: disabled)
Active: failed (Result: exit-code) since Fri 2020-07-17 09:18:52 EDT; 6s ago
Docs: man:podman-generate-systemd(1)
Process: 12371 ExecStart=/usr/bin/podman start 6e79cd4be0da3086a24806aa74851677040af5cbbc01b60cab5c9ff480a351e6 (code=exited, status=125)
Main PID: 10694 (code=exited, status=0/SUCCESS)

Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: container-mirror-registry.service: Control process exited, code=exited status=125
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: container-mirror-registry.service: Failed with result 'exit-code'.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: Failed to start Podman container-6e79cd4be0da3086a24806aa74851677040af5cbbc01b60cab5c9ff480a351e6.service.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: container-mirror-registry.service: Service RestartSec=100ms expired, scheduling restart.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: container-mirror-registry.service: Scheduled restart job, restart counter is at 5.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: Stopped Podman container-6e79cd4be0da3086a24806aa74851677040af5cbbc01b60cab5c9ff480a351e6.service.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: container-mirror-registry.service: Start request repeated too quickly.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: container-mirror-registry.service: Failed with result 'exit-code'.
Jul 17 09:18:52 helper-host.autoupi.example.com systemd[1]: Failed to start Podman container-6e79cd4be0da3086a24806aa74851677040af5cbbc01b60cab5c9ff480a351e6.service.

[jfblaine]

With debug logs:

TASK [mirror_registry : Enable container-mirror-registry on boot and start it] ****************************************************************************************************************
task path: /root/gitstuff/openshift-auto-upi/roles/mirror_registry/tasks/mirror_create.yml:17
2673 1594992402.40801: sending task start callback
2673 1594992402.40807: entering _queue_task() for helper/service
2673 1594992402.40813: Creating lock for service
2673 1594992402.40969: worker is 1 (out of 1 available)
2673 1594992402.41025: exiting _queue_task() for helper/service
2673 1594992402.41105: done queuing things up, now waiting for results queue to drain
2673 1594992402.41114: waiting for pending results...
2955 1594992402.41350: running TaskExecutor() for helper/TASK: mirror_registry : Enable container-mirror-registry on boot and start it
2955 1594992402.41492: in run() - task 0050568a-9a66-f27c-56e2-000000000025
2955 1594992402.41554: calling self._execute()
2955 1594992402.42075: trying /usr/share/ansible/plugins/connection
2955 1594992402.42089: trying /usr/lib/python3.6/site-packages/ansible/plugins/connection
2955 1594992402.42184: Loading Connection 'local' from /usr/lib/python3.6/site-packages/ansible/plugins/connection/local.py (searched paths: /usr/lib/python3.6/site-packages/ansible/plugins/connection:/usr/share/ansible/plugins/connection) (found_in_cache=True, class_only=False)
2955 1594992402.42210: trying /usr/lib/python3.6/site-packages/ansible/plugins/shell
2955 1594992402.42234: Loading ShellModule 'sh' from /usr/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2955 1594992402.42252: Loading ShellModule 'sh' from /usr/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2955 1594992402.42268: trying /usr/share/ansible/plugins/become
2955 1594992402.42278: trying /usr/lib/python3.6/site-packages/ansible/plugins/become
2955 1594992402.42317: Loading BecomeModule 'sudo' from /usr/lib/python3.6/site-packages/ansible/plugins/become/sudo.py (searched paths: /usr/lib/python3.6/site-packages/ansible/plugins/become:/usr/share/ansible/plugins/become) (found_in_cache=True, class_only=False)
2955 1594992402.42464: Loading ActionModule 'service' from /usr/lib/python3.6/site-packages/ansible/plugins/action/service.py (searched paths: /usr/lib/python3.6/site-packages/ansible/plugins/action:/usr/lib/python3.6/site-packages/ansible/plugins/action/pycache:/usr/share/ansible/plugins/action) (found_in_cache=True, class_only=False)
2955 1594992402.42494: starting attempt loop
2955 1594992402.42500: running the handler
2955 1594992402.42570: Loading FilterModule 'core' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/core.py (found_in_cache=True, class_only=False)
2955 1594992402.42584: Loading FilterModule 'gcp_kms_filters' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/gcp_kms_filters.py (found_in_cache=True, class_only=False)
2955 1594992402.42595: Loading FilterModule 'ipaddr' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/ipaddr.py (found_in_cache=True, class_only=False)
2955 1594992402.42604: Loading FilterModule 'json_query' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/json_query.py (found_in_cache=True, class_only=False)
2955 1594992402.42613: Loading FilterModule 'k8s' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/k8s.py (found_in_cache=True, class_only=False)
2955 1594992402.42623: Loading FilterModule 'mathstuff' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/mathstuff.py (found_in_cache=True, class_only=False)
2955 1594992402.42632: Loading FilterModule 'network' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/network.py (found_in_cache=True, class_only=False)
2955 1594992402.42641: Loading FilterModule 'urls' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/urls.py (found_in_cache=True, class_only=False)
2955 1594992402.42649: Loading FilterModule 'urlsplit' from /usr/lib/python3.6/site-packages/ansible/plugins/filter/urlsplit.py (found_in_cache=True, class_only=False)
2955 1594992402.42718: Loading TestModule 'core' from /usr/lib/python3.6/site-packages/ansible/plugins/test/core.py (found_in_cache=True, class_only=False)
2955 1594992402.42727: Loading TestModule 'files' from /usr/lib/python3.6/site-packages/ansible/plugins/test/files.py (found_in_cache=True, class_only=False)
2955 1594992402.42735: Loading TestModule 'mathstuff' from /usr/lib/python3.6/site-packages/ansible/plugins/test/mathstuff.py (found_in_cache=True, class_only=False)
Running systemd
2955 1594992402.43195: _low_level_execute_command(): starting
2955 1594992402.43210: _low_level_execute_command(): executing: /bin/sh -c 'echo ~root && sleep 0'
ESTABLISH LOCAL CONNECTION FOR USER: root
2955 1594992402.43231: in local.exec_command()
EXEC /bin/sh -c 'echo root && sleep 0'
2955 1594992402.43245: opening command with Popen()
2955 1594992402.43733: done running command with Popen()
2955 1594992402.43753: getting output with communicate()
2955 1594992402.43959: done communicating
2955 1594992402.43968: done with local.exec_command()
2955 1594992402.43980: _low_level_execute_command() done: rc=0, stdout=/root
, stderr=
2955 1594992402.44018: _low_level_execute_command(): starting
2955 1594992402.44032: _low_level_execute_command(): executing: /bin/sh -c '( umask 77 && mkdir -p "echo /root/.ansible/tmp"&& mkdir /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637 && echo ansible-tmp-1594992402.440076-2955-56461824364637="echo /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637" ) && sleep 0'
2955 1594992402.44041: in local.exec_command()
EXEC /bin/sh -c '( umask 77 && mkdir -p "echo /root/.ansible/tmp"&& mkdir /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637 && echo ansible-tmp-1594992402.440076-2955-56461824364637="echo /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637" ) && sleep 0'
2955 1594992402.44058: opening command with Popen()
2955 1594992402.44463: done running command with Popen()
2955 1594992402.44485: getting output with communicate()
2955 1594992402.45021: done communicating
2955 1594992402.45028: done with local.exec_command()
2955 1594992402.45038: _low_level_execute_command() done: rc=0, stdout=ansible-tmp-1594992402.440076-2955-56461824364637=/root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637
, stderr=
2955 1594992402.45150: ANSIBALLZ: Using generic lock for systemd
2955 1594992402.45156: ANSIBALLZ: Acquiring lock
2955 1594992402.45165: ANSIBALLZ: Lock acquired: 139910541748544
2955 1594992402.45174: ANSIBALLZ: Creating module
2955 1594992402.91153: ANSIBALLZ: Writing module into payload
2955 1594992402.91402: ANSIBALLZ: Writing module
2955 1594992402.91436: ANSIBALLZ: Renaming module
2955 1594992402.91446: ANSIBALLZ: Done creating module
Using module file /usr/lib/python3.6/site-packages/ansible/modules/system/systemd.py
2955 1594992402.91555: transferring module to remote /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/AnsiballZ_systemd.py
PUT /root/.ansible/tmp/ansible-local-26733wkf1lhm/tmpebcb4b9h TO /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/AnsiballZ_systemd.py
2955 1594992402.91680: done transferring module to remote
2955 1594992402.91702: _low_level_execute_command(): starting
2955 1594992402.91712: _low_level_execute_command(): executing: /bin/sh -c 'chmod u+x /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/ /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/AnsiballZ_systemd.py && sleep 0'
2955 1594992402.91720: in local.exec_command()
EXEC /bin/sh -c 'chmod u+x /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/ /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/AnsiballZ_systemd.py && sleep 0'
2955 1594992402.91731: opening command with Popen()
2955 1594992402.92226: done running command with Popen()
2955 1594992402.92246: getting output with communicate()
2955 1594992402.92477: done communicating
2955 1594992402.92484: done with local.exec_command()
2955 1594992402.92494: _low_level_execute_command() done: rc=0, stdout=, stderr=
2955 1594992402.92501: _low_level_execute_command(): starting
2955 1594992402.92525: _low_level_execute_command(): executing: /bin/sh -c '/usr/libexec/platform-python /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/AnsiballZ_systemd.py && sleep 0'
2955 1594992402.92534: in local.exec_command()
EXEC /bin/sh -c '/usr/libexec/platform-python /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/AnsiballZ_systemd.py && sleep 0'
2955 1594992402.92548: opening command with Popen()
2955 1594992402.92958: done running command with Popen()
2955 1594992402.92983: getting output with communicate()
2955 1594992403.36807: done communicating
2955 1594992403.36820: done with local.exec_command()
2955 1594992403.36832: _low_level_execute_command() done: rc=1, stdout=
{"msg": "Unable to start service container-mirror-registry: Job for container-mirror-registry.service failed because the control process exited with error code.\nSee "systemctl status container-mirror-registry.service" and "journalctl -xe" for details.\n", "failed": true, "invocation": {"module_args": {"name": "container-mirror-registry", "state": "started", "enabled": true, "daemon_reload": false, "daemon_reexec": false, "no_block": false, "force": null, "masked": null, "user": null, "scope": null}}}
, stderr=
2955 1594992403.36893: done with _execute_module (systemd, {'name': 'container-mirror-registry', 'state': 'started', 'enabled': True, '_ansible_check_mode': False, '_ansible_no_log': False, '_ansible_debug': True, '_ansible_diff': False, '_ansible_verbosity': 4, '_ansible_version': '2.9.10', '_ansible_module_name': 'systemd', '_ansible_syslog_facility': 'LOG_USER', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p', 'vfat'], '_ansible_string_conversion_action': 'warn', '_ansible_socket': None, '_ansible_shell_executable': '/bin/sh', '_ansible_keep_remote_files': False, '_ansible_tmpdir': '/root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/', '_ansible_remote_tmp': '/.ansible/tmp'})
2955 1594992403.36919: _low_level_execute_command(): starting
2955 1594992403.36946: _low_level_execute_command(): executing: /bin/sh -c 'rm -f -r /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/ > /dev/null 2>&1 && sleep 0'
2955 1594992403.36957: in local.exec_command()
EXEC /bin/sh -c 'rm -f -r /root/.ansible/tmp/ansible-tmp-1594992402.440076-2955-56461824364637/ > /dev/null 2>&1 && sleep 0'
2955 1594992403.36976: opening command with Popen()
2955 1594992403.38146: done running command with Popen()
2955 1594992403.38169: getting output with communicate()
2955 1594992403.38423: done communicating
2955 1594992403.38431: done with local.exec_command()
2955 1594992403.38440: _low_level_execute_command() done: rc=0, stdout=, stderr=
2955 1594992403.38454: handler run complete
2955 1594992403.38465: attempt loop complete, returning result
2955 1594992403.38482: _execute() done
2955 1594992403.38489: dumping result to json
2955 1594992403.38497: done dumping result, returning
2955 1594992403.38518: done running TaskExecutor() for helper/TASK: mirror_registry : Enable container-mirror-registry on boot and start it [0050568a-9a66-f27c-56e2-000000000025]
2955 1594992403.38539: sending task result for task 0050568a-9a66-f27c-56e2-000000000025
2955 1594992403.38607: done sending task result for task 0050568a-9a66-f27c-56e2-000000000025
2955 1594992403.38614: WORKER PROCESS EXITING
2673 1594992403.38961: marking helper as failed
2673 1594992403.38984: marking host helper failed, current state: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (HOST STATE: block=0, task=5, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (HOST STATE: block=0, task=4, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2673 1594992403.38995: ^ failed state is now: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (HOST STATE: block=0, task=5, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (HOST STATE: block=0, task=4, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_TASKS, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2673 1594992403.39002: getting the next task for host helper
2673 1594992403.39012: done getting next task for host helper
2673 1594992403.39017: ^ task is: None
2673 1594992403.39022: ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_TASKS, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
fatal: [helper]: FAILED! => {
"changed": false,
"invocation": {
"module_args": {
"daemon_reexec": false,
"daemon_reload": false,
"enabled": true,
"force": null,
"masked": null,
"name": "container-mirror-registry",
"no_block": false,
"scope": null,
"state": "started",
"user": null
}
},
"msg": "Unable to start service container-mirror-registry: Job for container-mirror-registry.service failed because the control process exited with error code.\nSee "systemctl status container-mirror-registry.service" and "journalctl -xe" for details.\n"
}
2673 1594992403.39095: no more pending results, returning what we have
2673 1594992403.39103: results queue empty
2673 1594992403.39109: checking for any_errors_fatal
2673 1594992403.39117: done checking for any_errors_fatal
2673 1594992403.39122: checking for max_fail_percentage
2673 1594992403.39127: done checking for max_fail_percentage
2673 1594992403.39132: checking to see if all hosts have failed and the running result is not ok
2673 1594992403.39137: done checking to see if all hosts have failed
2673 1594992403.39141: getting the remaining hosts for this loop
2673 1594992403.39147: done getting the remaining hosts for this loop
2673 1594992403.39157: building list of next tasks for hosts
2673 1594992403.39162: getting the next task for host helper
2673 1594992403.39170: done getting next task for host helper
2673 1594992403.39177: ^ task is: None
2673 1594992403.39182: ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_TASKS, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2673 1594992403.39188: done building task lists
2673 1594992403.39192: counting tasks in each state of execution
2673 1594992403.39198: done counting tasks in each state of execution:
num_setups: 0
num_tasks: 0
num_rescue: 0
num_always: 0
2673 1594992403.39203: all hosts are done, so returning None's for all hosts
2673 1594992403.39209: done queuing things up, now waiting for results queue to drain
2673 1594992403.39214: results queue empty
2673 1594992403.39218: checking for any_errors_fatal
2673 1594992403.39223: done checking for any_errors_fatal
2673 1594992403.39227: checking for max_fail_percentage
2673 1594992403.39231: done checking for max_fail_percentage
2673 1594992403.39236: checking to see if all hosts have failed and the running result is not ok
2673 1594992403.39240: done checking to see if all hosts have failed
2673 1594992403.39245: getting the next task for host helper
2673 1594992403.39253: done getting next task for host helper
2673 1594992403.39258: ^ task is: None
2673 1594992403.39264: ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_TASKS, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2673 1594992403.39272: running handlers

PLAY RECAP ************************************************************************************************************************************************************************************
helper : ok=10 changed=0 unreachable=0 failed=1 skipped=6 rescued=0 ignored=0

2673 1594992403.39457: RUNNING CLEANUP