Bug 14041

Summary:	qemuarm-alt failed to load rpcbind
Product:	[Build System, Metadata & Runtime] OE-Core	Reporter:	Richard Purdie <richard.purdie>
Component:	core	Assignee:	Kai Kang <kai.kang>
Status:	RESOLVED WORKSFORME	QA Contact:
Severity:	normal
Priority:	Medium	CC:	alex.kanavin, alexandre.belloni, anuj.mittal, meta.mr.watcher, meta.watcher, randy.macleod
Version:	3.2
Target Milestone:	4.0
Hardware:	x86
OS:	Multiple
Whiteboard:	AB-INT
OS type for building Yocto:	---	Type of Regression:	---
Verified:		Documentation change:	No (bug/feature does not impact docs)

Description Richard Purdie 2020-09-06 01:39:59 UTC

https://autobuilder.yoctoproject.org/typhoon/#/builders/110/builds/1313

Traceback (most recent call last):
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 36, in wrapped_f
    return func(*args, **kwargs)
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/runtime/cases/parselogs.py", line 375, in test_parselogs
    self.assertEqual(errcount, 0, msg=self.msg)
AssertionError: 6 != 0 : Log: /home/pokybuild/yocto-worker/qemuarm-alt/build/build/tmp/work/qemuarm-poky-linux-gnueabi/core-image-sato-sdk/1.0-r0/target_logs/dmesg_output.log
-----------------------
Central error: [   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
***********************
[   10.585222] systemd[1]: Created slice system-modprobe.slice.
[   10.607878] systemd[1]: Created slice system-serial\x2dgetty.slice.
[   10.640360] systemd[1]: Created slice User and Session Slice.
[   10.668022] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[   10.689829] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   10.711352] systemd[1]: Reached target Host and Network Name Lookups.
[   10.739071] systemd[1]: Reached target Paths.
[   10.758878] systemd[1]: Reached target Remote File Systems.
[   10.780112] systemd[1]: Reached target Slices.
[   10.798513] systemd[1]: Reached target Swap.
[   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
[   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
[   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
[   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
[   10.975831] systemd[1]: Dependency failed for RPC Bind.
[   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
[   11.008350] systemd[1]: Reached target RPC Port Mapper.
[   11.037311] systemd[1]: Listening on Syslog Socket.
[   11.059530] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   11.179181] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   11.192945] systemd[1]: Listening on Journal Socket (/dev/log).

***********************
Central error: [   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
***********************
[   10.607878] systemd[1]: Created slice system-serial\x2dgetty.slice.
[   10.640360] systemd[1]: Created slice User and Session Slice.
[   10.668022] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[   10.689829] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   10.711352] systemd[1]: Reached target Host and Network Name Lookups.
[   10.739071] systemd[1]: Reached target Paths.
[   10.758878] systemd[1]: Reached target Remote File Systems.
[   10.780112] systemd[1]: Reached target Slices.
[   10.798513] systemd[1]: Reached target Swap.
[   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
[   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
[   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
[   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
[   10.975831] systemd[1]: Dependency failed for RPC Bind.
[   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
[   11.008350] systemd[1]: Reached target RPC Port Mapper.
[   11.037311] systemd[1]: Listening on Syslog Socket.
[   11.059530] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   11.179181] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   11.192945] systemd[1]: Listening on Journal Socket (/dev/log).
[   11.212754] systemd[1]: Listening on Journal Socket.

***********************
Central error: [   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
***********************
[   10.640360] systemd[1]: Created slice User and Session Slice.
[   10.668022] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[   10.689829] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   10.711352] systemd[1]: Reached target Host and Network Name Lookups.
[   10.739071] systemd[1]: Reached target Paths.
[   10.758878] systemd[1]: Reached target Remote File Systems.
[   10.780112] systemd[1]: Reached target Slices.
[   10.798513] systemd[1]: Reached target Swap.
[   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
[   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
[   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
[   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
[   10.975831] systemd[1]: Dependency failed for RPC Bind.
[   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
[   11.008350] systemd[1]: Reached target RPC Port Mapper.
[   11.037311] systemd[1]: Listening on Syslog Socket.
[   11.059530] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   11.179181] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   11.192945] systemd[1]: Listening on Journal Socket (/dev/log).
[   11.212754] systemd[1]: Listening on Journal Socket.
[   11.237268] systemd[1]: Listening on Network Service Netlink Socket.

***********************
Central error: [   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
***********************
[   10.668022] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[   10.689829] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   10.711352] systemd[1]: Reached target Host and Network Name Lookups.
[   10.739071] systemd[1]: Reached target Paths.
[   10.758878] systemd[1]: Reached target Remote File Systems.
[   10.780112] systemd[1]: Reached target Slices.
[   10.798513] systemd[1]: Reached target Swap.
[   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
[   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
[   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
[   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
[   10.975831] systemd[1]: Dependency failed for RPC Bind.
[   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
[   11.008350] systemd[1]: Reached target RPC Port Mapper.
[   11.037311] systemd[1]: Listening on Syslog Socket.
[   11.059530] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   11.179181] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   11.192945] systemd[1]: Listening on Journal Socket (/dev/log).
[   11.212754] systemd[1]: Listening on Journal Socket.
[   11.237268] systemd[1]: Listening on Network Service Netlink Socket.
[   11.258559] systemd[1]: Listening on udev Control Socket.

***********************
Central error: [   10.975831] systemd[1]: Dependency failed for RPC Bind.
***********************
[   10.689829] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   10.711352] systemd[1]: Reached target Host and Network Name Lookups.
[   10.739071] systemd[1]: Reached target Paths.
[   10.758878] systemd[1]: Reached target Remote File Systems.
[   10.780112] systemd[1]: Reached target Slices.
[   10.798513] systemd[1]: Reached target Swap.
[   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
[   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
[   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
[   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
[   10.975831] systemd[1]: Dependency failed for RPC Bind.
[   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
[   11.008350] systemd[1]: Reached target RPC Port Mapper.
[   11.037311] systemd[1]: Listening on Syslog Socket.
[   11.059530] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   11.179181] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   11.192945] systemd[1]: Listening on Journal Socket (/dev/log).
[   11.212754] systemd[1]: Listening on Journal Socket.
[   11.237268] systemd[1]: Listening on Network Service Netlink Socket.
[   11.258559] systemd[1]: Listening on udev Control Socket.
[   11.280064] systemd[1]: Listening on udev Kernel Socket.

***********************
Central error: [   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
***********************
[   10.711352] systemd[1]: Reached target Host and Network Name Lookups.
[   10.739071] systemd[1]: Reached target Paths.
[   10.758878] systemd[1]: Reached target Remote File Systems.
[   10.780112] systemd[1]: Reached target Slices.
[   10.798513] systemd[1]: Reached target Swap.
[   10.897277] systemd[1]: rpcbind.socket: Failed to receive listening socket (0.0.0.0:111): Input/output error
[   10.910495] systemd[1]: rpcbind.socket: Failed to listen on sockets: Input/output error
[   10.922057] systemd[1]: rpcbind.socket: Failed with result 'resources'.
[   10.944044] systemd[1]: Failed to listen on RPCbind Server Activation Socket.
[   10.975831] systemd[1]: Dependency failed for RPC Bind.
[   10.998071] systemd[1]: rpcbind.service: Job rpcbind.service/start failed with result 'dependency'.
[   11.008350] systemd[1]: Reached target RPC Port Mapper.
[   11.037311] systemd[1]: Listening on Syslog Socket.
[   11.059530] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   11.179181] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   11.192945] systemd[1]: Listening on Journal Socket (/dev/log).
[   11.212754] systemd[1]: Listening on Journal Socket.
[   11.237268] systemd[1]: Listening on Network Service Netlink Socket.
[   11.258559] systemd[1]: Listening on udev Control Socket.
[   11.280064] systemd[1]: Listening on udev Kernel Socket.
[   11.300351] systemd[1]: Listening on User Database Manager Socket.

***********************
6 errors found in logs.

Stdout:
Machine information: 
*******************************
Machine name: qemuarm
CPU:  ARMv7 Processor rev 1 (v7l)
Arch: armv7l
Physical cores: 
Logical cores: 1
*******************************


Test requires ptest-runner to be installed
Test requires ptest-runner to be installed
Traceback (most recent call last):
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 36, in wrapped_f
    return func(*args, **kwargs)
  File "/home/pokybuild/yocto-worker/qemuarm-alt/build/meta/lib/oeqa/runtime/cases/systemd.py", line 98, in test_systemd_failed
    self.assertTrue(match, msg='Some systemd units failed:\n%s' % output)
AssertionError: None is not true : Some systemd units failed:
  UNIT           LOAD   ACTIVE SUB    DESCRIPTION                     
● rpcbind.socket loaded failed failed RPCbind Server Activation Socket

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

1 loaded units listed.● qemuarm
    State: degraded
     Jobs: 0 queued
   Failed: 1 units
    Since: Sat 2020-09-05 21:52:46 UTC; 32min ago
   CGroup: /
           ├─user.slice 
           │ └─user-0.slice 
           │   ├─session-c198.scope 
           │   │ ├─19942 sshd: root@notty
           │   │ ├─19944 sh -c export PATH=/usr/sbin:/sbin:/usr/bin:/bin; SYSTEMD_BUS_TIMEOUT=240s systemctl status --full --failed
           │   │ └─19945 systemctl status --full --failed
           │   ├─session-c1.scope 
           │   │ ├─224 /bin/login --
           │   │ └─324 -sh
           │   └─user@0.service …
           │     └─init.scope 
           │       ├─277 /lib/systemd/systemd --user
           │       └─280 (sd-pam)
           ├─init.scope 
           │ └─1 /sbin/init
           └─system.slice 
             ├─rngd.service 
             │ └─162 /usr/sbin/rngd -f -r /dev/hwrng
             ├─systemd-timesyncd.service 
             │ └─11205 /lib/systemd/systemd-timesyncd
             ├─dbus.service 
             │ └─186 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
             ├─avahi-daemon.service 
             │ ├─211 avahi-daemon: running [qemuarm.local]
             │ └─217 avahi-daemon: chroot helper
             ├─system-serial\x2dgetty.slice 
             │ └─serial-getty@hvc0.service 
             │   └─222 /sbin/agetty -8 -L hvc0 115200 xterm
             ├─system-getty.slice 
             │ └─getty@tty1.service 
             │   └─218 /sbin/agetty -o -p -- \u --noclear tty1 linux
             ├─wpa_supplicant.service 
             │ └─228 /usr/sbin/wpa_supplicant -u
             ├─connman.service 
             │ └─208 /usr/sbin/connmand -n
             ├─systemd-logind.service 
             │ └─191 /lib/systemd/systemd-logind
             ├─crond.service 
             │ └─185 /usr/sbin/crond -n
             ├─systemd-udevd.service 
             │ └─148 /lib/systemd/systemd-udevd
             ├─ofono.service 
             │ └─189 /usr/sbin/ofonod -n
             ├─tcf-agent.service 
             │ └─216 /usr/sbin/tcf-agent -d -L- -l0
             ├─busybox-syslog.service 
             │ └─18232 /sbin/syslogd -n
             ├─systemd-journald.service 
             │ └─131 /lib/systemd/systemd-journald
             ├─busybox-klogd.service 
             │ └─183 /sbin/klogd -n
             ├─xserver-nodm.service 
             │ ├─239 xinit /etc/X11/Xsession -- /usr/bin/Xorg :0 -br -pn
             │ ├─242 /usr/bin/Xorg :0 -br -pn
             │ ├─261 matchbox-window-manager -theme Sato -use_cursor no
             │ ├─270 dbus-launch --sh-syntax --exit-with-session
             │ ├─274 /usr/bin/dbus-daemon --syslog --fork --print-pid 5 --print-address 7 --session
             │ ├─285 /usr/libexec/at-spi-bus-launcher --launch-immediately
             │ ├─289 connman-applet
             │ ├─311 /usr/bin/dbus-daemon --config-file=/usr/share/defaults/at-spi2/accessibility.conf --nofork --print-address 3
             │ ├─312 matchbox-desktop
             │ ├─314 matchbox-panel --start-applets showdesktop,windowselector --end-applets clock,,systray,startup-notify,notify
             │ ├─317 /usr/bin/pulseaudio --start --log-target=syslog
             │ ├─321 /usr/libexec/gconfd-2
             │ ├─322 /usr/bin/settings-daemon
             │ └─329 /usr/libexec/at-spi2-registryd --use-gnome-session
             ├─systemd-networkd.service 
             │ └─203 /lib/systemd/systemd-networkd
             └─systemd-userdbd.service 
               ├─  246 /lib/systemd/systemd-userdbd
               ├─19760 systemd-userwork
               ├─19761 systemd-userwork
               └─19798 systemd-userwork

Startup finished in 7.600s (kernel) + 49.224s (userspace) = 56.825s.

Comment 1 Richard Purdie 2020-09-06 01:40:45 UTC

tumbleweed-ty-3

Comment 2 Randy MacLeod 2020-10-15 08:01:54 UTC

Kai are you able to reproduce this?

Comment 3 Alexander Kanavin 2020-10-25 11:11:02 UTC

I think I have seen the same one here, only even more services couldn't start:

AssertionError: None is not true : Some systemd units failed:
  UNIT                   LOAD   ACTIVE SUB    DESCRIPTION                     
● proc-fs-nfsd.mount     loaded failed failed NFSD configuration filesystem   
● psplash-start.service  loaded failed failed Start psplash boot splash screen
● rpcbind.service        loaded failed failed RPC Bind                        
● systemd-sysctl.service loaded failed failed Apply Kernel Variables          

https://autobuilder.yoctoproject.org/typhoon/#/builders/110/builds/1512/steps/8/logs/step1c

Comment 4 Alexandre Belloni 2021-05-11 10:25:47 UTC

https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/2244
master-next on ubuntu1804-ty-3

Central error: Apr 30 11:52:05 qemux86 dbus-daemon[155]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)


https://autobuilder.yoctoproject.org/typhoon/#/builders/102/builds/1633
master-next on ubuntu1804-ty-3

Central error: [   27.795314] systemd[1]: Failed to configure loopback device: Connection timed out

Comment 5 Anuj Mittal 2021-08-30 07:43:29 UTC

(In reply to comment #4)
> https://autobuilder.yoctoproject.org/typhoon/#/builders/102/builds/1633
> master-next on ubuntu1804-ty-3
> 
> Central error: [   27.795314] systemd[1]: Failed to configure loopback
> device: Connection timed out

Got this during do_testimage for qemuppc-alt, core-image-sato-sdk:

https://autobuilder.yoctoproject.org/typhoon/#/builders/107/builds/2005

Traceback (most recent call last):
  File "/home/pokybuild/yocto-worker/qemuppc-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 36, in wrapped_f
    return func(*args, **kwargs)
  File "/home/pokybuild/yocto-worker/qemuppc-alt/build/meta/lib/oeqa/runtime/cases/parselogs.py", line 383, in test_parselogs
    self.assertEqual(errcount, 0, msg=self.msg)
AssertionError: 1 != 0 : Log: /home/pokybuild/yocto-worker/qemuppc-alt/build/build/tmp/work/qemuppc-poky-linux/core-image-sato-sdk/1.0-r0/target_logs/dmesg_output.log
-----------------------
Central error: [   27.047731] systemd[1]: Failed to configure loopback device: Connection timed out
***********************
[    6.563662] devtmpfs: mounted

Comment 6 Randy MacLeod 2022-03-17 14:40:29 UTC

Anuj's bug seems to be a different root cause. The other two also seem to be unrelated. The unifying theme is that they involve systemd. 

Re-open if seen again.