"ImportError: No module named mach.logging" in backend.RecursiveMakeBackend make target, with mozmake

RESOLVED FIXED in mozilla28

Status

defect
RESOLVED FIXED
6 years ago
a year ago

People

(Reporter: Gijs, Assigned: mbrubeck)

Tracking

unspecified
mozilla28
x86_64
Windows 7

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

Reporter

Description

6 years ago
$ ./mach build browser
 0:00.45 E:/mozilla-build/msys/bin/sh.exe -c E:/mozilla-build/msys/bin/mozmake.EXE -C e:/dev/builds/ux-i686-pc-mingw32 -j8 -s
 backend.RecursiveMakeBackend
 0:00.69 Build configuration changed. Regenerating backend.
 0:00.73 Traceback (most recent call last):
 0:00.73   File "e:\dev\builds\ux-i686-pc-mingw32\config.status", line 878, in <module>
 0:00.73     from ConfigStatus import config_status
 0:00.73   File "e:/dev/ux-central\build\ConfigStatus.py", line 17, in <module>
 0:00.73     from mach.logging import LoggingManager
 0:00.75 ImportError: No module named mach.logging
 0:00.75 Makefile:78: recipe for target 'backend.RecursiveMakeBackend' failed
 0:00.75 mozmake.EXE: *** [backend.RecursiveMakeBackend] Error 1
Error running mach:

    ['build', 'browser']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.

You should consider filing a bug for this issue.

If filing a bug, please include the full output of mach, including this error
message.


The details of the failure are as follows:

Exception: Process executed with non-0 exit code: [u'E:/mozilla-build/msys/bin/sh.exe', u'-c', u'E:/mozilla-build/msys/bin/mozmake.EXE -C e:/dev/builds/ux-i686-pc-mingw32 -j8 -s backend.RecursiveMakeBackend']

  File "e:\dev\ux-central\python/mozbuild/mozbuild/mach_commands.py", line 366, in build
    log=False, print_directory=False)
  File "e:\dev\ux-central\python/mozbuild\mozbuild\base.py", line 463, in _run_make
    return fn(**params)
  File "e:\dev\ux-central\python/mozbuild\mozbuild\base.py", line 494, in _run_command_in_objdir
    return self.run_process(cwd=self.topobjdir, **args)
  File "e:\dev\ux-central\python/mach\mach\mixin\process.py", line 137, in run_process
    raise Exception('Process executed with non-0 exit code: %s' % args)



Windows, msvc, today or yesterday's m-c + ux, MOZCONFIG:
$ cat $MOZCONFIG
export MOZ_PSEUDO_DERECURSE=no-pymake

mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../builds/ux-@CONFIG_GUESS@

ac_add_options --enable-profiling


All this is after applying bug 933779 so that mach doesn't get stuck on Windows paths.
I am seeing this now as well.
So one thing I noticed... after pulling today the first thing I did was test that `mach build browser` worked, and it did. Then I did a clobber and full build, and now I'm seeing this error.
Brandon confirmed in IRC that ./config.status from the objdir seems to be working just fine. This rules out a class of issues around python.exe environment detection.

config.status's #! contains the virtualenv python. I confirmed /Makefile.in invokes |./config.status|, so it should pick up the virtualenv python. This is most weird.
Something fishy in the virtualenv manager after bug 932637?
Undoing that patch didn't fix the problem for me.
I wonder if the "mach" script from the root of the tree is getting registered as the "mach" Python package and Python somehow ends up looking for mach.logging (mach/logging.py) under path/to/mach/logging.py.
The problem is that sys.path is just the default when this is invoked - nothing in the python nor testing subdirectories are on the path.  IOW, even a simple "import mach" fails.  It looks like mach_bootstrap() hasn't been run (but I'm not sure how to run it, as I'm not sure how to determine the |topsrcdir| param this function needs.
Incase it helps anyone get past this dev blocker, the following hack makes things work for me:

--- a/python/mozbuild/mozbuild/controller/building.py
+++ b/python/mozbuild/mozbuild/controller/building.py
@@ -543,6 +543,7 @@ class BuildDriver(MozbuildObject):
         env = {}
         if not remove:
             env[b'NO_REMOVE'] = b'1'
+        env[b'PYTHONPATH'] = os.pathsep.join(sys.path)

         self._run_make(target='install-tests', append_env=env, pass_thru=True,
             print_directory=False)
(In reply to Mark Hammond [:markh] from comment #8)

I still hit the error with that patch applied.
(In reply to David Major [:dmajor] from comment #9)
> (In reply to Mark Hammond [:markh] from comment #8)
> 
> I still hit the error with that patch applied.

Yeah, it looks like it can happen in various different ways.  Applying the following similar patch also fixed the problem next time I saw it:

--- a/python/mach/mach/mixin/process.py
+++ b/python/mach/mach/mixin/process.py
@@ -116,6 +116,7 @@ class ProcessExecutionMixin(LoggingMixin):
             normalized_env[k] = v

         use_env = normalized_env
+        use_env[b'PYTHONPATH'] = os.pathsep.join(sys.path)

         if pass_thru:
             status = subprocess.call(args, cwd=cwd, env=use_env)
err - make that:
  use_env[b'PYTHONPATH'] = os.pathsep.join(sys.path).encode('utf-8')
Duplicate of this bug: 935449
We shouldn't need to set PYTHONPATH for this to work.

Please do the following.

$ mach python

>>> import mach.logging
>>> import sys
>>> print('\n'.join(sys.path))
Flags: needinfo?(mhammond)
Flags: needinfo?(dmajor)
I did this and get the same list both from earlier revision that doesn't break as well as a current one that breaks:

c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\Scripts\python27.zip
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\DLLs
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\lib
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\lib\plat-win
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\lib\lib-tk
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\Scripts
c:\mozilla-build\python\Lib
c:\mozilla-build\python\DLLs
c:\mozilla-build\python\Lib\lib-tk
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv
c:\src\fx-team\obj-i686-pc-mingw32\_virtualenv\lib\site-packages
c:\src\fx-team\python\blessings
c:\src\fx-team\python\codegen
c:\src\fx-team\python\configobj
c:\src\fx-team\python\mach
c:\src\fx-team\testing\mozbase\manifestdestiny
c:\src\fx-team\testing\marionette\client
c:\src\fx-team\python\mock-1.0.0
c:\src\fx-team\testing\mozbase\mozb2g
c:\src\fx-team\python\mozbuild
c:\src\fx-team\testing\mozbase\mozcrash
c:\src\fx-team\testing\mozbase\mozdevice
c:\src\fx-team\testing\mozbase\mozfile
c:\src\fx-team\testing\mozbase\mozhttpd
c:\src\fx-team\build
c:\src\fx-team\config
c:\src\fx-team\xpcom\typelib\xpt\tools
c:\src\fx-team\testing\mozbase\mozinfo
c:\src\fx-team\testing\mozbase\mozinstall
c:\src\fx-team\testing\mozbase\mozlog
c:\src\fx-team\testing\mozbase\moznetwork
c:\src\fx-team\testing\mozbase\mozprocess
c:\src\fx-team\testing\mozbase\mozprofile
c:\src\fx-team\testing\mozbase\mozrunner
c:\src\fx-team\testing\mozbase\mozsystemmonitor
c:\src\fx-team\testing\mozbase\moztest
c:\src\fx-team\obj-i686-pc-mingw32\build
c:\src\fx-team\other-licenses\ply
c:\src\fx-team\python\psutil
c:\src\fx-team\build\pymake
c:\src\fx-team\python\which
I have the same results as comment 14 (modulo topsrcdir and objdir) both before and after the break.
Flags: needinfo?(dmajor)
And you are both able to |import mach.logging| from the interactive shell without error?
(In reply to Gregory Szorc [:gps] from comment #16)
> And you are both able to |import mach.logging| from the interactive shell
> without error?

Like the first part of comment 13? Yeah, I didn't get any errors from that.
Indeed, no errors from any of that.
Assignee

Comment 19

6 years ago
If I add print('\n'.join(sys.path)) right before the failing line in ConfigStatus.py, then when I run "mach build" it prints:

 0:02.38 c:\Users\mbrub_000\src\elm\obj-metro
 0:02.38 c:\mozilla-build\python\lib\site-packages\setuptools-0.6c11-py2.7.egg
 0:02.38 c:\mozilla-build\python\python27.zip
 0:02.38 c:\mozilla-build\python\DLLs
 0:02.38 c:\mozilla-build\python\lib
 0:02.38 c:\mozilla-build\python\lib\plat-win
 0:02.38 c:\mozilla-build\python\lib\lib-tk
 0:02.38 c:\mozilla-build\python
 0:02.38 c:\mozilla-build\python\lib\site-packages
 0:02.38 c:/Users/mbrub_000/src/elm\build

So despite the #! line, this does not seem to be running with the virtualenv sys.path.
Assignee

Comment 20

6 years ago
This patch fixes the bug for me, but I don't understand why it would be needed.
Attachment #828237 - Flags: review?(gps)
Comment on attachment 828237 [details] [diff] [review]
use $(PYTHON) explicitly to run config.status

Review of attachment 828237 [details] [diff] [review]:
-----------------------------------------------------------------

This is acceptable. Still scratching my head why the shebang isn't picked up properly.
Attachment #828237 - Flags: review?(gps) → review+
Assignee

Comment 22

6 years ago
Note: This bug affects mozmake (GNU Make) but not pymake.
Summary: ImportError: No module named mach.logging when trying to run mach build → "ImportError: No module named mach.logging" in backend.RecursiveMakeBackend make target, with mozmake
I can reproduce this. Not sure what's going on. config.status via /Makefile is reporting mozillabuild's python.exe as sys.executable despite the shebang in config.status listing the virtualenv's. If I run ./config.status manually, the shebang is honored. I don't see anything Python related in the environment variables. Most weird.
Yes, this only is an issue with mozmake.

First line of my config.status:

#!c:/dev/src/mozilla-central/obj-ff/_virtualenv/Scripts/python.exe
   Must remake target 'backend.RecursiveMakeBackend'.
Creating temporary batch file C:/Users/gps/AppData/Local/Temp/make10536-2.sh
Batch file contents:
	echo "Build configuration changed. Regenerating backend."
CreateProcess(C:\dev\mozilla-build\msys\bin\sh.exe,C:/dev/mozilla-build/msys/bin/sh.exe C:/Users/gps/AppData/Local/Temp/make10536-2.sh,...)
Putting child 00E92D08 (backend.RecursiveMakeBackend) PID 15627800 on the chain.
Live child 00E92D08 (backend.RecursiveMakeBackend) PID 15627800 
Build configuration changed. Regenerating backend.
Reaping winning child 00E92D08 PID 15627800 
Cleaning up temp batch file C:/Users/gps/AppData/Local/Temp/make10536-2.sh
./config.status
CreateProcess(NULL,python.exe c:\dev\src\mozilla-central\obj-ff\config.status,...)
Live child 00E92D08 (backend.RecursiveMakeBackend) PID 15627800
Assignee

Comment 26

6 years ago
https://hg.mozilla.org/integration/fx-team/rev/440d233acb2e

I'm still poking at this to try to figure out the root cause, too.
Assignee: nobody → mbrubeck
Status: NEW → ASSIGNED
Component: mach → Build Config
Flags: needinfo?(mhammond)
Swapping the / for \ in the shebang fixes the issue.

I /think/ this is a limitation in sh.exe's shebang detection. glandium knows all about this given his recent mozmake work and can probably comment further.
Flags: needinfo?(mh+mozilla)
That patch doesn't seem to fix it for me. Is there anything else I might need to do to get it to work?
Assignee

Comment 29

6 years ago
(In reply to Brandon Benvie [:benvie] from comment #28)
> That patch doesn't seem to fix it for me. Is there anything else I might
> need to do to get it to work?

You'll need to manually run "./config.status" in your objdir one last time, to get the patch to take effect.
Also confirmed that manually changing the forward slashes to back slashes in config.status seems to fix it.
It looks like a similar patch landed in bug 932637 which also solves this problem for me.
I'll file a GNU make bug.
Flags: needinfo?(mh+mozilla)
(In reply to Mark Hammond [:markh] from comment #31)
> It looks like a similar patch landed in bug 932637 which also solves this
> problem for me.

I spoke too soon - it looks like it fixed it in one context, but not others...
(In reply to Gregory Szorc [:gps] from comment #27)
> Swapping the / for \ in the shebang fixes the issue.
> 
> I /think/ this is a limitation in sh.exe's shebang detection. glandium knows
> all about this given his recent mozmake work and can probably comment
> further.

It's, in fact, a limitation to the *GNU make* shebang detection. The relevant code is here:
http://git.savannah.gnu.org/cgit/make.git/tree/w32/subproc/sub_proc.c?id=9d58570c77240fed53d1f88217877f8e778f4bb2#n668

Relevant comment is here:
http://git.savannah.gnu.org/cgit/make.git/tree/w32/subproc/sub_proc.c?id=9d58570c77240fed53d1f88217877f8e778f4bb2#n622

So what GNU make does is consider that the path in the shebang is crap, and assume whatever file with the same basename is in the PATH will work. Which is arguably a problem in itself, but it further fails to do that consistently: if the shabang path uses backslashes, it doesn't do it.

I'll file an upstream bug.
https://hg.mozilla.org/mozilla-central/rev/440d233acb2e
Status: ASSIGNED → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla28

Updated

a year ago
Product: Core → Firefox Build System
You need to log in before you can comment on or make changes to this bug.