-
Bug
-
Resolution: Unresolved
-
Normal
-
None
-
4.16
-
Low
-
None
-
False
-
Looking at the logs for ironic-python-agent in a preprovisioning image, we get each log message twice - once directly from the agent process and once from podman:
Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.834 1 DEBUG ironic_python_agent.ironic_api_client [-] Heartbeat: announcing callback URL https://10.9.53.20:9999, API version is 1.68 heartbeat /usr/lib/python3.9/site-packages/ironic_python_agent/ironic_api_client.p y:186 Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.834 1 DEBUG ironic_python_agent.ironic_api_client [-] Heartbeat: announcing callback URL https://10.9.53.20:9999, API version is 1.68 heartbeat /usr/lib/python3.9/site-packages/ironic_python_agent/ironic_api_client.py:186 Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent [-] error sending heartbeat to ['https://10.9.49.125:6385']: ironic_python_agent.errors.HeartbeatError: Error heartbeating to agent API: Error 404: Node 6f7546a2-f49e-4d8d-88f6-a462d53 868b6 could not be found. Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent Traceback (most recent call last): Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent File "/usr/lib/python3.9/site-packages/ironic_python_agent/agent.py", line 148, in do_heartbeat Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent self.api.heartbeat( Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent File "/usr/lib/python3.9/site-packages/ironic_python_agent/ironic_api_client.py", line 200, in heartbeat Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent raise errors.HeartbeatError(error) Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent ironic_python_agent.errors.HeartbeatError: Error heartbeating to agent API: Error 404: Node 6f7546a2-f49e-4d8d-88f6-a462d53868b6 could not be found. Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent Oct 30 14:23:45 localhost.localdomain podman[3035]: 2024-10-30 14:23:44.867 1 INFO ironic_python_agent.agent [-] sleeping before next heartbeat, interval: 5.029721378959369 Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent [-] error sending heartbeat to ['https://10.9.49.125:6385']: ironic_python_agent.errors.HeartbeatError: Error heartbeating to agent API: Error 404: Node 6f7546a2-f49e-4d8d-88f6-a462d53868b6 could not be found. Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent Traceback (most recent call last): Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent File "/usr/lib/python3.9/site-packages/ironic_python_agent/agent.py", line 148, in do_heartbeat Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent self.api.heartbeat( Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent File "/usr/lib/python3.9/site-packages/ironic_python_agent/ironic_api_client.py", line 200, in heartbeat Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent raise errors.HeartbeatError(error) Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent ironic_python_agent.errors.HeartbeatError: Error heartbeating to agent API: Error 404: Node 6f7546a2-f49e-4d8d-88f6-a462d53868b6 could not be found. Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.866 1 ERROR ironic_python_agent.agent Oct 30 14:23:44 localhost.localdomain ironic-agent[3071]: 2024-10-30 14:23:44.867 1 INFO ironic_python_agent.agent [-] sleeping before next heartbeat, interval: 5.029721378959369
This is confusing and unnecessary, especially as the two sets of logs can be interleaved (note also the non-monotonic timestamps in the third column).
The log above actually comes from a ZTP deployment (the one in OCPBUGS-44026), but the IPA configuration even for that ultimately comes from the image-customization-controller.
Currently there is no log driver flag passed to podman so we get the default, which is journald. We have the use_stderr option set in the IPA config so logs get written to stderr, which podman will send to journald. We are also running the podman pod in the foreground, which I think will cause it to also pass the stderr to systemd, which also sends it to the journal.
I believe another side-effect of this misconfiguration is that one lot of logs show up red in journalctl and the other don't. Ideally we would have colour-coded logs by severity. This can be turned on for the stderr logging by setting log_color in the IPA config, but it might be better to enable use-journal instead of use-stderr so we get native logging to journald.
