Closed Bug 1048993 Opened 5 years ago Closed 5 years ago

Intermittent B2G "make[5]: *** [../dist/include/mozilla-config.h] Error 127" or "make[6]: *** [../dist/include/mozilla-config.h] Error 127" after "make[6]: ../dist/bin/nsinstall: Command not found"

Categories

(Firefox Build System :: General, defect)

defect
Not set

Tracking

(firefox32 unaffected, firefox33 unaffected, firefox34 fixed, firefox-esr24 unaffected, firefox-esr31 unaffected)

RESOLVED FIXED
mozilla34
Tracking Status
firefox32 --- unaffected
firefox33 --- unaffected
firefox34 --- fixed
firefox-esr24 --- unaffected
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: glandium)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Not really sure where this bug belongs, but ignoring it isn't helping. It's been happening across all trees for probably a couple weeks now.

https://tbpl.mozilla.org/php/getParsedLog.php?id=45257778&tree=Mozilla-Inbound

b2g_mozilla-inbound_emulator_dep on 2014-08-05 10:05:07 PDT for push 174637171dbe
slave: bld-linux64-spot-1069

10:09:10     INFO -  make[4]: Entering directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko'
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest dist/bin _build_manifests/install/dist_bin
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest dist/idl _build_manifests/install/dist_idl
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest dist/include _build_manifests/install/dist_include
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest dist/public _build_manifests/install/dist_public
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest dist/private _build_manifests/install/dist_private
10:09:10     INFO -  From dist/public: Kept 0 existing; Added/updated 0; Removed 0 files and 0 directories.
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest dist/sdk _build_manifests/install/dist_sdk
10:09:10     INFO -  From dist/private: Kept 0 existing; Added/updated 0; Removed 148 files and 1 directories.
10:09:10     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python -m mozbuild.action.process_install_manifest _tests _build_manifests/install/tests
10:09:10     INFO -  From dist/idl: Kept 1098 existing; Added/updated 0; Removed 0 files and 0 directories.
10:09:11     INFO -  From dist/bin: Kept 48 existing; Added/updated 0; Removed 2138 files and 256 directories.
10:09:11     INFO -  From dist/sdk: Kept 0 existing; Added/updated 0; Removed 21 files and 4 directories.
10:09:11     INFO -  From dist/include: Kept 4248 existing; Added/updated 1; Removed 186 files and 5 directories.
10:09:12     INFO -  From _tests: Kept 15372 existing; Added/updated 16; Removed 697 files and 105 directories.
10:09:12     INFO -  make recurse_export
10:09:13     INFO -  make[5]: Entering directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko'
10:09:13     INFO -  make[6]: Entering directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/config'
10:09:13     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python /builds/slave/b2g_m-in_emu_dep-0000000000000/build/gecko/config/nsinstall.py -t -m 755 'nsinstall' '../dist/bin'
10:09:13     INFO -  make[6]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/config'
10:09:13     INFO -  make[6]: Entering directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/config'
10:09:13     INFO -  ../dist/bin/nsinstall -R -m 755 'nsinstall' '../dist/bin'
10:09:13     INFO -  ../dist/bin/nsinstall -R -m 644 '../mozilla-config.h' '../dist/include'
10:09:13     INFO -  make[6]: ../dist/bin/nsinstall: Command not found
10:09:13    ERROR -  make[6]: *** [../dist/include/mozilla-config.h] Error 127
10:09:13     INFO -  make[6]: *** Waiting for unfinished jobs....
10:09:13     INFO -  make[6]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/config'
10:09:13    ERROR -  make[5]: *** [config/export] Error 2
10:09:13     INFO -  make[5]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko'
10:09:13    ERROR -  make[4]: *** [export] Error 2
10:09:13     INFO -  make[4]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko'
10:09:13    ERROR -  make[3]: *** [default] Error 2
10:09:13     INFO -  make[3]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko'
10:09:13    ERROR -  make[2]: *** [realbuild] Error 2
10:09:13     INFO -  make[2]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/gecko'
10:09:13    ERROR -  make[1]: *** [build] Error 2
10:09:13     INFO -  make[1]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/gecko'
10:09:13     INFO -  make: *** [out/target/product/generic/obj/DATA/gecko_intermediates/gecko] Error 2
10:09:13     INFO -  make: *** Waiting for unfinished jobs....
https://tbpl.mozilla.org/php/getParsedLog.php?id=45262966&tree=Fx-Team
Summary: Intermittent B2G "make[6]: *** [../dist/include/mozilla-config.h] Error 127" after "make[6]: ../dist/bin/nsinstall: Command not found" → Intermittent B2G "make[5]: *** [../dist/include/mozilla-config.h] Error 127" or "make[6]: *** [../dist/include/mozilla-config.h] Error 127" after "make[6]: ../dist/bin/nsinstall: Command not found"
CCing glandium in case this turns out to be a build system bug.
Oh, nice race condition:

10:09:13     INFO -  /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/bin/python /builds/slave/b2g_m-in_emu_dep-0000000000000/build/gecko/config/nsinstall.py -t -m 755 'nsinstall' '../dist/bin'

nsinstall is copied to ../dist/bin with nsinstall.py

10:09:13     INFO -  make[6]: Leaving directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/config'
10:09:13     INFO -  make[6]: Entering directory `/builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/config'

This is indication that the build dependencies are right and things are going sequentially (that is, what follows is executed after what's above)

10:09:13     INFO -  ../dist/bin/nsinstall -R -m 755 'nsinstall' '../dist/bin'
10:09:13     INFO -  ../dist/bin/nsinstall -R -m 644 '../mozilla-config.h' '../dist/include'

Those execute in parallel.

10:09:13     INFO -  make[6]: ../dist/bin/nsinstall: Command not found

This is likely an error happening on the second command because the first re-installs nsinstall to ../dist/bin.

I see two ways out here:
- Figure out why make thinks it needs to re-install nsinstall
- Use nsinstall from $(topobjdir)/config instead of $(DIST)/bin.
Assignee: nobody → mh+mozilla
Status: NEW → ASSIGNED
Attachment #8468317 - Attachment is patch: false
Attachment #8468317 - Flags: review?(mshal)
Attachment #8468317 - Attachment is obsolete: true
Attachment #8468317 - Attachment is patch: true
Component: General Automation → Build Config
OS: Gonk (Firefox OS) → All
Product: Release Engineering → Core
QA Contact: catlee
Hardware: ARM → All
(In reply to Mike Hommey [:glandium] from comment #5)
> /builds/slave/b2g_m-in_emu_dep-0000000000000/build/objdir-gecko/_virtualenv/
> bin/python
> /builds/slave/b2g_m-in_emu_dep-0000000000000/build/gecko/config/nsinstall.py
> -t -m 755 'nsinstall' '../dist/bin'

With 'nsinstall.py -t', it uses shutil.copy2 (shutil.copystat under the hood), which is trying to preserve the timestamp of config/nsinstall when it installs to dist/bin/nsinstall. Unfortunately it sounds like python uses floats internally for this, resulting in truncation of the nanosecond field. If you add some stats in nsinstall.py you can see the problem:

  File: ‘/home/marf/mozilla-central-git/obj-x86_64-unknown-linux-gnu/config/nsinstall’
  Size: 23770           Blocks: 48         IO Block: 4096   regular file
Device: 801h/2049d      Inode: 12730416    Links: 1
Access: (0775/-rwxrwxr-x)  Uid: ( 1000/    marf)   Gid: ( 1000/    marf)
Access: 2014-08-06 13:24:26.561346636 -0400
Modify: 2014-08-06 13:24:26.561346636 -0400
Change: 2014-08-06 13:24:26.561346636 -0400

  File: ‘/home/marf/mozilla-central-git/obj-x86_64-unknown-linux-gnu/dist/bin/nsinstall’
  Size: 23770           Blocks: 48         IO Block: 4096   regular file
Device: 801h/2049d      Inode: 12331023    Links: 1
Access: (0775/-rwxrwxr-x)  Uid: ( 1000/    marf)   Gid: ( 1000/    marf)
Access: 2014-08-06 13:24:26.561346000 -0400
Modify: 2014-08-06 13:24:26.561346000 -0400
Change: 2014-08-06 13:34:41.589335041 -0400

The last 3 digits of mtime became 000, so dist/bin/nsinstall is older than config/nsinstall and it gets reinstalled the second time make recurses into config.
Comment on attachment 8468322 [details] [diff] [review]
Use nsinstall from $(topobjdir)/config instead of $(DIST)/bin to avoid races when make wants to reinstall it for some reason

It seems like this fixes the problem, so r+. But maybe it is worth fixing shutil.copy2, or not doing nsinstall.py -t to avoid timestamp resolution issues? Up to you if you want to look into it.
Attachment #8468322 - Flags: review?(mshal) → review+
> Unfortunately it sounds like python uses floats internally for this, resulting in truncation
> of the nanosecond field.

Ah, in fact it's just that it's using the POSIX API that doesn't have nanosecond resolution.
(In reply to Mike Hommey [:glandium] from comment #12)
> > Unfortunately it sounds like python uses floats internally for this, resulting in truncation
> > of the nanosecond field.
> 
> Ah, in fact it's just that it's using the POSIX API that doesn't have
> nanosecond resolution.

oic - I should have mentioned I read about the floats thing in a random blog post, so who knows how accurate it is :). However it decides to truncate, that's obviously not what we want.
https://hg.mozilla.org/mozilla-central/rev/b5abd8d46814
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
Product: Core → Firefox Build System
You need to log in before you can comment on or make changes to this bug.