Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log

[Martin Jansa <martin.jansa@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 10347 bytes --]

On Wed, Sep 13, 2017 at 10:46:59PM +0200, Martin Jansa wrote:
> * we often see QA warnings like:
>   glibc-locale-2.26: glibc-locale: /glibc-binary-localedata-en-gb/usr/lib/locale/en_GB/LC_MEASUREMENT is owned by uid 3004, which is the same as the user running bitbake. This may be due to host contamination [host-user-contaminated]
>   glibc-locale-2.26: glibc-locale: /glibc-binary-localedata-nn-no.iso-8859-1/usr/lib/locale/nn_NO.ISO-8859-1/LC_MEASUREMENT is owned by uid 3004, which is the same as the user running bitbake. This may be due to host contamination [host-user-contaminated]
>   but we don't know the root cause of it.
> * the only theory we currently have is that it's a bug in pseudo when
>   inode is being reused for different files, which is supported by
>   pseudo.log entries:
> 
>   Good build:
>   pseudo$ grep -v "^path mismatch" pseudo.log
>   debug_logfile: fd 2
>   pid 7975 [parent 7974], doing new pid setup and server start
>   Setup complete, sending SIGUSR1 to pid 7974.
>   db cleanup for server shutdown, 17:33:58.787
>   memory-to-file backup complete, 17:33:58.787.
>   db cleanup finished, 17:33:58.787
> 
>   Build with QA host-user-contaminated issue:
>   ERROR: foo-1.0.0-r0 do_package_qa: QA Issue: foo: file-with-wrong-UID is owned
>   by uid 2001, which is the same as the user running bitbake. This may be due to
>   host contamination [host-user-contaminated]
> 
>   pseudo$ grep "file-with-wrong-UID" pseudo.log
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   creat ignored for existing file 'file-with-wrong-UID'.
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   inode mismatch: 'file-with-wrong-UID' ino 13242270 in db, 13242271 in request.
>   path mismatch [1 link]: ino 13242270 db 'file-with-wrong-UID' req 'some-other-unrelated-file'.
>   creat for 'some-other-unrelated-file' replaces existing 13242270 ['file-with-wrong-UID'].
>   db cleanup for server shutdown, 02:16:23.685
>   memory-to-file backup complete, 02:16:23.685.
>   db cleanup finished, 02:16:23.685
> 
>   And some-other-unrelated-file is really some different file, not just hardlink
>   to the same file from some different directory (like between WORKDIR and sysroot
>   other "path mismatch" entries show).
> 
> Signed-off-by: Martin Jansa <Martin.Jansa@gmail.com>
> ---
>  meta/classes/insane.bbclass | 40 ++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 40 insertions(+)
> 
> diff --git a/meta/classes/insane.bbclass b/meta/classes/insane.bbclass
> index 78b41caf99..617bf7011d 100644
> --- a/meta/classes/insane.bbclass
> +++ b/meta/classes/insane.bbclass
> @@ -1237,6 +1237,41 @@ python do_qa_unpack() {
>          bb.warn('%s: the directory %s (%s) pointed to by the S variable doesn\'t exist - please set S within the recipe to point to where the source has been unpacked to' % (d.getVar('PN'), d.getVar('S', False), s_dir))
>  }
>  
> +python do_qa_pseudo() {
> +    ###########################################################################
> +    # Check pseudo.log for unexpected errors
> +    #
> +    # Typical pseudo.log contains many "^path mismatch" lines for all the hardlinked files
> +    # e.g. in some smaller component I see 231/237 lines to be "^path mismatch" other 6
> +    # lines are setup and cleanup lines like this:
> +    # debug_logfile: fd 2
> +    # pid 7975 [parent 7974], doing new pid setup and server start
> +    # Setup complete, sending SIGUSR1 to pid 7974.
> +    # db cleanup for server shutdown, 17:33:58.787
> +    # memory-to-file backup complete, 17:33:58.787.
> +    # db cleanup finished, 17:33:58.787
> +    #
> +    # but if there is one of:
> +    # "^inode mismatch"
> +    # "^creat ignored for existing file"
> +    # "^creat for.*replaces existing"
> +    # then there might be some bigger issue which sometimes results in host-user-contaminated QA warnings
> +    ###########################################################################
> +
> +    import subprocess
> +
> +    pseudodir = d.getVar('PSEUDO_LOCALSTATEDIR')
> +    bb.note("Checking pseudo.log for common errors")
> +    pseudolog = os.path.join(pseudodir, "pseudo.log")
> +    statement = "grep" \
> +        " -e '^inode mismatch'" \
> +        " -e '^creat ignored for existing file'" \
> +        " -e '^creat for.*replaces existing'" \
> +        " %s" % pseudolog
> +    if subprocess.call("%s -q" % statement, shell=True) == 0:
> +        bb.fatal("This %s indicates errors, see %s or grep -v '^path mismatch' %s" % (pseudolog, statement, pseudolog))
> +}
> +
>  # The Staging Func, to check all staging
>  #addtask qa_staging after do_populate_sysroot before do_build
>  do_populate_sysroot[postfuncs] += "do_qa_staging "
> @@ -1249,6 +1284,11 @@ do_configure[postfuncs] += "do_qa_configure "
>  # Check does S exist.
>  do_unpack[postfuncs] += "do_qa_unpack"
>  
> +# Check pseudo.log for unexpected errors
> +# For some reason do_build postfunction isn't executed
> +# do_build[postfuncs] += "do_qa_pseudo"
> +addtask do_qa_pseudo after do_populate_sysroot do_packagedata do_package before do_build
> +
>  python () {
>      import re

Quick build of systemd with this enabled found 2 issues in dbus and
systemd:

ERROR: systemd-1_234-r0 do_qa_pseudo: This /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/pseudo/pseudo.log indicates errors, see grep -e '^inode mismatch' -e '^creat ignored for existing file' -e '^creat for.*replaces existing' /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/pseudo/pseudo.log or grep -v '^path mismatch' /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/pseudo/pseudo.log
ERROR: systemd-1_234-r0 do_qa_pseudo: Function failed: do_qa_pseudo
ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/temp/log.do_qa_pseudo.28996
ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/systemd/systemd_234.bb:do_qa_pseudo) failed with exit code '1'
ERROR: dbus-1.10.20-r0 do_qa_pseudo: This /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/pseudo/pseudo.log indicates errors, see grep -e '^inode mismatch' -e '^creat ignored for existing file' -e '^creat for.*replaces existing' /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/pseudo/pseudo.log or grep -v '^path mismatch' /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/pseudo/pseudo.log
ERROR: dbus-1.10.20-r0 do_qa_pseudo: Function failed: do_qa_pseudo
ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/temp/log.do_qa_pseudo.29053
ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/dbus/dbus_1.10.20.bb:do_qa_pseudo) failed with exit code '1'

OE @ ~/openembedded-core $ grep -v '^path mismatch' /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/pseudo/pseudo.log
debug_logfile: fd 2
pid 22562 [parent 22560], doing new pid setup and server start
Setup complete, sending SIGUSR1 to pid 22560.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/group' ino 29361846 in db, 29361904 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/group' ino 29361846 in db, 29361904 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/group' ino 29361846 in db, 29361901 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361911 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361911 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361942 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361942 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361901 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361901 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361957 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361957 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/systemd/1_234-r0/recipe-sysroot/etc/passwd' ino 29361844 in db, 29361972 in request.
db cleanup for server shutdown, 22:44:28.138
memory-to-file backup complete, 22:44:28.138.
db cleanup finished, 22:44:28.138


OE @ ~/openembedded-core $ grep -v '^path mismatch' /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/pseudo/pseudo.log
debug_logfile: fd 2
pid 23440 [parent 23433], doing new pid setup and server start
Setup complete, sending SIGUSR1 to pid 23433.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/recipe-sysroot/etc/group' ino 29391451 in db, 29391468 in request.
inode mismatch: '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/dbus/1.10.20-r0/recipe-sysroot/etc/passwd' ino 29391450 in db, 29391470 in request.
db cleanup for server shutdown, 22:44:42.563
memory-to-file backup complete, 22:44:42.563.
db cleanup finished, 22:44:42.563

So maybe we should filter the log only for the other 2 entries.

-- 
Martin 'JaMa' Jansa     jabber: Martin.Jansa@gmail.com

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 201 bytes --]