Bug 2101490

Summary:	crio service doesn't start automatically during the deployment after written to the disk image is booted the first time
Product:	OpenShift Container Platform	Reporter:	Alexander Chuzhoy <sasha>
Component:	Installer	Assignee:	Rom Freiman <rfreiman>
Installer sub component:	Single Node OpenShift	QA Contact:	Omri Hochman <ohochman>
Status:	CLOSED DUPLICATE	Docs Contact:
Severity:	high
Priority:	unspecified
Version:	4.11
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2022-06-27 17:13:39 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Alexander Chuzhoy 2022-06-27 15:29:38 UTC

crio service doesn't start automatically during the deployment after written to the disk image is booted the first time



Running journalctl -u crio shows:



-- Logs begin at Mon 2022-06-27 15:13:31 UTC, end at Mon 2022-06-27 15:20:25 UTC. --
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com systemd[1]: Starting Container Runtime Interface for OCI (CRI-O)...
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.946915534Z" level=info msg="Starting CRI-O, version: 1.24.1-5.rhaos4.11.gitff26732.el8, git: ()"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947048378Z" level=info msg="Node configuration value for hugetlb cgroup is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947057244Z" level=info msg="Node configuration value for pid cgroup is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947121034Z" level=info msg="Node configuration value for memoryswap cgroup is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947134407Z" level=info msg="Node configuration value for cgroup v2 is false"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.953465654Z" level=info msg="Node configuration value for systemd CollectMode is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.958790107Z" level=info msg="Node configuration value for systemd AllowedCPUs is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.960512010Z" level=info msg="Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.964477855Z" level=info msg="Conmon does support the --sync option"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.964547352Z" level=info msg="Conmon does support the --log-global-size-max option"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965746420Z" level=info msg="Using seccomp default profile when unspecified: true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965789098Z" level=info msg="No seccomp profile specified, using the internal default"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965797899Z" level=info msg="AppArmor is disabled by the system or at CRI-O build-time"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965803144Z" level=info msg="No blockio config file specified, blockio not configured"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965808552Z" level=info msg="RDT not available in the host system"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965909911Z" level=info msg="Updated default CNI network name to "
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.999410054Z" level=warning msg="Error encountered when checking whether cri-o should wipe images: version file /var/lib/crio/version not found: open /var/lib/crio/version: no such file or directory"
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:03.000111233Z" level=fatal msg="Failed to start streaming server: listen tcp [fd2e:6f44:5dd8::51]:10010: bind: cannot assign requested address"
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: crio.service: Main process exited, code=exited, status=1/FAILURE
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: crio.service: Failed with result 'exit-code'.
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: Failed to start Container Runtime Interface for OCI (CRI-O).
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: crio.service: Consumed 85ms CPU time



Was able to manually start the crio service:



-- Logs begin at Mon 2022-06-27 15:13:31 UTC, end at Mon 2022-06-27 15:26:04 UTC. --
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com systemd[1]: Starting Container Runtime Interface for OCI (CRI-O)...
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.946915534Z" level=info msg="Starting CRI-O, version: 1.24.1-5.rhaos4.11.gitff26732.el8, git: ()"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947048378Z" level=info msg="Node configuration value for hugetlb cgroup is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947057244Z" level=info msg="Node configuration value for pid cgroup is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947121034Z" level=info msg="Node configuration value for memoryswap cgroup is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.947134407Z" level=info msg="Node configuration value for cgroup v2 is false"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.953465654Z" level=info msg="Node configuration value for systemd CollectMode is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.958790107Z" level=info msg="Node configuration value for systemd AllowedCPUs is true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.960512010Z" level=info msg="Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.964477855Z" level=info msg="Conmon does support the --sync option"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.964547352Z" level=info msg="Conmon does support the --log-global-size-max option"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965746420Z" level=info msg="Using seccomp default profile when unspecified: true"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965789098Z" level=info msg="No seccomp profile specified, using the internal default"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965797899Z" level=info msg="AppArmor is disabled by the system or at CRI-O build-time"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965803144Z" level=info msg="No blockio config file specified, blockio not configured"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965808552Z" level=info msg="RDT not available in the host system"
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.965909911Z" level=info msg="Updated default CNI network name to "
Jun 27 15:16:02 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:02.999410054Z" level=warning msg="Error encountered when checking whether cri-o should wipe images: version file /var/lib/crio/version not found: open /var/lib/crio/version: no such file or directory"
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com crio[2351]: time="2022-06-27 15:16:03.000111233Z" level=fatal msg="Failed to start streaming server: listen tcp [fd2e:6f44:5dd8::51]:10010: bind: cannot assign requested address"
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: crio.service: Main process exited, code=exited, status=1/FAILURE
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: crio.service: Failed with result 'exit-code'.
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: Failed to start Container Runtime Interface for OCI (CRI-O).
Jun 27 15:16:03 api.sno-0.qe.lab.redhat.com systemd[1]: crio.service: Consumed 85ms CPU time
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com systemd[1]: Starting Container Runtime Interface for OCI (CRI-O)...
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.940389375Z" level=info msg="Starting CRI-O, version: 1.24.1-5.rhaos4.11.gitff26732.el8, git: ()"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.940766061Z" level=info msg="Node configuration value for hugetlb cgroup is true"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.940845676Z" level=info msg="Node configuration value for pid cgroup is true"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.940960196Z" level=info msg="Node configuration value for memoryswap cgroup is true"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.941004988Z" level=info msg="Node configuration value for cgroup v2 is false"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.947141968Z" level=info msg="Node configuration value for systemd CollectMode is true"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.952029642Z" level=info msg="Node configuration value for systemd AllowedCPUs is true"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.952956467Z" level=info msg="Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956202734Z" level=info msg="Conmon does support the --sync option"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956272767Z" level=info msg="Conmon does support the --log-global-size-max option"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956661699Z" level=info msg="Using seccomp default profile when unspecified: true"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956728316Z" level=info msg="No seccomp profile specified, using the internal default"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956768451Z" level=info msg="AppArmor is disabled by the system or at CRI-O build-time"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956828828Z" level=info msg="No blockio config file specified, blockio not configured"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956875584Z" level=info msg="RDT not available in the host system"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.956972393Z" level=info msg="Updated default CNI network name to "
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.964436494Z" level=warning msg="Error encountered when checking whether cri-o should wipe images: version file /var/lib/crio/version not found: open /var/lib/crio/version: no such file or directory"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com crio[3665]: time="2022-06-27 15:20:30.965334531Z" level=info msg="Serving metrics on :9537 via HTTP"
Jun 27 15:20:30 api.sno-0.qe.lab.redhat.com systemd[1]: Started Container Runtime Interface for OCI (CRI-O).



No pods are started automatically after that.
Tried to restart the bootkube service and saw that the pods began to start after that.

Comment 1 Alexander Chuzhoy 2022-06-27 15:30:05 UTC

happens with 4.11.0-0.nightly-2022-06-25-081133

Comment 2 Alexander Chuzhoy 2022-06-27 17:13:39 UTC


*** This bug has been marked as a duplicate of bug 2099794 ***