| Summary: | logrotate.LogrotateTest.test_2_logrotate selftest failure in core-image-full-cmdline | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [QA/Testing] Runtime Testing | Reporter: | Richard Purdie <richard.purdie> | ||||
| Component: | oeqa/runtime | Assignee: | Trevor Gamblin <tvgamblin> | ||||
| Status: | RESOLVED FIXED | QA Contact: | |||||
| Severity: | normal | ||||||
| Priority: | Medium+ | CC: | akuster, randy.macleod, tvgamblin | ||||
| Version: | unspecified | ||||||
| Target Milestone: | 3.1 M3 | ||||||
| Hardware: | x86 | ||||||
| OS: | Multiple | ||||||
| Whiteboard: | with backport | ||||||
| OS type for building Yocto: | --- | Type of Regression: | --- | ||||
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |||||
| Attachments: |
|
||||||
|
Description
Richard Purdie
2019-11-18 12:10:36 UTC
Maybe be a dup of 13602 Haven't been able to recreate this yet with bitbake -c testimage core-image-full-cmdline. Cutting down to just logrotate and the tests it requires to see if I can force it out by running the tests on loop. Happened again on the autobuilder in master: https://autobuilder.yoctoproject.org/typhoon/#/builders/56/builds/830 I'm making some progress on this, but I don't have an actual patch for it yet. Here's a condensed test_logrotate, where lines 55 and 56 are added for debug:
37 @OETestDepends(['ssh.SSHTest.test_ssh'])
38 def test_logrotate(self):
39 status, output = self.target.run('mkdir $HOME/logrotate_dir')
40 msg = 'Could not create logrotate_dir. Output: %s' % output
41 self.assertEqual(status, 0, msg = msg)
42
43 status, output = self.target.run('echo "create \n include /etc/logrotate.d \n olddir $HOME/logrotate_dir" > /tmp/logrotate-test.conf')
44 status, output = self.target.run('logrotate -f /tmp/logrotate-test.conf')
45
46 msg = ('logrotate service could not be reloaded. Status and output: '
47 '%s and %s' % (status, output))
48 self.assertEqual(status, 0, msg = msg)
49
50 _, output = self.target.run('ls -la $HOME/logrotate_dir/ | wc -l')
51 msg = ('new logfile could not be created. List of files within log '
52 'directory: %s' % (
53 self.target.run('ls -la $HOME/logrotate_dir')[1]))
54 self.assertTrue(int(output)>=3, msg = msg)
55 testoutput = "output is {0} and the files are: \n {1}".format(output, self.target.run('ls -la $HOME/logrotate_dir/')[1])
56 self.assertTrue(2 < 1, msg = testoutput)
The second self.assertTrue is put there so that you can see the contents of the output variable and what's in the directory. When I run the image tests, it shows this:
Traceback (most recent call last):
File "/yow-lpggp31/tgamblin/oe-core.git/meta/lib/oeqa/core/decorator/__init__.py", line 36, in wrapped_f
return func(*args, **kwargs)
File "/yow-lpggp31/tgamblin/oe-core.git/meta/lib/oeqa/runtime/cases/logrotate.py", line 57, in test_logrotate
self.assertTrue(2 < 1, msg = testoutput)
AssertionError: False is not true : output is 3 and the files are:
total 2
drwxr-xr-x 2 root root 1024 Jan 14 19:30 .
drwx------ 4 root root 1024 Jan 14 19:30 ..
Note that that's three lines of output from that ls call, so in current usage the test is passing even though there aren't any files in the directory. Logging into the core-image-full-cmdline image confirms this (ls from coreutils):
root@qemux86-64:~# ls -al /bin/ls
lrwxrwxrwx 1 root root 17 Jan 14 19:48 /bin/ls -> /bin/ls.coreutils
root@qemux86-64:~# ls
root@qemux86-64:~# mkdir testdir
root@qemux86-64:~# ls -al testdir/
total 2
drwxr-xr-x 2 root root 1024 Jan 14 19:50 .
drwx------ 3 root root 1024 Jan 14 19:50 ..
root@qemux86-64:~#
Compare with a core-image-minimal build (ls from busybox):
root@qemux86-64:~# ls -al /bin/ls
lrwxrwxrwx 1 root root 19 Jan 14 19:53 /bin/ls -> /bin/busybox.nosuid
root@qemux86-64:~# mkdir testdir
root@qemux86-64:~# ls -al testdir/
drwxr-xr-x 2 root root 1024 Jan 14 19:54 .
drwx------ 3 root root 1024 Jan 14 19:54 ..
root@qemux86-64:~#
So the wc -l in the logrotate test may returning 3 in some instances (passing the assert) even though there's nothing in logrotate_dir.
Is it possible that the autobuilder is occasionally hitting a sequence of building and testing where it builds an image with busybox (e.g. core-image-minimal) in the same place as a previous image with coreutils (e.g. core-image-full-cmdline), but then tries to run e.g. bitbake -c testimage core-image-full-cmdline on those build artifacts?
Bigger issue - maybe I'm misunderstanding how logrotate should be used, but it doesn't look like the call is ever actually rotating things into the path specified by olddir.
Still debugging.
Patch submitted to clean up the test and make debugging easier (if it still occurs). Created attachment 4615 [details]
packages unique to both core-image-full-cmdline and core-image-sato-sdk that are NOT in core-image-sato
Added a list of the packages that are in both of the images we've seen fail, but not in another image e.g. core-image-sato. Not sure yet if any of these could be part of the problem.
Thinking I need a new patch with the verbose option added to the logrotate calls, to see what it thinks is happening when it's unable to rotate a log.
Was looking around and noticed this after running qemu on a fresh core-image-sato-sdk: hwclock: settimeofday() failed: Invalid argument touch: cannot touch '/var/log/wtmp': No such file or directory chown: cannot access '/var/log/wtmp': No such file or directory Failed to set owner -root- for -/var/log/wtmp-. chmod: cannot access '/var/log/wtmp': No such file or directory Failed to set mode -0664- for -/var/log/wtmp-. Still appears inconsistent. Based on what comes after that in the boot log, I'm inclined to think that it might be a problem with syslogd: Wed Jan 29 02:13:16 2020: hwclock: settimeofday() failed: Invalid argument Wed Jan 29 02:13:16 2020: Starting syslogd/klogd: done Wed Jan 29 02:13:16 2020: * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon I have a single build environment consistently reporting that issue with /var/log/wtmp (as shown above) at boot, but the test still passes (even with my modifications to the logrotate test) when I run "bitbake core-image-sato-sdk -c testimage". I'm suspecting that this is an issue with meta/recipes-core/initscripts/initscripts-1.0/populate-volatile.sh. Doing a text search on the filesystem after booting with QEMU points to a file called /etc/volatile.cache, which contains the following lines (among others for other data in /var/log):
touch "/var/log/wtmp";
chown root:root /var/log/wtmp || echo "Failed to set owner -root- for -/var/log/wtmp-." >/dev/tty0 2>&1;
chmod 0664 /var/log/wtmp || echo "Failed to set mode -0664- for -/var/log/wtmp-." >/dev/tty0 2>&1
Which matches the error messages seen in some boot logs:
Fri Jan 31 15:50:35 2020: touch: cannot touch '/var/log/wtmp': No such file or directory
Fri Jan 31 15:50:35 2020: chown: cannot access '/var/log/wtmp': No such file or directory
Fri Jan 31 15:50:35 2020: Failed to set owner -root- for -/var/log/wtmp-.
Fri Jan 31 15:50:35 2020: chmod: cannot access '/var/log/wtmp': No such file or directory
Fri Jan 31 15:50:35 2020: Failed to set mode -0664- for -/var/log/wtmp-.
Possibly a problem with the filesystem not being available when this script starts up? Still digging...
Clearly, if the autobuilder is running into the issue where there's no wtmp log to rotate in the logrotate tests, then the issue lies with the initscripts and sysvinit. Looking at meta/recipes-core/initscripts/initscripts-1.0/volatiles, here are the files that populate-volatile.sh should create: 26 d root root 1777 /run/lock none 27 d root root 0755 /var/volatile/log none 28 d root root 1777 /var/volatile/tmp none 29 l root root 1777 /var/lock /run/lock 30 l root root 0755 /var/run /run 31 l root root 1777 /var/tmp /var/volatile/tmp 32 l root root 1777 /tmp /var/tmp 33 d root root 0755 /var/lock/subsys none 34 f root root 0664 /var/log/wtmp none 35 f root root 0664 /var/run/utmp none 36 l root root 0644 /etc/resolv.conf /var/run/resolv.conf 37 f root root 0644 /var/run/resolv.conf none I don't see any obvious patches in the commit log when searching for "populate-volatile" or "initscripts" that are close enough to the first report to be the smoking gun. I also still can't get testimage to actually fail for the builds where I see this error. *** Bug 13602 has been marked as a duplicate of this bug. *** This has been fixed with https://git.openembedded.org/openembedded-core/commit/?id=b9392403e96c6d880de844b44da2c7300fcf411c Bug 13784 has been opened to investigate the race condition that got this error occurring in the first place. |