Bug 6477

Other occurence:
=======
DEBUG: Executing shell function sysroot_stage_all
/home/nxadm/nx/yow-lpgbld-vm66.1/builds-2014-06-17-170158/qemux86_world_bp_ds/bitbake_build/tmp/work/i586-wrs-linux/strace/4.8-r0/temp/do_populate_sysroot/run.do_populate_sysroot.sysroot_stage_all.18517: line 106: sysroot_stage_dirs: command not found
WARNING: /home/nxadm/nx/yow-lpgbld-vm66.1/builds-2014-06-17-170158/qemux86_world_bp_ds/bitbake_build/tmp/work/i586-wrs-linux/strace/4.8-r0/temp/do_populate_sysroot/run.do_populate_sysroot.sysroot_stage_all.18517:105 exit 127 from
  sysroot_stage_dirs /home/nxadm/nx/yow-lpgbld-vm66.1/builds-2014-06-17-170158/qemux86_world_bp_ds/bitbake_build/tmp/work/i586-wrs-linux/strace/4.8-r0/image /home/nxadm/nx/yow-lpgbld-vm66.1/builds-2014-06-17-170158/qemux86_world_bp_ds/bitbake_build/tmp/work/i586-wrs-linux/strace/4.8-r0/sysroot-destdir/
DEBUG: Python function do_populate_sysroot finished
ERROR: Function failed: sysroot_stage_all (log file is located at /home/nxadm/nx/yow-lpgbld-vm66.1/builds-2014-06-17-170158/qemux86_world_bp_ds/bitbake_build/tmp/work/i586-wrs-linux/strace/4.8-r0/temp/do_populate_sysroot/log.do_populate_sysroot.18517)

=======
DEBUG: Executing shell function sysroot_stage_all
/home/nxadm/nx/yow-lpgbld-vm50.1/builds-2014-06-14-085246/qemux86-64_tiny_bprod/bitbake_build/tmp/work/i686-linux/lzo-native/2.06-r1/temp/do_populate_sysroot/run.do_populate_sysroot.sysroot_stage_all.7943: line 106: sysroot_stage_dirs: command not found
WARNING: /home/nxadm/nx/yow-lpgbld-vm50.1/builds-2014-06-14-085246/qemux86-64_tiny_bprod/bitbake_build/tmp/work/i686-linux/lzo-native/2.06-r1/temp/do_populate_sysroot/run.do_populate_sysroot.sysroot_stage_all.7943:105 exit 127 from
  sysroot_stage_dirs /home/nxadm/nx/yow-lpgbld-vm50.1/builds-2014-06-14-085246/qemux86-64_tiny_bprod/bitbake_build/tmp/work/i686-linux/lzo-native/2.06-r1/image /home/nxadm/nx/yow-lpgbld-vm50.1/builds-2014-06-14-085246/qemux86-64_tiny_bprod/bitbake_build/tmp/work/i686-linux/lzo-native/2.06-r1/sysroot-destdir/
DEBUG: Python function do_populate_sysroot finished
ERROR: Function failed: sysroot_stage_all (log file is located at /home/nxadm/nx/yow-lpgbld-vm50.1/builds-2014-06-14-085246/qemux86-64_tiny_bprod/bitbake_build/tmp/work/i686-linux/lzo-native/2.06-r1/temp/do_populate_sysroot/log.do_populate_sysroot.7943)

Which version of the metadata is this? Do you have http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=107269d9d02debe1adde9745df52da9dd5faf5c7 applied?

(In reply to comment #2)
> Which version of the metadata is this? Do you have

It's bitbake 2.0.0, the latest occurrence was using the one we rebase upstream
master on 6/18/2014.

> http://git.yoctoproject.org/cgit.cgi/poky/commit/
> ?id=107269d9d02debe1adde9745df52da9dd5faf5c7 applied?

yeah, we did have this one.

Unfortunately my hands are tied on this one as we can't reproduce. I'm reassigning it to Jackie since he at least has access to the problematic build environment.

We have code in bitbake (codeparser) which determines the dependencies between the different shell functions and its likely something is missing a dependency which than means the function isn't emitted into the final script.

Saving off the caches in a failed build and then comparing them with a good build may be one way to debug this.

(In reply to comment #4)
> Unfortunately my hands are tied on this one as we can't reproduce. I'm
> reassigning it to Jackie since he at least has access to the problematic
> build environment.

We lost the latest problematic environment, but I will save one and try to debug on it if it happens again. 

> 
> We have code in bitbake (codeparser) which determines the dependencies
> between the different shell functions and its likely something is missing a
> dependency which than means the function isn't emitted into the final script.
> 
> Saving off the caches in a failed build and then comparing them with a good
> build may be one way to debug this.

The issue reproduced again and it seems to me a hash collision after some debugging in the problematic environment.

when doing parse_shell for "sysroot_stage_dirs",
emit_func in lib/bb/data.py:
newdeps |=  bb.codeparser.ShellParser(dep, logger).parse_shell(d.getVar(dep, True))

parse_shell in lib/bb/codeparser.py:
h = hash(str(value))
if h in codeparsercache.shellcache:
    self.execs = codeparsercache.shellcache[h]["execs"]
    return self.execs

and we get:
h: -296430354
codeparsercache.shellcache: -296430354: {'execs': set(['ln', 'rm'])}
newdeps: set(['ln', 'rm']

which is incorrect, the expected deps should be:
set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])

Looks like hash with different values(strings) may get the same hash value.

Then I checked our history reproducers (about 10 times since April, 2014) and found that all failures occurred on 32bit host, seems like the hash function in python work unreliable. I think maybe we should use hashlib.md5 instead.

Jackie: Are you still seeing this?

On a 32 bit system we see:

>>> hash("set(['ln', 'rm'])")
-1829747437
>>> hash("set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])")
2018305735

which are not identical and not -296430354.

Could you provide information about how you debugged this and what kind of a system this is on please?

Looking further at this, you actually mean that:
hash("sysroot_stage_dirs")
can have the same value as something else. It doesn't hash to that value you mention, can you illustrate which values you believe have the same hash value?

>>> hash("sysroot_stage_dirs")
-871805407

The more likely way this could corrupt is like the case I linked to above, you mention that was in your tree though :/

(In reply to comment #7)
> Jackie: Are you still seeing this?

Yes, we had 20+ this failures on our daily builds in the past 3 months, all of them happend on 32 bit systems(opensuse13.1_32, centos6_32, centos5.11_32, fedora20_32 and SLED11.2_32).

> 
> On a 32 bit system we see:
> 
> >>> hash("set(['ln', 'rm'])")
> -1829747437
> >>> hash("set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])")
> 2018305735
> 
> which are not identical and not -296430354.

Yes, I know, I got the same result if I run hash on a 32 bit system manually.

> 
> Could you provide information about how you debugged this and what kind of a
> system this is on please?

The system I was debugging on is CentOS 5.11 32bit, and just put some prints around in lib/bb/data.py and find that when parsing the "sysroot_stage_dir" functin, the hash value returned "-296430354", but in codeparsercache.shellcache, the key "-296430354" points to "{'execs': set(['ln', 'rm'])}", then the "sysroot_stage_dir" was missing in the deps.

I also use the contrib/dump_cache.py(with a little modified) to dump the bb_codeparser.dat and checked the value.

Created attachment 2435 [details]
The bb_codeparser.dat in a failure builds and the script to dump the data.

The attachment includes the bb_codeparser.dat in a failure builds and the script to dump the data:
$ ./dump_cache-debug.py bb_codeparser.dat > bb_codeparser.txt

Is it expected that the same string is saved many times(2000+) in the cache file?

I see:

$ grep -F "set(['ln', 'rm'])" bb_codeparser.txt | tail
-2134115093: {'execs': set(['ln', 'rm'])}
914226412: {'execs': set(['ln', 'rm'])}
-529269462: {'execs': set(['ln', 'rm'])}
285081048: {'execs': set(['ln', 'rm'])}
2089024993: {'execs': set(['ln', 'rm'])}
-1214906856: {'execs': set(['ln', 'rm'])}
-888013222: {'execs': set(['ln', 'rm'])}
1842871998: {'execs': set(['ln', 'rm'])}
3276754: {'execs': set(['ln', 'rm'])}
-1541387081: {'execs': set(['ln', 'rm'])}
$ grep -F "set(['ln', 'rm'])" bb_codeparser.txt | wc -l
2721
$ grep -F "set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])" bb_codeparser.txt | wc -l
2432

Run hash manually, I see:

>>> hash("set(['ln', 'rm'])")
-1829747437
>>> hash("set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])")
2018305735

But neither "-1829747437" nor "2018305735" in the cache file:
$ egrep "\-1829747437|2018305735" bb_codeparser.txt
$

(In reply to comment #11)
> Is it expected that the same string is saved many times(2000+) in the cache
> file?

With version 6 of the cache format which you appear to be using, yes. There were improvements:

http://git.yoctoproject.org/cgit.cgi/poky/commit/bitbake/lib/bb/codeparser.py?id=89d178841208557b030103cf0ae813a42550487c

(In reply to comment #11)
> I see:
> 
> $ grep -F "set(['ln', 'rm'])" bb_codeparser.txt | tail
> -2134115093: {'execs': set(['ln', 'rm'])}
> 914226412: {'execs': set(['ln', 'rm'])}
> -529269462: {'execs': set(['ln', 'rm'])}
> 285081048: {'execs': set(['ln', 'rm'])}
> 2089024993: {'execs': set(['ln', 'rm'])}
> -1214906856: {'execs': set(['ln', 'rm'])}
> -888013222: {'execs': set(['ln', 'rm'])}
> 1842871998: {'execs': set(['ln', 'rm'])}
> 3276754: {'execs': set(['ln', 'rm'])}
> -1541387081: {'execs': set(['ln', 'rm'])}
> $ grep -F "set(['ln', 'rm'])" bb_codeparser.txt | wc -l
> 2721
> $ grep -F "set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])"
> bb_codeparser.txt | wc -l
> 2432
> 
> Run hash manually, I see:
> 
> >>> hash("set(['ln', 'rm'])")
> -1829747437
> >>> hash("set(['sysroot_stage_dir', '[', 'rm', 'sysroot_stage_libdir'])")
> 2018305735
> 
> But neither "-1829747437" nor "2018305735" in the cache file:
> $ egrep "\-1829747437|2018305735" bb_codeparser.txt
> $

That is to be expected. You'd have to hash the code which has these dependencies to generate the hash value, its not the hash of the result but the input. Unfortunately debugging is tricky since the input code is not saved in the cache.

I think this was a bug fixed between versions 6 and 7 of the codeparser cache. Specifically, in 
http://git.yoctoproject.org/cgit.cgi/poky/commit/bitbake/lib/bb/codeparser.py?id=89d178841208557b030103cf0ae813a42550487c

there is

         if h in codeparsercache.pythoncache:
-            self.references = codeparsercache.pythoncache[h]["refs"]
-            self.execs = codeparsercache.pythoncache[h]["execs"]
-            self.contains = codeparsercache.pythoncache[h]["contains"]
+            self.references = set(codeparsercache.pythoncache[h].refs)

and the new code creates new set() entries, in the old code, a set was reused. This could be modified and create cache corrption. Making it a frozenset() (as in the above patch) made the problem much more obvious.

I'm guessing the above change therefore resolves this issue.

(In reply to comment #14)
> I think this was a bug fixed between versions 6 and 7 of the codeparser
> cache. Specifically, in 
> http://git.yoctoproject.org/cgit.cgi/poky/commit/bitbake/lib/bb/codeparser.
> py?id=89d178841208557b030103cf0ae813a42550487c
> 
> there is
> 
>          if h in codeparsercache.pythoncache:
> -            self.references = codeparsercache.pythoncache[h]["refs"]
> -            self.execs = codeparsercache.pythoncache[h]["execs"]
> -            self.contains = codeparsercache.pythoncache[h]["contains"]
> +            self.references = set(codeparsercache.pythoncache[h].refs)
> 
> and the new code creates new set() entries, in the old code, a set was
> reused. This could be modified and create cache corrption. Making it a
> frozenset() (as in the above patch) made the problem much more obvious.
> 
> I'm guessing the above change therefore resolves this issue.

FYI, we're still getting this with some of our automated builds with dizzy, at Mentor, and dizzy includes that commit, so I don't think this is correct.