Open Bug 1423666 Opened 4 years ago Updated 4 years ago

mach buildsymbols produces empty zips?

Categories

(Toolkit :: Crash Reporting, defect)

defect
Not set
normal

Tracking

()

People

(Reporter: Gankra, Assigned: rhunt)

Details

Attachments

(2 files, 1 obsolete file)

Attached file log.txt
Fairly recent install on x64 windows 10, buildsymbols seems to finish very quickly and produce empty zips and no output dir. As a result the gecko profiler gets no symbols.

See attached log for details (mozconfig is fairly boring and shouldn't affect this).
Apparently the problem is that dump_syms.exe is not present, in objdir/dist/bin/.
config.status contains 'MSVC_HAS_DIA_SDK': '1',
Ted, do you have pointers for where to look next?
Flags: needinfo?(ted)
Sorry, maybe I typoed or you misread, but the binary should be at $objdir/dist/host/bin/dump_syms.exe . If that's not present even though MSVC_HAS_DIA_SDK is set something else is seriously broken.
Flags: needinfo?(ted)
Oh, ok. There is a dump_syms.exe at $objdir/dist/host/bin/.
OK! then that's not the problem, at least! From the log:
 0:15.49 Finished processing c:\gecko\obj-i686-pc-mingw32\toolkit\library\xul.dll in 0.03s

...that is definitely not long enough to have done anything useful! Two questions:
1) Does c:\gecko\obj-i686-pc-mingw32\toolkit\library\xul.pdb exist? If not your build doesn't have debug symbols (unlikely).
2) Does running `c:/gecko/obj-i686-pc-mingw32/dist/host/bin/dump_syms.exe c:/gecko/obj-i686-pc-mingw32/toolkit/library/xul.dll` produce any useful output or an error message? It should produce a lot of output. If it errors the error message should be useful.
Interesting:


$ ./obj-i686-pc-mingw32/dist/host/bin/dump_syms.exe obj-i686-pc-mingw32/dist/bin/xul.dll
CoCreateInstance CLSID_DiaSource {E6756135-1E65-4D17-8576-610761398C3C} failed (msdia*.dll unregistered?)
Open failed
Huh. So somehow you have the DIA SDK installed, but the COM components aren't registered so it doesn't actually work. That's exciting! (Also buildsymbols really should error in this situation, that's a bummer.)

Try running `regsvr32 "c:/Program Files (x86)/Microsoft Visual Studio 14.0/DIA SDK/bin/msdia140.dll"` (assuming you have VS2017 installed) and see if that fixes things?
Had to become administrator, and needed to use this path instead (probably because I was using Community edition):

regsvr32 C\:/Program\ Files\ \(x86\)/Microsoft\ Visual\ Studio/2017/Community/DIA\ SDK/bin/msdia140.dll

But it worked!
I have a machine which is in the same state at the moment. It seems to happen if you had VS2015 installed at some point but then uninstalled it. There's some discussion in https://github.com/csoltenborn/GoogleTestAdapter/issues/124 which says that there are registry keys left in the registry that point to the old VS2015 locations for these DLLs, and that the lack of valid registry keys for the VS2017 paths is expected due to https://docs.microsoft.com/en-us/visualstudio/extensibility/breaking-changes-2017#change-reduce-registry-impact : "Visual Studio now uses Registration-Free Activation for COM components. [...] As a result, external code that relies on global COM registration for Visual Studio COM interfaces will no longer find these registrations."

Ted, do you know what we can do about this?
Flags: needinfo?(ted)
I do not, but this is unfortunate! We should at least fix symbolstore.py to error when dump_syms returns an error so that `mach buildsymbols` doesn't silently appear to succeed.
Flags: needinfo?(ted)
I was running into this and thought it'd take a swing at making symbolstore.py fail correctly. Also as a side note, the `regsvr32` command worked for me as well, but I had to point it to amd64\msdia140.dll because I was building 64bit.

I don't usually write python so any feedback is welcome, along with tests I should run (if any).
Attached patch symbolstore.patch (obsolete) — Splinter Review
Attachment #8965301 - Flags: review?(ted)
With this patch I get:
```
$ ./mach buildsymbols
 0:01.54 c:\mozilla-build\mozmake\mozmake.EXE -C . -j8 -s -w buildsymbols
 0:01.95 mozmake.EXE: Entering directory 'c:/src/firefox/obj-x86_64-pc-mingw32'
 0:53.03 mozmake.EXE[1]: Entering directory 'c:/src/firefox/obj-x86_64-pc-mingw32/toolkit/library/rust'
 0:53.03 force-cargo-library-build
 0:59.85 [m[m[32m[1m    Finished[m dev [optimized + debuginfo] target(s) in 0.4 secs
 0:59.90 mozmake.EXE[1]: Leaving directory 'c:/src/firefox/obj-x86_64-pc-mingw32/toolkit/library/rust'
 4:50.01 mozmake.EXE[1]: Entering directory 'c:/src/firefox/obj-x86_64-pc-mingw32/toolkit/library'
 4:50.35 mozmake.EXE[1]: Leaving directory 'c:/src/firefox/obj-x86_64-pc-mingw32/toolkit/library'
 4:53.98 mozmake.EXE[1]: Entering directory 'c:/src/firefox/obj-x86_64-pc-mingw32/toolkit/library'
 5:09.37 Beginning work for file: c:\src\firefox\obj-x86_64-pc-mingw32\toolkit\library\xul.dll
 5:09.37 Processing file: c:\src\firefox\obj-x86_64-pc-mingw32\toolkit\library\xul.dll
 5:09.37 c:\src\firefox\obj-x86_64-pc-mingw32\dist\host\bin\dump_syms.exe c:\src\firefox\obj-x86_64-pc-mingw32\toolkit\library\xul.dll
 5:09.37 Unexpected error: CoCreateInstance CLSID_DiaSource {E6756135-1E65-4D17-8576-610761398C3C} failed (msdia*.dll unregistered?)
 5:09.37
 5:09.37 Open failed
 5:09.37
 5:09.37
 5:09.37 Unexpected error: Command '['c:\\src\\firefox\\obj-x86_64-pc-mingw32\\dist\\host\\bin\\dump_syms.exe', 'c:\\src\\firefox\\obj-x86_64-pc-mingw32\\toolkit\\library\\xul.dll']' returned non-zero exit status 1
 5:09.37 Traceback (most recent call last):
 5:09.37   File "c:/src/firefox\toolkit\crashreporter\tools\symbolstore.py", line 912, in <module>
 5:09.37     main()
 5:09.38   File "c:/src/firefox\toolkit\crashreporter\tools\symbolstore.py", line 908, in main
 5:09.38     dumper.Process(args[2])
 5:09.38   File "c:/src/firefox\toolkit\crashreporter\tools\symbolstore.py", line 498, in Process
 5:09.38     self.ProcessFile(file_to_process)
 5:09.38   File "c:/src/firefox\toolkit\crashreporter\tools\symbolstore.py", line 512, in ProcessFile
 5:09.38     self.ProcessFileWork(file, arch_num, arch, vcs_root, dsymbundle)
 5:09.38   File "c:/src/firefox\toolkit\crashreporter\tools\symbolstore.py", line 608, in ProcessFileWork
 5:09.38     raise subprocess.CalledProcessError(proc.returncode, cmd, None)
 5:09.38 subprocess.CalledProcessError: Command '['c:\\src\\firefox\\obj-x86_64-pc-mingw32\\dist\\host\\bin\\dump_syms.exe', 'c:\\src\\firefox\\obj-x86_64-pc-mingw32\\toolkit\\library\\xul.dll']' returned non-zero exit status 1
 5:09.39 Running: c:/src/firefox/obj-x86_64-pc-mingw32/_virtualenv/Scripts/python.exe c:/src/firefox\toolkit\crashreporter\tools\symbolstore.py -c --vcs-info --install-manifest=c:/src/firefox/obj-x86_64-pc-mingw32\_build_manifests\install\dist_include,c:/src/firefox/obj-x86_64-pc-mingw32\dist\include -s c:/src/firefox c:/src/firefox/obj-x86_64-pc-mingw32\dist\host\bin\dump_syms.exe c:/src/firefox/obj-x86_64-pc-mingw32\dist\crashreporter-symbols c:\src\firefox\obj-x86_64-pc-mingw32\toolkit\library\xul.dll
 5:09.41 Traceback (most recent call last):
 5:09.41   File "c:\mozilla-build\python\Lib\runpy.py", line 174, in _run_module_as_main
 5:09.41     "__main__", fname, loader, pkg_name)
 5:09.41   File "c:\mozilla-build\python\Lib\runpy.py", line 72, in _run_code
 5:09.41     exec code in run_globals
 5:09.41   File "c:\src\firefox\python\mozbuild\mozbuild\action\dumpsymbols.py", line 79, in <module>
 5:09.41     sys.exit(main(sys.argv[1:]))
 5:09.41   File "c:\src\firefox\python\mozbuild\mozbuild\action\dumpsymbols.py", line 75, in main
 5:09.41     return dump_symbols(*argv)
 5:09.41   File "c:\src\firefox\python\mozbuild\mozbuild\action\dumpsymbols.py", line 64, in dump_symbols
 5:09.41     out_files = subprocess.check_output(args)
 5:09.41   File "c:\mozilla-build\python\Lib\subprocess.py", line 219, in check_output
 5:09.41     raise CalledProcessError(retcode, cmd, output=output)
 5:09.42 subprocess.CalledProcessError: Command '[u'c:/src/firefox/obj-x86_64-pc-mingw32/_virtualenv/Scripts/python.exe', u'c:/src/firefox\\toolkit\\crashreporter\\tools\\symbolstore.py', '-c', '--vcs-info', u'--install-manifest=c:/src/firefox/obj-x86_64-pc-mingw32\\_build_manifests\\install\\dist_include,c:/src/firefox/obj-x86_64-pc-mingw32\\dist\\include', '-s', u'c:/src/firefox', u'c:/src/firefox/obj-x86_64-pc-mingw32\\dist\\host\\bin\\dump_syms.exe', u'c:/src/firefox/obj-x86_64-pc-mingw32\\dist\\crashreporter-symbols', 'c:\\src\\firefox\\obj-x86_64-pc-mingw32\\toolkit\\library\\xul.dll']' returned non-zero exit status 1
 5:09.42 mozmake.EXE[1]: *** [c:/src/firefox/config/rules.mk:800: xul.dll_syms.track] Error 1
 5:09.42 mozmake.EXE[1]: Leaving directory 'c:/src/firefox/obj-x86_64-pc-mingw32/toolkit/library'
 5:09.42 mozmake.EXE: *** [c:/src/firefox/config/recurse.mk:73: toolkit/library/syms] Error 2
 5:09.42 mozmake.EXE: Leaving directory 'c:/src/firefox/obj-x86_64-pc-mingw32'
```

Which seems to be good output.
Comment on attachment 8965301 [details] [diff] [review]
symbolstore.patch

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

Thanks for the patch! This seems like a sensible approach, but I wonder if we can make things a bit clearer than they currently are.

Also if you feel up to it it would be great to add a test for this! There are a bunch of tests for this code already:
https://dxr.mozilla.org/mozilla-central/source/toolkit/crashreporter/tools/unit-symbolstore.py

Something similar to `testFileMapping` would probably work:
https://dxr.mozilla.org/mozilla-central/rev/62c2508f27a865dd0ac5ca3f0485cb20afafbbd0/toolkit/crashreporter/tools/unit-symbolstore.py#410

...but you'd want to set `mock_Popen.return_value.returncode = 1` or something like that, and you'd need to wrap the call to `Process` in a `with self.assertRaises(subprocess.CalledProcessError):` similar to what this test does:
https://dxr.mozilla.org/mozilla-central/rev/62c2508f27a865dd0ac5ca3f0485cb20afafbbd0/toolkit/crashreporter/tools/unit-symbolstore.py#371

::: toolkit/crashreporter/tools/symbolstore.py
@@ +523,5 @@
>          print("Processing file: %s" % file, file=sys.stderr)
>  
>          sourceFileStream = ''
>          code_id, code_file = None, None
>          try:

What if we moved this try down 3 lines to pull the `proc = ...` bit outside the try block, and then put the `proc.wait()` into a `finally:` block at the end?

@@ +604,5 @@
> +                proc.wait()
> +
> +            if proc.returncode != 0:
> +                print("Unexpected error: %s" % proc.stderr.read(), file=sys.stderr)
> +                raise subprocess.CalledProcessError(proc.returncode, cmd, None)

I don't know that manually creating a `CalledProcessError` is the right thing here, but considering nothing actually catches this it probably doesn't matter too much.
Attachment #8965301 - Flags: review?(ted)
Assignee: nobody → rhunt
Took a little bit of experimenting to figure out how python mock works, but I think I got the tests working now.
Attachment #8965301 - Attachment is obsolete: true
Attachment #8967430 - Flags: review?(ted)
Comment on attachment 8967430 [details] [diff] [review]
symbolstore.patch

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

Thanks!

::: toolkit/crashreporter/tools/symbolstore.py
@@ +531,1 @@
>              proc = subprocess.Popen(cmd, stdout=subprocess.PIPE,

I think that this line ought to be before the `try` block as well, but it's probably not that big of a deal.

@@ +532,5 @@
> +                                    stderr=subprocess.PIPE)
> +            try:
> +                module_line = proc.stdout.next()
> +            except StopIteration:
> +                module_line = ''

Do you need this change now or would the existing code have worked as-is?
Attachment #8967430 - Flags: review?(ted) → review+
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #16)
> Comment on attachment 8967430 [details] [diff] [review]
> symbolstore.patch
> 
> Review of attachment 8967430 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks!
> 
> ::: toolkit/crashreporter/tools/symbolstore.py
> @@ +531,1 @@
> >              proc = subprocess.Popen(cmd, stdout=subprocess.PIPE,
> 
> I think that this line ought to be before the `try` block as well, but it's
> probably not that big of a deal.
> 

Yes, that would make sense. I'll make that change.

> @@ +532,5 @@
> > +                                    stderr=subprocess.PIPE)
> > +            try:
> > +                module_line = proc.stdout.next()
> > +            except StopIteration:
> > +                module_line = ''
> 
> Do you need this change now or would the existing code have worked as-is?

No it would work as is, I'll change it back.
Pushed by rhunt@eqrion.net:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c06258f53c2c
Fail in symbolstore.py if dump_syms returns a non-zero exit code. r=ted
Backed out changeset c06258f53c2c (bug 1423666) for build bustage on OS X on a CLOSED TREE

Failure push: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=c06258f53c2c476ba35b51b7ab06b105f8d4102b&selectedJob=173511271

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=173511271&repo=mozilla-inbound&lineNumber=20011

Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/6fd88252e9c240b07e195493aefebee9953dd90a

[task 2018-04-13T14:16:50.346Z] 14:16:50     INFO -  Unexpected error:
[task 2018-04-13T14:16:50.346Z] 14:16:50     INFO -  Traceback (most recent call last):
[task 2018-04-13T14:16:50.347Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py", line 912, in <module>
[task 2018-04-13T14:16:50.348Z] 14:16:50     INFO -      main()
[task 2018-04-13T14:16:50.349Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py", line 908, in main
[task 2018-04-13T14:16:50.349Z] 14:16:50     INFO -      dumper.Process(args[2])
[task 2018-04-13T14:16:50.351Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py", line 498, in Process
[task 2018-04-13T14:16:50.351Z] 14:16:50     INFO -      self.ProcessFile(file_to_process)
[task 2018-04-13T14:16:50.351Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py", line 785, in ProcessFile
[task 2018-04-13T14:16:50.352Z] 14:16:50     INFO -      Dumper.ProcessFile(self, file, dsymbundle=dsymbundle)
[task 2018-04-13T14:16:50.352Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py", line 512, in ProcessFile
[task 2018-04-13T14:16:50.352Z] 14:16:50     INFO -      self.ProcessFileWork(file, arch_num, arch, vcs_root, dsymbundle)
[task 2018-04-13T14:16:50.353Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py", line 611, in ProcessFileWork
[task 2018-04-13T14:16:50.353Z] 14:16:50     INFO -      raise subprocess.CalledProcessError(proc.returncode, cmd, None)
[task 2018-04-13T14:16:50.353Z] 14:16:50     INFO -  subprocess.CalledProcessError: Command '['/builds/worker/workspace/build/src/obj-firefox/dist/host/bin/dump_syms', '-a', 'x86_64', '-g', '/builds/worker/workspace/build/src/obj-firefox/dom/plugins/ipc/interpose/libplugin_child_interpose.dylib.dSYM', '/builds/worker/workspace/build/src/obj-firefox/dom/plugins/ipc/interpose/libplugin_child_interpose.dylib']' returned non-zero exit status -11
[task 2018-04-13T14:16:50.354Z] 14:16:50     INFO -  Running: /builds/worker/workspace/build/src/obj-firefox/_virtualenv/bin/python /builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py -c -a x86_64 --vcs-info --install-manifest=/builds/worker/workspace/build/src/obj-firefox/_build_manifests/install/dist_include,/builds/worker/workspace/build/src/obj-firefox/dist/include -s /builds/worker/workspace/build/src /builds/worker/workspace/build/src/obj-firefox/dist/host/bin/dump_syms /builds/worker/workspace/build/src/obj-firefox/dist/crashreporter-symbols /builds/worker/workspace/build/src/obj-firefox/dom/plugins/ipc/interpose/libplugin_child_interpose.dylib
[task 2018-04-13T14:16:50.354Z] 14:16:50     INFO -  Traceback (most recent call last):
[task 2018-04-13T14:16:50.355Z] 14:16:50     INFO -    File "/usr/lib/python2.7/runpy.py", line 162, in _run_module_as_main
[task 2018-04-13T14:16:50.355Z] 14:16:50     INFO -      "__main__", fname, loader, pkg_name)
[task 2018-04-13T14:16:50.355Z] 14:16:50     INFO -    File "/usr/lib/python2.7/runpy.py", line 72, in _run_code
[task 2018-04-13T14:16:50.355Z] 14:16:50     INFO -      exec code in run_globals
[task 2018-04-13T14:16:50.356Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/python/mozbuild/mozbuild/action/dumpsymbols.py", line 79, in <module>
[task 2018-04-13T14:16:50.356Z] 14:16:50     INFO -      sys.exit(main(sys.argv[1:]))
[task 2018-04-13T14:16:50.356Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/python/mozbuild/mozbuild/action/dumpsymbols.py", line 75, in main
[task 2018-04-13T14:16:50.356Z] 14:16:50     INFO -      return dump_symbols(*argv)
[task 2018-04-13T14:16:50.357Z] 14:16:50     INFO -    File "/builds/worker/workspace/build/src/python/mozbuild/mozbuild/action/dumpsymbols.py", line 64, in dump_symbols
[task 2018-04-13T14:16:50.357Z] 14:16:50     INFO -      out_files = subprocess.check_output(args)
[task 2018-04-13T14:16:50.357Z] 14:16:50     INFO -    File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
[task 2018-04-13T14:16:50.358Z] 14:16:50     INFO -      raise CalledProcessError(retcode, cmd, output=output)
[task 2018-04-13T14:16:50.359Z] 14:16:50     INFO -  subprocess.CalledProcessError: Command '[u'/builds/worker/workspace/build/src/obj-firefox/_virtualenv/bin/python', u'/builds/worker/workspace/build/src/toolkit/crashreporter/tools/symbolstore.py', '-c', '-a', u'x86_64', '--vcs-info', u'--install-manifest=/builds/worker/workspace/build/src/obj-firefox/_build_manifests/install/dist_include,/builds/worker/workspace/build/src/obj-firefox/dist/include', '-s', u'/builds/worker/workspace/build/src', u'/builds/worker/workspace/build/src/obj-firefox/dist/host/bin/dump_syms', u'/builds/worker/workspace/build/src/obj-firefox/dist/crashreporter-symbols', '/builds/worker/workspace/build/src/obj-firefox/dom/plugins/ipc/interpose/libplugin_child_interpose.dylib']' returned non-zero exit status 1
[task 2018-04-13T14:16:50.359Z] 14:16:50     INFO -  /builds/worker/workspace/build/src/config/rules.mk:800: recipe for target 'libplugin_child_interpose.dylib_syms.track' failed
[task 2018-04-13T14:16:50.359Z] 14:16:50     INFO -  make[4]: *** [libplugin_child_interpose.dylib_syms.track] Error 1
[task 2018-04-13T14:16:50.359Z] 14:16:50     INFO -  make[4]: Leaving directory '/builds/worker/workspace/build/src/obj-firefox/dom/plugins/ipc/interpose'
[task 2018-04-13T14:16:50.359Z] 14:16:50     INFO -  /builds/worker/workspace/build/src/config/recurse.mk:73: recipe for target 'dom/plugins/ipc/interpose/syms' failed
[task 2018-04-13T14:16:50.360Z] 14:16:50     INFO -  make[3]: *** [dom/plugins/ipc/interpose/syms] Error 2
[task 2018-04-13T14:16:50.362Z] 14:16:50     INFO -  make[3]: *** Waiting for unfinished jobs....
[task 2018-04-13T14:16:50.362Z] 14:16:50     INFO -  make[4]: Entering directory '/builds/worker/workspace/build/src/obj-firefox/media/mtransport/test'
[task 2018-04-13T14:16:50.363Z] 14:16:50     INFO -  make[4]: Leaving directory '/builds/worker/workspace/build/src/obj-firefox/media/mtransport/test'
[task 2018-04-13T14:16:50.364Z] 14:16:50     INFO -  make[4]: Nothing to be done for 'syms'.
Flags: needinfo?(rhunt)
Interesting, it looks like dump_syms is returning exit code 11 on 'libplugin_child_interpose' on OSX. I have a mac, so I'll see if I can reproduce this issue.
Flags: needinfo?(rhunt)
Running ./mach buildsymbols works for me locally (OSX 10.12.6), but my build doesn't actually generate libplugin_child_interpose, and I'm not sure how to configure it to build...
You need to log in before you can comment on or make changes to this bug.