Openembedded Core Discussions
 help / color / mirror / Atom feed
* [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
@ 2017-09-13 20:46 Martin Jansa
  2017-09-13 20:50 ` Martin Jansa
                   ` (2 more replies)
  0 siblings, 3 replies; 14+ messages in thread
From: Martin Jansa @ 2017-09-13 20:46 UTC (permalink / raw)
  To: openembedded-core

* 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
     
-- 
2.14.1



^ permalink raw reply related	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 20:46 [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log Martin Jansa
@ 2017-09-13 20:50 ` Martin Jansa
  2017-09-13 22:08   ` Seebs
  2017-09-13 22:09 ` Seebs
  2017-09-19 15:18 ` [RFC][PATCHv2] " Martin Jansa
  2 siblings, 1 reply; 14+ messages in thread
From: Martin Jansa @ 2017-09-13 20:50 UTC (permalink / raw)
  To: openembedded-core

[-- 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 --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 20:50 ` Martin Jansa
@ 2017-09-13 22:08   ` Seebs
  2017-09-13 22:28     ` Martin Jansa
  2017-09-14 13:17     ` Burton, Ross
  0 siblings, 2 replies; 14+ messages in thread
From: Seebs @ 2017-09-13 22:08 UTC (permalink / raw)
  To: openembedded-core

On Wed, 13 Sep 2017 22:50:32 +0200
Martin Jansa <martin.jansa@gmail.com> wrote:

> 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.

Just to be clear about this:

This is at least potentially an Actual Problem. It's probably not a
good idea to habitually ignore these. A thing like this happening means
that, at some point:

1. Something created etc/group, and it got inode 29361846 recorded in
the database.
2. Something deleted etc/group, and did NOT record this to the database.
3. Something created etc/group, with inode 29361904.

It's possible that the thing creating etc/group didn't record it to the
database, and something else just referred to it later (like a stat
call), or that this was generated by the request creating the entry.

Either way, it means changes were made to a pseudo-managed hunk of
filesystem without pseudo knowing about it, and that is generally bad.

-s


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 20:46 [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log Martin Jansa
  2017-09-13 20:50 ` Martin Jansa
@ 2017-09-13 22:09 ` Seebs
  2017-09-14 14:53   ` Burton, Ross
  2017-09-19 15:18 ` [RFC][PATCHv2] " Martin Jansa
  2 siblings, 1 reply; 14+ messages in thread
From: Seebs @ 2017-09-13 22:09 UTC (permalink / raw)
  To: openembedded-core

On Wed, 13 Sep 2017 22:46:59 +0200
Martin Jansa <martin.jansa@gmail.com> wrote:

>   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).

To clarify a thing: In practice, "path mismatch" with links > 1 is
probably harmless. I think I had a patch floating around to stop
alerting about it except when being paranoid.

-s


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 22:08   ` Seebs
@ 2017-09-13 22:28     ` Martin Jansa
  2017-09-14 14:27       ` Seebs
  2017-09-14 13:17     ` Burton, Ross
  1 sibling, 1 reply; 14+ messages in thread
From: Martin Jansa @ 2017-09-13 22:28 UTC (permalink / raw)
  To: Seebs; +Cc: Patches and discussions about the oe-core layer

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

OK, thanks.

Any insights to the first issue described in commit message? That we know
that is an Actual Problem, but hard to reproduce it.

I'm rebuilding one component over and over again and with pseudo 1.8.1 I
got this issue in 5 rebuilds from 1000, now in the same build with latest
pseudo 1.8.2 backported from oe-core/master I got this issue only 2 times
in 1000 iterations.

Hopefully this insane check will help discover similar issues even without
triggering the QA host-user-contamination check, so that we can detect such
issues even without really trying (it's now included in my regular "bitbake
world" builds which quite often trigger this QA host-user-contamination
issue in glibc-locale. And now we can correlate that with pseudo.log more
easily.

On Thu, Sep 14, 2017 at 12:08 AM, Seebs <seebs@seebs.net> wrote:

> On Wed, 13 Sep 2017 22:50:32 +0200
> Martin Jansa <martin.jansa@gmail.com> wrote:
>
> > 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.
>
> Just to be clear about this:
>
> This is at least potentially an Actual Problem. It's probably not a
> good idea to habitually ignore these. A thing like this happening means
> that, at some point:
>
> 1. Something created etc/group, and it got inode 29361846 recorded in
> the database.
> 2. Something deleted etc/group, and did NOT record this to the database.
> 3. Something created etc/group, with inode 29361904.
>
> It's possible that the thing creating etc/group didn't record it to the
> database, and something else just referred to it later (like a stat
> call), or that this was generated by the request creating the entry.
>
> Either way, it means changes were made to a pseudo-managed hunk of
> filesystem without pseudo knowing about it, and that is generally bad.
>
> -s
> --
> _______________________________________________
> Openembedded-core mailing list
> Openembedded-core@lists.openembedded.org
> http://lists.openembedded.org/mailman/listinfo/openembedded-core
>

[-- Attachment #2: Type: text/html, Size: 2907 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 22:08   ` Seebs
  2017-09-13 22:28     ` Martin Jansa
@ 2017-09-14 13:17     ` Burton, Ross
  1 sibling, 0 replies; 14+ messages in thread
From: Burton, Ross @ 2017-09-14 13:17 UTC (permalink / raw)
  To: Seebs; +Cc: OE-core

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

On 13 September 2017 at 23:08, Seebs <seebs@seebs.net> wrote:

> On Wed, 13 Sep 2017 22:50:32 +0200
> Martin Jansa <martin.jansa@gmail.com> wrote:
>
> > 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.
>
> Just to be clear about this:
>
> This is at least potentially an Actual Problem. It's probably not a
> good idea to habitually ignore these. A thing like this happening means
> that, at some point:
>
> 1. Something created etc/group, and it got inode 29361846 recorded in
> the database.
> 2. Something deleted etc/group, and did NOT record this to the database.
> 3. Something created etc/group, with inode 29361904.
>
> It's possible that the thing creating etc/group didn't record it to the
> database, and something else just referred to it later (like a stat
> call), or that this was generated by the request creating the entry.
>
> Either way, it means changes were made to a pseudo-managed hunk of
> filesystem without pseudo knowing about it, and that is generally bad.


I just applied this patch and got an identical hit in systemd, which makes
me think that the useradd class (maze of code that it is) is causing this
instance.

Ross

[-- Attachment #2: Type: text/html, Size: 1782 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 22:28     ` Martin Jansa
@ 2017-09-14 14:27       ` Seebs
  0 siblings, 0 replies; 14+ messages in thread
From: Seebs @ 2017-09-14 14:27 UTC (permalink / raw)
  To: Martin Jansa; +Cc: Patches and discussions about the oe-core layer

On Thu, 14 Sep 2017 00:28:34 +0200
Martin Jansa <martin.jansa@gmail.com> wrote:

> OK, thanks.
> 
> Any insights to the first issue described in commit message? That we
> know that is an Actual Problem, but hard to reproduce it.

This one?
  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]

My first guess would be some kind of weird timing interaction involving
symlinks or, if it's still there, the really weird copy of locale data
into an intermediate location to move it from the glibc package to the
glibc_locale package or something. But it seems like that should be
reproducible, so I'm not sure.

-s


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 22:09 ` Seebs
@ 2017-09-14 14:53   ` Burton, Ross
  2017-09-14 14:59     ` Seebs
  0 siblings, 1 reply; 14+ messages in thread
From: Burton, Ross @ 2017-09-14 14:53 UTC (permalink / raw)
  To: Seebs; +Cc: OE-core

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

On 13 September 2017 at 23:09, Seebs <seebs@seebs.net> wrote:

> On Wed, 13 Sep 2017 22:46:59 +0200
> Martin Jansa <martin.jansa@gmail.com> wrote:
>
> >   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).
>
> To clarify a thing: In practice, "path mismatch" with links > 1 is
> probably harmless. I think I had a patch floating around to stop
> alerting about it except when being paranoid.
>

Example:

path mismatch [5 links]: ino 27539515 db
'/data/poky-tmp/master/build/work/corei7-64-poky-linux/dbus/1.10.20-r0/recipe-sysroot-native/usr/bin/x86_64-poky-linux/x86_64-poky-linux-ld.bfd'
req
'/data/poky-tmp/master/build/sysroots-components/x86_64/binutils-cross-x86_64/usr/bin/x86_64-poky-linux/x86_64-poky-linux-ld'.

Looks like this is just warning that there is a symlink, right?

Ross

[-- Attachment #2: Type: text/html, Size: 1546 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-14 14:53   ` Burton, Ross
@ 2017-09-14 14:59     ` Seebs
  0 siblings, 0 replies; 14+ messages in thread
From: Seebs @ 2017-09-14 14:59 UTC (permalink / raw)
  To: OE-core

On Thu, 14 Sep 2017 15:53:09 +0100
"Burton, Ross" <ross.burton@intel.com> wrote:

> Example:
> 
> path mismatch [5 links]: ino 27539515 db
> '/data/poky-tmp/master/build/work/corei7-64-poky-linux/dbus/1.10.20-r0/recipe-sysroot-native/usr/bin/x86_64-poky-linux/x86_64-poky-linux-ld.bfd'
> req
> '/data/poky-tmp/master/build/sysroots-components/x86_64/binutils-cross-x86_64/usr/bin/x86_64-poky-linux/x86_64-poky-linux-ld'.
> 
> Looks like this is just warning that there is a symlink, right?

Hard link, not symlink. Symlinks are recorded separately, "links" is
the hard link count in the filesystem, which doesn't include symlinks.

That message is almost always Harmless. Although strictly speaking, it
probably indicates that one of the links was made outside of pseudo,
which in theory shouldn't happen, I think.

At least, I *think* the current intent is to always use an exact match
(both path and inode) if possible, so it shouldn't see a mismatch
unless there's a path that got used but that isn't in the database.

-s


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC][PATCHv2] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-13 20:46 [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log Martin Jansa
  2017-09-13 20:50 ` Martin Jansa
  2017-09-13 22:09 ` Seebs
@ 2017-09-19 15:18 ` Martin Jansa
  2017-10-16 15:01   ` Martin Jansa
  2 siblings, 1 reply; 14+ messages in thread
From: Martin Jansa @ 2017-09-19 15:18 UTC (permalink / raw)
  To: openembedded-core

* 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.
* don't trigger error from '^inode mismatch'
* show parts of pseudo.log in console
  many builds are executed in tmpfs, so I cannot check the pseudo.log later
* lower from error to warn as I hate all my builds reporting failure
  just because of this pseudo debug
* 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 | 43 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 43 insertions(+)

diff --git a/meta/classes/insane.bbclass b/meta/classes/insane.bbclass
index 0a3b528ddb..76cd92709b 100644
--- a/meta/classes/insane.bbclass
+++ b/meta/classes/insane.bbclass
@@ -1238,6 +1238,44 @@ 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 '^creat ignored for existing file'" \
+        " -e '^creat for.*replaces existing'" \
+        " %s" % pseudolog
+    if subprocess.call("%s -q" % statement, shell=True) == 0:
+        statement2 = "grep -v '^path mismatch' %s" % pseudolog
+        statement2_count = "grep -v '^path mismatch' -c %s" % pseudolog
+        output = subprocess.check_output(statement2, shell=True).decode("utf-8")
+        output_count = subprocess.check_output(statement2_count, shell=True).decode("utf-8").replace('\n', '')
+        bb.warn("This %s indicates %s errors, see %s or %s [qa_pseudo]: %s" % (pseudolog, output_count, statement, statement2, output))
+}
+
 # The Staging Func, to check all staging
 #addtask qa_staging after do_populate_sysroot before do_build
 do_populate_sysroot[postfuncs] += "do_qa_staging "
@@ -1250,6 +1288,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
     
-- 
2.14.1



^ permalink raw reply related	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCHv2] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-09-19 15:18 ` [RFC][PATCHv2] " Martin Jansa
@ 2017-10-16 15:01   ` Martin Jansa
  2017-10-16 15:10     ` Burton, Ross
  0 siblings, 1 reply; 14+ messages in thread
From: Martin Jansa @ 2017-10-16 15:01 UTC (permalink / raw)
  To: Patches and discussions about the oe-core layer

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

The world builds with this check applied show that *a lot* of components
report one of these errors and often many of errors, the most complete logs
from last couple days:

366 in:
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.report.20171012_161223.log
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.world.qemuarm.20171010_225937.log/qa.log
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.world.qemux86.20171011_084917.log/qa.log
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.world.qemux86-64.20171010_012728.log/qa.log


376 in:
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.report.20171001_085046.log
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.world.qemuarm.20170926_004402.log/qa.log
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.world.qemux86.20170926_004401.log/qa.log
http://logs.nslu2-linux.org/buildlogs/oe/world/rocko/log.world.qemux86-64.20170927_070922.log/qa.log

The number of errors differs in various builds, e.g.:
tcl-8.6.7: This
/work/armv5te-oe-linux-gnueabi/tcl/8.6.7-r0/pseudo/pseudo.log indicates 7
errors [qa_pseudo]
tcl-8.6.7: This
/work/armv5te-oe-linux-gnueabi/tcl/8.6.7-r0/pseudo/pseudo.log indicates 5
errors [qa_pseudo]
tcl-8.6.7: This /work/i586-oe-linux/tcl/8.6.7-r0/pseudo/pseudo.log
indicates 7 errors [qa_pseudo]
tcl-8.6.7: This /work/i586-oe-linux/tcl/8.6.7-r0/pseudo/pseudo.log
indicates 8 errors [qa_pseudo]
tcl-8.6.7: This /work/core2-64-oe-linux/tcl/8.6.7-r0/pseudo/pseudo.log
indicates 6 errors [qa_pseudo]
tcl-8.6.7: This /work/core2-64-oe-linux/tcl/8.6.7-r0/pseudo/pseudo.log
indicates 6 errors [qa_pseudo]

glibc-locale-2.26: This
/work/armv5e-oe-linux-gnueabi/glibc-locale/2.26-r0/pseudo/pseudo.log
indicates 17 errors [qa_pseudo]
glibc-locale-2.26: This
/work/armv5e-oe-linux-gnueabi/glibc-locale/2.26-r0/pseudo/pseudo.log
indicates 5 errors [qa_pseudo]
glibc-locale-2.26: This
/work/i586-oe-linux/glibc-locale/2.26-r0/pseudo/pseudo.log indicates 12
errors [qa_pseudo]
glibc-locale-2.26: This
/work/i586-oe-linux/glibc-locale/2.26-r0/pseudo/pseudo.log indicates 10
errors [qa_pseudo]
glibc-locale-2.26: This
/work/core2-64-oe-linux/glibc-locale/2.26-r0/pseudo/pseudo.log indicates 11
errors [qa_pseudo]
glibc-locale-2.26: This
/work/core2-64-oe-linux/glibc-locale/2.26-r0/pseudo/pseudo.log indicates 16
errors [qa_pseudo]

If I filter out the architecture specific path to pseudo.log and the number
of errors it still gives 368 different builds with errors:

acl-2.2.52 alsa-oss-1.0.17 alsa-plugins-1.1.4 apache2-2.4.27 apmd-3.2.2-15
aspell-0.60.6.1 attr-2.4.47 aufs-util-4.4+gitAUTOINC+89afb1806c
autofs-5.1.2 avahi-ui-0.6.32 base-passwd-3.5.29 binutils-2.29
blktrace-1.1.0+gitAUTOINC+43fc870ce0 bluez5-5.46 bmap-tools-3.4
bonnie++-1.03e boost-1.64.0 bootchart2-0.14.8 busybox-1.24.1
cantarell-fonts-0.0.24 can-utils-0.0+gitrAUTOINC+4c8fb05cb4 canutils-4.0.6
cdparanoia-10.2 chrony-2.4 ckermit-302 connman-1.34 conntrack-tools-1.4.4
console-tools-0.3.2 coreutils-8.27 corosync-2.4.2 cpufrequtils-008
cryptodev-module-1.9 ctdb-2.5.6 cups-2.2.4 curlpp-0.8.1
cwautomacros-20110201 cxxtest-4.3 daemontools-0.76 dbus-test-1.10.20
ddrescue-1.19 dfu-util-0.9 dhcp-4.3.6 diffutils-3.6 dmidecode-3.1
docbook-xml-dtd4-4.5 dovecot-2.2.29 ebtables-2.0.10-4 efivar-0.31
eglinfo-fb-1.0.0 espeak-1.48.04 evtest-1.33+AUTOINC+ab140a2dab expat-2.2.3
f2fs-tools-1.8.0 firefox-l10n-ff-45.9.0esr firefox-l10n-si-45.9.0esr
flac-1.3.2 flatbuffers-1.7.1 fontforge-20170731 frame-2.5.0
freeradius-3.0.15 fribidi-0.19.7 fuse-2.9.7
gateone-1.2+gitAUTOINC+f7a9be46cb gawk-4.1.4 gd-2.2.4 gdb-8.0 gegl-0.3.18
geoip-1.6.9 gettext-0.19.8.1 giflib-5.1.4 git-2.13.3 glade-3.20.0
glib-2.0-2.52.3 glibc-2.26 glibc-locale-2.26 glib-networking-2.50.0
gnupg-2.2.0 gnuplot-5.0.5 go-1.9 gobject-introspection-1.52.1
gptfdisk-1.0.3 gstreamer-0.10.36 gtkmm-2.24.5 hiredis-0.13.1 hplip-3.12.6
icon-slicer-0.3 icu-59.1 inetutils-1.9.4 init-ifupdown-1.0 iotop-0.6
iperf3-3.2 ipsec-tools-0.8.2 iptables-1.6.1 iputils-s20151218
iscsitarget-1.4.20.3+svn502 jack-1.9.10+gitAUTOINC+2d1d323505 kbd-2.0.4
kconfig-frontends-4.11.0.1 kexec-tools-2.0.14 konkretcmpi-0.9.2 krb5-1.15.1
lcdproc-0.5.8+gitAUTOINC+f5156e2e41 less-487 libatasmart-0.19
libatomic-ops-7.6.0+gitAUTOINC+73c60c5ef1 libbsd-0.8.6 libcanberra-0.30
libconnman-qt5-1.1.10+gitAUTOINC+4d6def3053
libcrypt-openssl-random-perl-0.11 libdrm-2.4.83 libencode-perl-2.83
libevdev-1.5.7 libfastjson-0.99.4 libgnome-2.32.1 libiec61883-1.2.0
libinput-1.8.1 libldb-1.1.29 liblogging-1.0.5 libmms-0.6.4 libotr-4.1.1
libpciaccess-0.13.5 libqofono-0.87+gitrAUTOINC+54435de3be librelp-1.2.14
librsvg-2.40.18 libsombok3-2.4.0 libtext-wrapi18n-perl-0.06
libtool-cross-2.4.6 libusb-compat-0.1.5 libusbg-0.1.0 libuser-0.62
libvncserver-0.9.11 libwmf-0.2.8.4 libwnck3-3.20.1 libxcursor-1.1.14
libxml2-2.9.4 libxml-perl-0.08 libxslt-1.1.29 libxxf86vm-1.1.4
linux-atm-2.5.2 linux-yocto-4.12.12+gitAUTOINC+eda4d18ce4_16de014967
linux-yocto-4.12.12+gitAUTOINC+eda4d18ce4_67b62d8d7b lirc-0.9.4d llvm-5.0
lmbench-3.0-a9 lockfile-progs-0.1.17 log4cpp-1.1.2 logfsprogs-git
logrotate-3.12.3 lowpan-tools-0.3.1+gitAUTOINC+38f42dbfce lprng-3.8.C
lttng-tools-2.9.5 lvm2-2.02.171
maliit-framework-qt5-0.99.0+gitAUTOINC+60b1b10de1 mariadb-5.5.57
matchbox-keyboard-0.1.1 mc-4.8.19 mce-inject-git md5deep-4.4
memcached-1.5.0 menulibre-2.1.3 mesa-demos-8.3.0 meson-0.40.1
minicoredumper-2.0.0 mongodb-3.4.6+gitAUTOINC+c55eb86ef4 mosquitto-1.4.14
mozilla-devscripts-0.30 mpich-3.2 multipath-tools-0.7.1 nana-2.5
ndisc6-1.0.4+gitAUTOINC+4c794b5512 netcat-0.7.1 net-snmp-5.7.3 nettle-3.3
nginx-1.12.1 nss-3.31.1 ntp-4.2.8p10 onboard-1.4.1 onig-5.9.6
openconnect-7.08 openhpi-3.6.1 openipmi-2.0.24 open-isns-0.97
openlmi-tools-0.10.5 opensaf-5.17.07 opensc-0.16.0 openssh-7.5p1
openssl-1.0.2l opkg-utils-0.3.5 opus-tools-0.1.8 os-release-1.0
ossp-uuid-1.6.2 packagegroup-core-ssh-openssh-1.0
packagegroup-core-x11-xserver-1.0 pango-1.40.6 pciutils-3.5.5 perf-1.0
perl-5.24.1 php-7.1.9 phpmyadmin-4.7.3 pixz-1.0.6 pkcs11-helper-1.11
pm-qa-0.5.2 pm-utils-1.4.1 poppler-data-0.4.7 portaudio-v19-v190600
postfix-3.2.2 postgresql-9.4.13 powertop-2.8 procps-3.3.12 proftpd-1.3.6
pure-ftpd-1.0.42 puzzles-0.0+gitAUTOINC+8dfe5cec31 pyrtm-0.4.2
python-2.7.13 python3-3.5.3 python3-babel-2.5.1 python3-chardet-3.0.4
python3-coverage-4.4.1 python3-cryptography-2.0.3 python3-cython-0.27.1
python3-django-1.11.5 python3-docutils-0.14 python3-isort-4.2.15
python3-mako-1.0.7 python3-ndg-httpsclient-0.4.3 python3-nose-1.3.7
python3-ntplib-0.3.3 python3-pandas-0.20.3 python3-pip-9.0.1
python3-psutil-5.3.1 python3-pykickstart-2.35 python3-pylint-1.7.2
python3-pylint-1.7.4 python3-pyparted-3.10.7+gitAUTOINC+69c4a478e4
python3-serpent-1.23 python3-simplejson-3.11.1 python3-xlrd-1.1.0
python-asn1crypto-0.23.0 python-cheetah-2.4.4 python-cpuset-1.5.7
python-cson-git python-cython-0.26.1 python-django-1.11.5
python-epydoc-3.0.1 python-gevent-1.2.2 python-imaging-1.1.7
python-jsonpatch-1.16 python-jsonpointer-1.12 python-ndg-httpsclient-0.4.3
python-netaddr-0.7.19 python-nose-1.3.7 python-numeric-24.2
python-numpy-1.13.1 python-pandas-0.20.3 python-pbr-3.1.1
python-pyflakes-1.2.3 python-pylint-1.7.2 python-pylint-1.7.4
python-pyro4-4.62 python-pyserial-3.4 python-pytest-3.2.2
python-scons-2.5.1 python-selectors34-1.2 python-setuptools-36.2.7
python-snakefood-1.4 python-snimpy-0.8.11 python-twisted-17.9.0
python-urllib3-1.22 python-vobject-0.9.5 python-xlrd-1.1.0
python-yappi-0.98 pywbem-0.8.0 qemu-2.10.0 qt3d-5.9.2+gitAUTOINC+9d8c9ada16
qt5-creator-3.5.1 qt5-plugin-generic-vboxtouch-1.1.3+gitrAUTOINC+d613ad1cc6
qtbase-5.9.2+gitAUTOINC+73573fce29 qtcharts-5.9.2+gitAUTOINC+1f47b1a7ae
qtconnectivity-5.9.2+gitAUTOINC+94cc2b914a
qtdatavis3d-5.9.2+gitAUTOINC+3f8ae713df
qtdeclarative-5.9.2+gitAUTOINC+7c45b035b9
qtenginio-5.9.2+gitAUTOINC+0555cf73c8 qtgamepad-5.9.2+gitAUTOINC+1fc40deed6
qtgraphicaleffects-5.9.2+gitAUTOINC+b6ff12df54
qtimageformats-5.9.2+gitAUTOINC+144a3535db
qtlocation-5.9.2+gitAUTOINC+c832af7897_9ecbe3642f
qtmultimedia-5.9.2+gitAUTOINC+343e281f0e
qtnetworkauth-5.9.2+gitAUTOINC+3d93f64365
qtquick1-5.9.2+gitAUTOINC+9bf0edd9bd
qtquickcontrols2-5.9.2+gitAUTOINC+63f2f55462
qtremoteobjects-5.9.2+gitAUTOINC+6e0341bc87
qtscript-5.9.2+gitAUTOINC+86ee61734e qtscxml-5.9.2+gitAUTOINC+a1dff1a11a
qtsensors-5.9.2+gitAUTOINC+1673dbed00
qtserialbus-5.9.2+gitAUTOINC+1d37c357c8
qtserialport-5.9.2+gitAUTOINC+93b539140c qtsmarthome-1.0
qtsvg-5.9.2+gitAUTOINC+0fcd016066 qtsystems-5.9.2+gitAUTOINC+f364358a81
qttools-5.9.2+gitAUTOINC+fdc5749b56 qtwayland-5.9.2+gitAUTOINC+7f70da6a64
qtwebchannel-5.9.2+gitAUTOINC+b5229df6a0
qtwebengine-5.9.2+gitAUTOINC+99f84ffd2c_21508b5b54
qtwebkit-5.9.2+gitAUTOINC+97c4a80a12
qtwebsockets-5.9.2+gitAUTOINC+fb71c823a7
qtwebview-5.9.2+gitAUTOINC+e4016a67bb
qtx11extras-5.9.2+gitAUTOINC+f65d50eb06
qtxmlpatterns-5.9.2+gitAUTOINC+fcfa824402 quagga-1.2.1 rabbitmq-c-0.7.0
radvd-2.17 readline-7.0 ristretto-0.8.2 rsync-3.1.2 rsyslog-8.29.0
ruby-2.4.1 samba-4.6.7 satyr-0.23 sblim-sfcb-1.4.9 sblim-sfcc-2.2.8
scsirastools-1.6.6 sed-4.2.2 sg3-utils-1.42 shadow-4.2.1 slang-2.3.1a
snort-2.9.7.5 speexdsp-1.2rc3 sqlite3-3.20.0 squid-3.5.27 sthttpd-2.27.1
strace-4.18 systemd-234 systemtap-3.1 tcl-8.6.7 telepathy-python-0.15.19
tftp-hpa-5.2 tipcutils-2.2.0+gitAUTOINC+7ab2211b87 tomoyo-tools-2.5.0
tslib-1.1 ttf-gentium-1.02 ubi-utils-klibc-1.5.2 udisks-1.0.5 ufw-0.33
upm-1.3.0-gitAUTOINC+106b6c7062 usbredir-0.7.1+gitAUTOINC+39aa3c69f6
usermode-1.111 vblade-22 vlc-2.2.2 vte-0.48.3 weston-init-1.0
xcb-util-wm-0.4.1 xcursor-transparent-theme-0.1.1+gitAUTOINC+23c8af5ba4
xdebug-2.5.1 xdelta3-3.0.11 xf86-input-evdev-2.10.5 xf86-input-mouse-1.9.2
xfce4-closebutton-plugin-0.1.0+gitrAUTOINC+02b74f13ad
xfce4-hotcorner-plugin-0.0.2 xfce4-mixer-4.11.0 xfce4-power-manager-1.6.0
xfce4-verve-plugin-1.1.0 xfwm4-themes-4.10.0 xserver-xorg-1.19.3
xstdcmap-1.0.3 xwd-1.0.6 xz-5.2.3 ypbind-mt-2.4
zlog-1.2.12+gitAUTOINC+13904dab28

Any other insight what might be causing these?

On Tue, Sep 19, 2017 at 5:18 PM, Martin Jansa <martin.jansa@gmail.com>
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.
> * don't trigger error from '^inode mismatch'
> * show parts of pseudo.log in console
>   many builds are executed in tmpfs, so I cannot check the pseudo.log later
> * lower from error to warn as I hate all my builds reporting failure
>   just because of this pseudo debug
> * 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 | 43 ++++++++++++++++++++++++++++++
> +++++++++++++
>  1 file changed, 43 insertions(+)
>
> diff --git a/meta/classes/insane.bbclass b/meta/classes/insane.bbclass
> index 0a3b528ddb..76cd92709b 100644
> --- a/meta/classes/insane.bbclass
> +++ b/meta/classes/insane.bbclass
> @@ -1238,6 +1238,44 @@ 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 '^creat ignored for existing file'" \
> +        " -e '^creat for.*replaces existing'" \
> +        " %s" % pseudolog
> +    if subprocess.call("%s -q" % statement, shell=True) == 0:
> +        statement2 = "grep -v '^path mismatch' %s" % pseudolog
> +        statement2_count = "grep -v '^path mismatch' -c %s" % pseudolog
> +        output = subprocess.check_output(statement2,
> shell=True).decode("utf-8")
> +        output_count = subprocess.check_output(statement2_count,
> shell=True).decode("utf-8").replace('\n', '')
> +        bb.warn("This %s indicates %s errors, see %s or %s [qa_pseudo]:
> %s" % (pseudolog, output_count, statement, statement2, output))
> +}
> +
>  # The Staging Func, to check all staging
>  #addtask qa_staging after do_populate_sysroot before do_build
>  do_populate_sysroot[postfuncs] += "do_qa_staging "
> @@ -1250,6 +1288,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
>
> --
> 2.14.1
>
>

[-- Attachment #2: Type: text/html, Size: 18971 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCHv2] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-10-16 15:01   ` Martin Jansa
@ 2017-10-16 15:10     ` Burton, Ross
  2017-10-16 15:50       ` Martin Jansa
  0 siblings, 1 reply; 14+ messages in thread
From: Burton, Ross @ 2017-10-16 15:10 UTC (permalink / raw)
  To: Martin Jansa; +Cc: Patches and discussions about the oe-core layer

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

On 16 October 2017 at 16:01, Martin Jansa <martin.jansa@gmail.com> wrote:

> The world builds with this check applied show that *a lot* of components
> report one of these errors and often many of errors, the most complete logs
> from last couple days:
>

A lot of the errors in my logs were due to package-output.lock being
accessed inside/outside pseudo context.  Can you grep all of your logs and
collate some common patterns?

Ross

[-- Attachment #2: Type: text/html, Size: 788 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCHv2] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-10-16 15:10     ` Burton, Ross
@ 2017-10-16 15:50       ` Martin Jansa
  2017-12-19 16:09         ` Martin Jansa
  0 siblings, 1 reply; 14+ messages in thread
From: Martin Jansa @ 2017-10-16 15:50 UTC (permalink / raw)
  To: Burton, Ross; +Cc: Patches and discussions about the oe-core layer

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

Yes, package-output.lock is very often the cause for "^inode mismatch":

martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' | wc
-l
1485
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
grep package-output.lock | wc -l
1168

log.do_install also causes "^inode mismatch" in many cases:

martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
grep -v package-output.lock | wc -l
317
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
grep -v package-output.lock | grep temp/log.do_install | wc -l
309

That leaves only couple other files:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
grep -v package-output.lock | grep -v temp/log.do_install
inode mismatch:
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/qtbase/5.9.2+gitAUTOINC+73573fce29-r0/image/usr/include/qt5/QtNetwork/qt_temp.rhjRGj'
ino 691255 in db, 691256 in request.
inode mismatch: '/home/jenkins/.python-history' ino 1066494 in db, 1066493
in request.
inode mismatch: '/home/jenkins/.python-history' ino 1066494 in db, 1066493
in request.
inode mismatch: '/home/jenkins/.python-history' ino 1066729 in db, 1062665
in request.
inode mismatch: '/home/jenkins/.python-history' ino 1066729 in db, 1062665
in request.
inode mismatch:
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/qt3d/5.9.2+gitAUTOINC+9d8c9ada16-r0/image/usr/include/qt5/Qt3DInput/qt_temp.rhjRGj'
ino 520536 in db, 520539 in request.
inode mismatch:
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/libqofono/0.87+gitrAUTOINC+54435de3be-r0/image/usr/lib/libqofono-qt5/tests/qt_temp.rhjRGj'
ino 876399 in db, 876404 in request.
inode mismatch:
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/libqofono/0.87+gitrAUTOINC+54435de3be-r0/image/usr/lib/libqofono-qt5/tests/qt_temp.rhjRGj'
ino 876404 in db, 876408 in request.

Similarly with "creat for", but there is more wide selection of files
triggering this one:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces'  | wc -l
1771
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for'  | grep package-output.lock | wc -l
198

for "creat for" the log.do_install appears only twice, but various
temp/run.* files are quite common cause:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run | wc -l
294

pm-qa is triggering this on many files,
e.g. /home/jenkins/oe/world/shr-core/tmp-glibc/work/core2-64-oe-linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_07.sh
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run -v  | grep
pm-qa | wc -l
229

martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run -v  | grep
pm-qa | grep cpuhotplug_05.sh
creat for
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh'
replaces existing 902737 ['NAMELESS FILE'].
creat for
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh'
replaces existing 1264757 ['NAMELESS FILE'].
creat for
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/i586-oe-linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh'
replaces existing 976636 ['NAMELESS FILE'].
creat for
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/core2-64-oe-linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh'
replaces existing 576004 ['NAMELESS FILE'].
creat for
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/core2-64-oe-linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh'
replaces existing 986226 ['NAMELESS FILE'].

then stamps files
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run -v  | grep
-v pm-qa | grep -v package-output.lock | grep glibc/stamps | wc -l
130

so it looks pretty rancom, but most of these errors are replacing 'NAMELESS
FILE'
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces' | grep 'NAMELESS FILE' | wc
-l
1632

which leaves only 139 other files:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces' | grep 'replaces.*NAMELESS
FILE' -v | wc -l
139

from which couple of them are package-output.lock again:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces' | grep 'replaces.*NAMELESS
FILE' -v | grep replaces.*package-output.lock | wc -l
31

and then random selection of builds, most of them from glibc-locale:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces' | grep 'replaces.*NAMELESS
FILE' -v | grep replaces.*package-output.lock -v | grep glibc-locale | wc -l
34
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces' | grep 'replaces.*NAMELESS
FILE' -v | grep replaces.*package-output.lock -v | grep llvm | wc -l
3
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep 'creat for.* replaces' | grep 'replaces.*NAMELESS
FILE' -v | grep replaces.*package-output.lock -v | grep linux-yocto | wc -l
7

"^creat ignored" is again mostly 195/202 package-output.lock:

martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
-v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
'^creat ignored ' | wc -l
202
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
-v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
'^creat ignored ' | grep package-output.lock | wc -l
195
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
-v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
'^creat ignored ' | grep package-output.lock -v
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/qtbase/5.9.2+gitAUTOINC+73573fce29-r0/image/usr/include/qt5/QtNetwork/qt_temp.rhjRGj'.
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/qt3d/5.9.2+gitAUTOINC+9d8c9ada16-r0/image/usr/include/qt5/Qt3DInput/qt_temp.rhjRGj'.
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/libqofono/0.87+gitrAUTOINC+54435de3be-r0/image/usr/lib/libqofono-qt5/tests/qt_temp.rhjRGj'.
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-oe-linux-gnueabi/libqofono/0.87+gitrAUTOINC+54435de3be-r0/image/usr/lib/libqofono-qt5/tests/qt_temp.rhjRGj'.
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/sstate-control/index-armv5te.lock'.
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/sstate-control/index-armv5te.lock'.
creat ignored for existing file
'/home/jenkins/oe/world/shr-core/tmp-glibc/work/i586-oe-linux/usermode/1.111-r0/build/po/.intltool-merge-cache'.

^dir err: also happens a lot in the log files where other issues appear as
well (because the QA check isn't triggered by this one):
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
-v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
'^creat ignored ' -v | grep '^dir err ' | wc -l
744

couple ^symlink err:
martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
-v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
'^creat ignored ' -v | grep '^dir err ' -v | grep '^symlink err' | wc -l
223

martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep -v
'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
-v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
'^creat ignored ' -v | grep '^dir err ' -v | grep '^symlink err' -v | grep
'^symlink mismatch: ' | wc -l
309

I fail to see useful patterns in this, maybe fixing the package-output.lock
might help to filter the noise a bit.

On Mon, Oct 16, 2017 at 5:10 PM, Burton, Ross <ross.burton@intel.com> wrote:

> On 16 October 2017 at 16:01, Martin Jansa <martin.jansa@gmail.com> wrote:
>
>> The world builds with this check applied show that *a lot* of components
>> report one of these errors and often many of errors, the most complete logs
>> from last couple days:
>>
>
> A lot of the errors in my logs were due to package-output.lock being
> accessed inside/outside pseudo context.  Can you grep all of your logs and
> collate some common patterns?
>
> Ross
>

[-- Attachment #2: Type: text/html, Size: 13076 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC][PATCHv2] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log
  2017-10-16 15:50       ` Martin Jansa
@ 2017-12-19 16:09         ` Martin Jansa
  0 siblings, 0 replies; 14+ messages in thread
From: Martin Jansa @ 2017-12-19 16:09 UTC (permalink / raw)
  To: Burton, Ross; +Cc: Patches and discussions about the oe-core layer

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

I've created
https://bugzilla.yoctoproject.org/show_bug.cgi?id=12434
to track this issue.

I get this QA error now 100% reproducible when the "right" do_package
sstate archive is being used, but still haven't found the root cause (aka
why/how this bad sstate archive was created in first place).

On Mon, Oct 16, 2017 at 5:50 PM, Martin Jansa <martin.jansa@gmail.com>
wrote:

> Yes, package-output.lock is very often the cause for "^inode mismatch":
>
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
> wc -l
> 1485
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
> grep package-output.lock | wc -l
> 1168
>
> log.do_install also causes "^inode mismatch" in many cases:
>
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
> grep -v package-output.lock | wc -l
> 317
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
> grep -v package-output.lock | grep temp/log.do_install | wc -l
> 309
>
> That leaves only couple other files:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep '^inode mismatch' |
> grep -v package-output.lock | grep -v temp/log.do_install
> inode mismatch: '/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-
> oe-linux-gnueabi/qtbase/5.9.2+gitAUTOINC+73573fce29-r0/
> image/usr/include/qt5/QtNetwork/qt_temp.rhjRGj' ino 691255 in db, 691256
> in request.
> inode mismatch: '/home/jenkins/.python-history' ino 1066494 in db,
> 1066493 in request.
> inode mismatch: '/home/jenkins/.python-history' ino 1066494 in db,
> 1066493 in request.
> inode mismatch: '/home/jenkins/.python-history' ino 1066729 in db,
> 1062665 in request.
> inode mismatch: '/home/jenkins/.python-history' ino 1066729 in db,
> 1062665 in request.
> inode mismatch: '/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-
> oe-linux-gnueabi/qt3d/5.9.2+gitAUTOINC+9d8c9ada16-r0/
> image/usr/include/qt5/Qt3DInput/qt_temp.rhjRGj' ino 520536 in db, 520539
> in request.
> inode mismatch: '/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-
> oe-linux-gnueabi/libqofono/0.87+gitrAUTOINC+54435de3be-r0/
> image/usr/lib/libqofono-qt5/tests/qt_temp.rhjRGj' ino 876399 in db,
> 876404 in request.
> inode mismatch: '/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-
> oe-linux-gnueabi/libqofono/0.87+gitrAUTOINC+54435de3be-r0/
> image/usr/lib/libqofono-qt5/tests/qt_temp.rhjRGj' ino 876404 in db,
> 876408 in request.
>
> Similarly with "creat for", but there is more wide selection of files
> triggering this one:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces'  | wc -l
> 1771
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for'  | grep package-output.lock | wc -l
> 198
>
> for "creat for" the log.do_install appears only twice, but various
> temp/run.* files are quite common cause:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run | wc -l
> 294
>
> pm-qa is triggering this on many files, e.g. /home/jenkins/oe/world/
> shr-core/tmp-glibc/work/core2-64-oe-linux/pm-qa/0.5.2-r0/
> image/usr/bin/cpuhotplug_07.sh
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run -v  |
> grep pm-qa | wc -l
> 229
>
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run -v  |
> grep pm-qa | grep cpuhotplug_05.sh
> creat for '/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-
> oe-linux-gnueabi/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh' replaces
> existing 902737 ['NAMELESS FILE'].
> creat for '/home/jenkins/oe/world/shr-core/tmp-glibc/work/armv5te-
> oe-linux-gnueabi/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh' replaces
> existing 1264757 ['NAMELESS FILE'].
> creat for '/home/jenkins/oe/world/shr-core/tmp-glibc/work/i586-oe-
> linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh' replaces existing
> 976636 ['NAMELESS FILE'].
> creat for '/home/jenkins/oe/world/shr-core/tmp-glibc/work/core2-64-
> oe-linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh' replaces existing
> 576004 ['NAMELESS FILE'].
> creat for '/home/jenkins/oe/world/shr-core/tmp-glibc/work/core2-64-
> oe-linux/pm-qa/0.5.2-r0/image/usr/bin/cpuhotplug_05.sh' replaces existing
> 986226 ['NAMELESS FILE'].
>
> then stamps files
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces'  | grep temp/run -v  |
> grep -v pm-qa | grep -v package-output.lock | grep glibc/stamps | wc -l
> 130
>
> so it looks pretty rancom, but most of these errors are replacing
> 'NAMELESS FILE'
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces' | grep 'NAMELESS FILE' |
> wc -l
> 1632
>
> which leaves only 139 other files:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces' | grep
> 'replaces.*NAMELESS FILE' -v | wc -l
> 139
>
> from which couple of them are package-output.lock again:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces' | grep
> 'replaces.*NAMELESS FILE' -v | grep replaces.*package-output.lock | wc -l
> 31
>
> and then random selection of builds, most of them from glibc-locale:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces' | grep
> 'replaces.*NAMELESS FILE' -v | grep replaces.*package-output.lock -v | grep
> glibc-locale | wc -l
> 34
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces' | grep
> 'replaces.*NAMELESS FILE' -v | grep replaces.*package-output.lock -v | grep
> llvm | wc -l
> 3
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep 'creat for.* replaces' | grep
> 'replaces.*NAMELESS FILE' -v | grep replaces.*package-output.lock -v | grep
> linux-yocto | wc -l
> 7
>
> "^creat ignored" is again mostly 195/202 package-output.lock:
>
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
> grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
> -v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
> '^creat ignored ' | wc -l
> 202
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
> grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
> -v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
> '^creat ignored ' | grep package-output.lock | wc -l
> 195
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
> grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
> -v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
> '^creat ignored ' | grep package-output.lock -v
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/work/armv5te-oe-linux-gnueabi/qtbase/5.9.2+
> gitAUTOINC+73573fce29-r0/image/usr/include/qt5/QtNetwork/qt_temp.rhjRGj'.
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/work/armv5te-oe-linux-gnueabi/qt3d/5.9.2+
> gitAUTOINC+9d8c9ada16-r0/image/usr/include/qt5/Qt3DInput/qt_temp.rhjRGj'.
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/work/armv5te-oe-linux-gnueabi/libqofono/0.
> 87+gitrAUTOINC+54435de3be-r0/image/usr/lib/libqofono-qt5/
> tests/qt_temp.rhjRGj'.
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/work/armv5te-oe-linux-gnueabi/libqofono/0.
> 87+gitrAUTOINC+54435de3be-r0/image/usr/lib/libqofono-qt5/
> tests/qt_temp.rhjRGj'.
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/sstate-control/index-armv5te.lock'.
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/sstate-control/index-armv5te.lock'.
> creat ignored for existing file '/home/jenkins/oe/world/shr-
> core/tmp-glibc/work/i586-oe-linux/usermode/1.111-r0/build/
> po/.intltool-merge-cache'.
>
> ^dir err: also happens a lot in the log files where other issues appear as
> well (because the QA check isn't triggered by this one):
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
> grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
> -v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
> '^creat ignored ' -v | grep '^dir err ' | wc -l
> 744
>
> couple ^symlink err:
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
> grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
> -v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
> '^creat ignored ' -v | grep '^dir err ' -v | grep '^symlink err' | wc -l
> 223
>
> martin@jama ~/pseudo-qa $ cat log.world.qemu* | grep -v "grep -e" | grep
> -v 'inode mismatch' | grep -v 'creat for.* replaces' | grep -v indicates |
> grep -v '^Setup complete' | grep -v '^db cleanup' | grep -v '^pid ' | grep
> -v '^ \[' | grep -v '^memory-to-file' | grep -v '^debug_logfile: ' | grep
> '^creat ignored ' -v | grep '^dir err ' -v | grep '^symlink err' -v | grep
> '^symlink mismatch: ' | wc -l
> 309
>
> I fail to see useful patterns in this, maybe fixing the
> package-output.lock might help to filter the noise a bit.
>
> On Mon, Oct 16, 2017 at 5:10 PM, Burton, Ross <ross.burton@intel.com>
> wrote:
>
>> On 16 October 2017 at 16:01, Martin Jansa <martin.jansa@gmail.com> wrote:
>>
>>> The world builds with this check applied show that *a lot* of components
>>> report one of these errors and often many of errors, the most complete logs
>>> from last couple days:
>>>
>>
>> A lot of the errors in my logs were due to package-output.lock being
>> accessed inside/outside pseudo context.  Can you grep all of your logs and
>> collate some common patterns?
>>
>> Ross
>>
>
>

[-- Attachment #2: Type: text/html, Size: 14336 bytes --]

^ permalink raw reply	[flat|nested] 14+ messages in thread

end of thread, other threads:[~2017-12-19 16:09 UTC | newest]

Thread overview: 14+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-09-13 20:46 [RFC][PATCH] insane.bbclass: Add do_qa_pseudo function to check for common errors listed in pseudo.log Martin Jansa
2017-09-13 20:50 ` Martin Jansa
2017-09-13 22:08   ` Seebs
2017-09-13 22:28     ` Martin Jansa
2017-09-14 14:27       ` Seebs
2017-09-14 13:17     ` Burton, Ross
2017-09-13 22:09 ` Seebs
2017-09-14 14:53   ` Burton, Ross
2017-09-14 14:59     ` Seebs
2017-09-19 15:18 ` [RFC][PATCHv2] " Martin Jansa
2017-10-16 15:01   ` Martin Jansa
2017-10-16 15:10     ` Burton, Ross
2017-10-16 15:50       ` Martin Jansa
2017-12-19 16:09         ` Martin Jansa

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox