Bug 9520

Steps to Reproduce it:

a) Download the core-image-sato-sdk image from autobuilder( link available in the description of this bug)
	b) Make checkout on the poky commit (available in the description_ $ git://git.yoctoproject.org/poky"
		- In poky directory checkout on the desired commit: "git checkout <commit-id>"
	c) source the environment:
		- In poky directory ( "cd ~/poky"): " source oe-init-build-env"
	d) Add some information in local. conf :
		* local.conf path: ~/poky/build/conf
		- at the end of file add:	
			INHERIT += "testimage"
	
			TEST_TARGET = "simpleremote"
	
			TEST_TARGET_IP = "DUT ip"

			TEST_SERVER_IP = "workstation ip"
	
		- change the machine: MACHINE ??= "genericx86-64"
	e) add in bblayers.conf:
		* bblayers.conf path: ~/poky/build/conf
		- in " BBLAYERS ?= " \ " section add meta-selftest respecting the pattern from above
	f) in ~poky/build directory, in command line, type the following commands in terminal:
$ bitbake rpm psplash //wait for tasks to be executed
$ bitbake package-index //wait for tasks to be executed
// after finishing the tasks copy the image manifest (core-image-sato-sdk-genericx86-64.manifest) from autobuilder at the following path:
"~poky/build/tmp/deploy/images/genericx86-64/" ( if "/tmp/deploy/images/genericx86" does not exist create new directories with this path)
After this, type in a terminal:
$ bitbake core-image-sato-sdk -c testimage

I retested this standalone on a NUC D54250WYK and a NUC5i5 with the released image and was not able to reproduce this problem, if you still have this issue, please preserve the image and machine so I can do some direct forensics on it.

test_parselogs fails on 1.8.2.rc3: c9f0a99050ec0050f0dbcd55d0cd2ab18848113f
ENV: genericx86-64 on NUC

ERROR:

FAIL: test_parselogs (oeqa.runtime.parselogs.ParseLogsTest)
| ----------------------------------------------------------------------
| Traceback (most recent call last):
|   File "/home/romanalx/poky-1.8.2/poky/meta/lib/oeqa/utils/decorators.py", line 86, in wrapped_f
|     return f(*args)
|   File "/home/romanalx/poky-1.8.2/poky/meta/lib/oeqa/runtime/parselogs.py", line 212, in test_parselogs
|     self.assertEqual(errcount, 0, msg=self.msg)
| AssertionError: 6 != 0 : Log: /tmp/dmesg_output.log

Put this on new.

(In reply to comment #2)
> I retested this standalone on a NUC D54250WYK and a NUC5i5 with the released
> image and was not able to reproduce this problem, if you still have this
> issue, please preserve the image and machine so I can do some direct
> forensics on it.

Hi I ran this again, and failed on NUC D54250WYK.
Build Configuration:
BB_VERSION        = "1.31.0"
BUILD_SYS         = "x86_64-linux"
NATIVELSBSTRING   = "Ubuntu-15.10"
TARGET_SYS        = "x86_64-poky-linux"
MACHINE           = "genericx86-64"
DISTRO            = "poky"
DISTRO_VERSION    = "2.1+snapshot-20160531"
TUNE_FEATURES     = "m64 core2"
TARGET_FPU        = ""
meta-selftest     
meta              
meta-yocto        
meta-yocto-bsp    = "master:56ab1a53453525f3200a8c4d1e1963df0e4e8890"

Attached you can find logs " testimage.26233"

Created attachment 3197 [details]
testimage.26233

When testing qemuarm 2 tests fail with similar error:

FAIL: test_smart_add_rpmdir (oeqa.runtime.smart.SmartRepoTest)
| ----------------------------------------------------------------------
| Traceback (most recent call last):
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py", line 109, in wrapped_f
|     return func(*args, **kwargs)
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py", line 161, in test_smart_add_rpmdir
|     self.smart('channel --add myrpmdir type=rpm-dir path=/tmp/myrpmdir -y')
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py", line 97, in wrapped_f
|     return f(*args, **kwargs)
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py", line 22, in smart
|     self.assertEqual(status, expected, message)
| AssertionError: 1 != 0 : smart channel --add myrpmdir type=rpm-dir path=/tmp/myrpmdir -y
| Channel alias 'myrpmdir' is already in use.
| Channel alias: Traceback (most recent call last):
|   File "/usr/bin/smart", line 200, in <module>
|     main(sys.argv[1:])
|   File "/usr/bin/smart", line 173, in main
|     exitcode = iface.run(opts.command, opts.argv)
|   File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in run
|     result = _command.main(self._ctrl, opts)
|   File "/usr/lib/python2.7/site-packages/smart/commands/channel.py", line 247, in main
|     alias = raw_input(_("Channel alias: ")).strip()
|   File "/usr/lib/python2.7/site-packages/smart/__init__.py", line 72, in raw_input
|     res = _raw_input(prompt)
| EOFError: EOF when reading a line
| 
| ======================================================================
| FAIL: test_smart_local_dir (oeqa.runtime.smart.SmartRepoTest)
| ----------------------------------------------------------------------
| Traceback (most recent call last):
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py", line 109, in wrapped_f
|     return func(*args, **kwargs)
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py", line 143, in test_smart_local_dir
|     self.smart('channel --add myrpmdir type=rpm-dir path=/tmp/myrpmdir -y')
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py", line 97, in wrapped_f
|     return f(*args, **kwargs)
|   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py", line 22, in smart
|     self.assertEqual(status, expected, message)
| AssertionError: 1 != 0 : smart channel --add myrpmdir type=rpm-dir path=/tmp/myrpmdir -y
| Channel alias 'myrpmdir' is already in use.
| Channel alias: Traceback (most recent call last):
|   File "/usr/bin/smart", line 200, in <module>
|     main(sys.argv[1:])
|   File "/usr/bin/smart", line 173, in main
|     exitcode = iface.run(opts.command, opts.argv)
|   File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in run
|     result = _command.main(self._ctrl, opts)
|   File "/usr/lib/python2.7/site-packages/smart/commands/channel.py", line 247, in main
|     alias = raw_input(_("Channel alias: ")).strip()
|   File "/usr/lib/python2.7/site-packages/smart/__init__.py", line 72, in raw_input
|     res = _raw_input(prompt)
| EOFError: EOF when reading a line


I'm mentioning this happens only on qemuarm machine.

(In reply to comment #7)
> When testing qemuarm 2 tests fail with similar error:
> 
> FAIL: test_smart_add_rpmdir (oeqa.runtime.smart.SmartRepoTest)
> | ----------------------------------------------------------------------
> | Traceback (most recent call last):
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py",
> line 109, in wrapped_f
> |     return func(*args, **kwargs)
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py",
> line 161, in test_smart_add_rpmdir
> |     self.smart('channel --add myrpmdir type=rpm-dir path=/tmp/myrpmdir -y')
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py",
> line 97, in wrapped_f
> |     return f(*args, **kwargs)
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py",
> line 22, in smart
> |     self.assertEqual(status, expected, message)
> | AssertionError: 1 != 0 : smart channel --add myrpmdir type=rpm-dir
> path=/tmp/myrpmdir -y
> | Channel alias 'myrpmdir' is already in use.
> | Channel alias: Traceback (most recent call last):
> |   File "/usr/bin/smart", line 200, in <module>
> |     main(sys.argv[1:])
> |   File "/usr/bin/smart", line 173, in main
> |     exitcode = iface.run(opts.command, opts.argv)
> |   File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in
> run
> |     result = _command.main(self._ctrl, opts)
> |   File "/usr/lib/python2.7/site-packages/smart/commands/channel.py", line
> 247, in main
> |     alias = raw_input(_("Channel alias: ")).strip()
> |   File "/usr/lib/python2.7/site-packages/smart/__init__.py", line 72, in
> raw_input
> |     res = _raw_input(prompt)
> | EOFError: EOF when reading a line
> | 
> | ======================================================================
> | FAIL: test_smart_local_dir (oeqa.runtime.smart.SmartRepoTest)
> | ----------------------------------------------------------------------
> | Traceback (most recent call last):
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py",
> line 109, in wrapped_f
> |     return func(*args, **kwargs)
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py",
> line 143, in test_smart_local_dir
> |     self.smart('channel --add myrpmdir type=rpm-dir path=/tmp/myrpmdir -y')
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/utils/decorators.py",
> line 97, in wrapped_f
> |     return f(*args, **kwargs)
> |   File "/home/romanalx/master2.2/poky/meta/lib/oeqa/runtime/smart.py",
> line 22, in smart
> |     self.assertEqual(status, expected, message)
> | AssertionError: 1 != 0 : smart channel --add myrpmdir type=rpm-dir
> path=/tmp/myrpmdir -y
> | Channel alias 'myrpmdir' is already in use.
> | Channel alias: Traceback (most recent call last):
> |   File "/usr/bin/smart", line 200, in <module>
> |     main(sys.argv[1:])
> |   File "/usr/bin/smart", line 173, in main
> |     exitcode = iface.run(opts.command, opts.argv)
> |   File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in
> run
> |     result = _command.main(self._ctrl, opts)
> |   File "/usr/lib/python2.7/site-packages/smart/commands/channel.py", line
> 247, in main
> |     alias = raw_input(_("Channel alias: ")).strip()
> |   File "/usr/lib/python2.7/site-packages/smart/__init__.py", line 72, in
> raw_input
> |     res = _raw_input(prompt)
> | EOFError: EOF when reading a line
> 
> 
> I'm mentioning this happens only on qemuarm machine.

This appears to be a different issue and is RPM/SMART not related to the udevd inotify issue, please file a new bug

In trying to sort this bug out, we have the original issue parselog failure with udevd and inotify, then the SMART/RPM issue was added, this has been filed as a new separate bug 9776, which is assigned to Robert.

We are trying to reproduce the udevd inotifycurrently, it it's not reproducible we will close this bug.

Hi
I just retested this one, please find attached the results.
Regards,

Created attachment 3243 [details]
log23600

(In reply to comment #11)
> Created attachment 3243 [details]
> log23600

Build Configuration:
BB_VERSION        = "1.30.0"
BUILD_SYS         = "x86_64-linux"
NATIVELSBSTRING   = "universal"
TARGET_SYS        = "x86_64-poky-linux"
MACHINE           = "genericx86-64"
DISTRO            = "poky"
DISTRO_VERSION    = "2.1"
TUNE_FEATURES     = "m64 core2"
TARGET_FPU        = ""
meta-selftest     
meta              
meta-poky         
meta-yocto-bsp    
workspace         = "krogoth:8f51f6153a09f8048fb4c4ce9cf4a19655240de4"

AB Link: http://autobuilder.yoctoproject.org/pub/releases/CURRENT/machines/genericx86-64/core-image-sato-sdk-genericx86-64.hddimg

Tested on NUC: D54250WYK

Created attachment 3244 [details]
NUC6i5SYH_logs

Tested on NUC6i5SYH
Build Configuration:
BB_VERSION        = "1.30.0"
BUILD_SYS         = "x86_64-linux"
NATIVELSBSTRING   = "universal"
TARGET_SYS        = "x86_64-poky-linux"
MACHINE           = "genericx86-64"
DISTRO            = "poky"
DISTRO_VERSION    = "2.1"
TUNE_FEATURES     = "m64 core2"
TARGET_FPU        = ""
meta-selftest     
meta              
meta-poky         
meta-yocto-bsp    
workspace         = "krogoth:8f51f6153a09f8048fb4c4ce9cf4a19655240de4"

AB Link: http://autobuilder.yoctoproject.org/pub/releases/CURRENT/machines/genericx86-64/core-image-sato-sdk-genericx86-64.hddimg

Created attachment 3248 [details]
log

Attached you find the results log for 2.2M1 rc2 : 6f0c5537e02c59e1c8f3b08f598dc049ff8ee098 for genericx86 on MM32

After some initial investigation, I found that the call into inotify_add_watch() in udev-watch.c:udev_watch_begin() line 104 is failing, it retries if there is a failure and that is what is showing this error.

I added some debug statements around both the initialization of udev from the /etc/init.d/udev script and in the eudev source code itself.  The /dev/loop0 device does exists.  This seems like it might be a race condition, but could do with a little deeper investigation into the kernel's inotify code related to adding the watch and why it determines the device does not exist.

I found something a little weird, udev is started twice on this platform, I just haven't found out why, the inotify error happens just before udev being started for the second time.

This is part of the log23600:
6.984671] udevd[344]: inotify_add_watch(6, /dev/loop0, 10) failed: No such file or directory
[    7.656252] udevd[420]: starting version 3.2

Although this only shows the second invocation (I don't have the complete log), this would explain why /dev/loop0 does exist, although it doesn't exist when required by inotify_add_watch, since its created afterwards, another thing is that the first time udev is started its not being started via /etc/init.d/udev or /etc/rcS.d/S04udev (same), I added some debug statements to check this, so maybe its not started correctly?

So we need to find out why and how udev is being started before being invocated by /etc/rcS.d/S04udev and perhaps if we avoid that first execution, the inotify_add_watch call will happen when it should (after udev is started correctly)

Getting back to this:

Just confirming what I said before, here's whats hapening on qemu:

Freeing unused kernel memory: 1252K (ffffffff81c87000 - ffffffff81dc0000)
Starting udev from init.d step 1                          
Starting udev from init.d step 2                        
Starting udev from init.d step 3                          
Starting udev from init.d step 4                          
udevd[114]: starting version 3.2
random: udevd urandom read with 41 bits of entropy available                    
udevd[115]: starting eudev-3.2

and then no inotify error and everything goes smoothly...


Here's what's happening on the NUC:
Freeing unused kernel memory: 1252K...
...
udevd[100]: starting version 3.2
random: udevd urandom read with 15 bits of entropy available                    
udevd[102]: starting eudev-3.2
...
udevd[294]: inotify_add_watch(7, /dev/loop0, 10) failed: No such file or directory ...
...
Starting udev from init.d step 1                          
Starting udev from init.d step 2                        
Starting udev from init.d step 3                          
Starting udev from init.d step 4                          
udevd[331]: starting version 3.2
udevd[332]: starting eudev-3.2

As you can see I added some debug statements on /etc/init.d/udev, to make sure it wasn't calling it and exiting at some point.

So on the NUC udev is started twice, the first time is somehow being started by calling /sbin/udevd , and the second time (correctly), by calling /etc/init.d/udev.

I think it might be too much of a coincidence that the call to /etc/init.d/udev happens exactly after the error, I think the call is happening because of the error, which is ok because we end up having /dev/loop0, do for the end user its sort of transparent.

But we still need to figure out why on certain platforms using the same image it presents different behavior.

Found another odd thing happening, so I started adding debug statements to eudev source code, on udev-watch.c too, I wanted to know the state of the system just before the error happened.

Anyway, after modifying eudev, I updated the package via smart, and after rebooting I found that the statements show up, but only when eudev is started the second time (called from /etc/init.d/udev), the first time it is started my changes are simply not there.

Which got me thinking, so I did a little experiment, and moved both udevd and udevadm away from PATH, and when I rebooted, eudev was started (the first time) anyway, and the second call was issued but failed, since it actually checks that udevd exists before actually starting it.

So udevd is being called from somewhere else, and its not the same udevd which was upgraded on the system from building the modified eudev package.

So udev is called twice, once from with in the initrd image inside the kernel which mounts the rootfs.ext4 image and then the second time after switchroot is called and you start executing from with in the actual rootfs.

During the first invocation, the /dev/loop0 device is not created until after udev is called, so the inotify_add_watch() fails. If we can move the mknod to before the udev call I think this will fix this issue.

I believe that this came about because of the switch to eudev which uses the inotify systcalls rather than what the older udev did.

Yes, as Saul said, the first udev call is being issued from the initrd image, which we crete during build, hence why my changes were not there when booting, so I started messing around with the live boot script on initrd.
Firstly I tried manually creating the /dev/loop0 device using mknod before calling udev, so when it tries to add the watch, it wouldn't fail, but surprisingly I found out that the mknod call fails stating that the file already exists:

mknod: /dev/loop0: File exists

This doesn't make much sense to me, since although at this point during boot /dev/ has just been mounted, but it should not be populated yet, since udev hasn't been called yet.

I added other debug statements and got the following:

(dbg) Early setup begins... 
(dbg) Mounting /dev, /proc and /sys...
tsc: Refined TSC clocksource calibration: 1800.015 MHz                            
clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x19f237ca5cc, max_idle_ns: 440795276806 ns                         
(dbg) Mounted tmpfs                                                 
(dbg) /dev directory exists.
(dbg) loop0 device  exists.
(dbg) Mounting /var /run   
(dbg) Before udev call
(dbg) loop0  device exists.         
(dbg) adding loop0
(dbg) mknod: /dev/loop0: File exists                 
(dbg) adding loop0 failed
(dbg) calling udev
udevd[102]: starting version 3.2
...
inotify error

So, before calling udevd the loop0 device exists and the call to mknod fails, somehow after calling udevd it doesn't exist anymore adn then we get the inotify error.

Ok, I've found out what the problem is:

The problem does indeed come when live booting, in a very basic way, what we do when live booting is the following:

1.- We boot to initrd and do an early_setup where we mount /proc /sys /dev and such, and after that we start the udev daemon (which comes from initrd), and udev starts doing its job populating /dev/*

2.- After that we create a new mountpoint for root image, and mount the root image, then we call boot_live_root

3.- Here, since we will be booting now from our new root, we call udevadm settle --timeout=3, which should take care of what udev was doing and exit afterwards, and then we kill all udev processes (or we think we do).

4.- After that, we do the initial steps to switch to our new root, which involve moving /proc /sys and /dev, and here's where our problem begins:

mount -n --move /proc ${ROOT_MOUNT}/proc
mount -n --move /sys ${ROOT_MOUNT}/sys
mount -n --move /dev ${ROOT_MOUNT}/dev

Now, since udev wasn't completely killed before, it still has some stuff to do, part of which is the add_watch to /dev/loop0, before doing this, udev checks for the file existance using stat(), and the call fails if it doesn't exist, returning to add_watch and throwing the error: "inotify_add_watch(7, /dev/loop0, 10) failed: No such file or directory".

This is in fact what's happening, the stat() syscall is failing since the file /dev/loop0 doesn't exist anymore, we literally just moved it to ${ROOT_MOUNT}/dev/loop0.

So that is why the error was not reproducible 100% of the time, it is a race condition, it depends on if the stat() call coming from udev happens before or after the mount -n --move /dev ${ROOT_MOUNT}/dev command, if it happens before, the file still exists, if it happens afterwards, the file isn't there anymore.

We either need to find a way to wait for all the udev events to finish and completely kill udev before moving /dev/ or simply completely kill udev, now this usually would not be a very wise choice, since there's probably a reason why udev is still running, although, in this case, perhaps its ok, since once we switch root, the scripts on /etc/init.d/ will run , and these include udev, so either way it runs again on our real root, and finishes what was left to do.

Fixed here:

http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=4f9ddb6e90e5d49441406baefccd791556769013

Tested on:
ENVIRONMENT: genericx86-64 on NUC
Build Configuration:
BB_VERSION        = "1.32.0"
BUILD_SYS         = "x86_64-linux"
NATIVELSBSTRING   = "universal"
TARGET_SYS        = "x86_64-poky-linux"
MACHINE           = "genericx86-64"
DISTRO            = "poky"
DISTRO_VERSION    = "2.2"
TUNE_FEATURES     = "m64 core2"
TARGET_FPU        = ""
meta              
meta-poky         
meta-yocto-bsp    = "HEAD:dc8508f609974cc99606b9042bfa7f870ce80228"


no udev error in dmesg log.

14:27:50 - bitbake-worker - RESULTS - Testcase 1096: PASSED

Log attached.

Created attachment 3518 [details]
Results NUC 6i5SYH

This error is present in 2.4M3rc1 5f6945f5031e1a4ca116cc1eccf4c2f9dc228547
NUC5CPYH

Build Configuration:
BB_VERSION        = "1.35.0"
BUILD_SYS         = "x86_64-linux"
NATIVELSBSTRING   = "universal"
TARGET_SYS        = "x86_64-poky-linux"
MACHINE           = "intel-corei7-64"
DISTRO            = "poky"
DISTRO_VERSION    = "2.3"
TUNE_FEATURES     = "m64 corei7"
TARGET_FPU        = ""
meta              
meta-poky         
meta-yocto-bsp    = "HEAD:5f6945f5031e1a4ca116cc1eccf4c2f9dc228547"
meta-intel        = "HEAD:8d44e72d6eff173d96eb5b2571e8c1e10de53816"

Central error: [    7.442749] udevd[231]: inotify_add_watch(6, /dev/loop0, 10) failed: No such file or directory

Log attached.

Created attachment 3979 [details]
Results_NUC5CPYH.log

(In reply to comment #26)
> Created attachment 3979 [details]
> Results_NUC5CPYH.log

Hey Juan,

Could you please provide the full dmesg log / boot log?

Thanks!