1721471 - mach logs do not include stack traces

Reporter

Description

•

4 years ago

I ran into an exception logged by Glean and was surprised to not see a stack trace.

The output was just:

 0:43.51 Glean error

Upon investigation, our logging formatter does not emit stack traces. Commenting out some lines in python/mach/mach/logging.py:

diff --git a/python/mach/mach/logging.py b/python/mach/mach/logging.py
--- a/python/mach/mach/logging.py
+++ b/python/mach/mach/logging.py
@@ -218,35 +218,35 @@ class LoggingManager(object):
         self.json_handlers.append(handler)

     def add_terminal_logging(
         self, fh=sys.stdout, level=logging.INFO, write_interval=False, write_times=True
     ):
         """Enable logging to the terminal."""

         fh = _wrap_stdstream(fh)
-        formatter = StructuredHumanFormatter(
-            self.start_time, write_interval=write_interval, write_times=write_times
-        )
+        # formatter = StructuredHumanFormatter(
+        #     self.start_time, write_interval=write_interval, write_times=write_times
+        # )

-        if self.terminal:
-            formatter = StructuredTerminalFormatter(
-                self.start_time, write_interval=write_interval, write_times=write_times
-            )
-            formatter.set_terminal(self.terminal)
+        # if self.terminal:
+        #     formatter = StructuredTerminalFormatter(
+        #         self.start_time, write_interval=write_interval, write_times=write_times
+        #     )
+        #     formatter.set_terminal(self.terminal)

         handler = logging.StreamHandler(stream=fh)
-        handler.setFormatter(formatter)
+        # handler.setFormatter(formatter)
         handler.setLevel(level)

         for logger in self.structured_loggers:
             logger.addHandler(handler)

         self.terminal_handler = handler
-        self.terminal_formatter = formatter
+        # self.terminal_formatter = formatter

     def replace_terminal_handler(self, handler):
         """Replace the installed terminal handler.

         Returns the old handler or None if none was configured.
         If the new handler is None, removes any existing handler and disables
         logging to the terminal.
         """

and re-running the command that triggered the error resulted in a stack trace:

{msg}
Traceback (most recent call last):
  File "c:\Users\Barret\.mozbuild\_virtualenvs\mach\lib\site-packages\glean\_dispatcher.py", line 123, in _worker    
    task(*args, **kwargs)
  File "c:\Users\Barret\.mozbuild\_virtualenvs\mach\lib\site-packages\glean\metrics\boolean.py", line 63, in set     
    _ffi.lib.glean_boolean_set(self._handle, value)
TypeError: an integer is required

Ideally, we would include these stack traces in the output.

Beth Rennie [:beth] (she/her)

Reporter

Updated

•

4 years ago

Updated

•

4 years ago

Priority: -- → P2

Mitchell Hentges [:mhentges] 🦀

Comment 1

•

4 years ago

This is a little trickier to reproduce, but here's what I was able to do to re-trigger the problem:

Do the following on a Windows machine
Undo Barret's patch
Make a minimal Mach command (I like overwriting ./mach python) that has the following contents:

self.populate_logger()
self.log_manager.enable_unstructured()

export SSH_CLIENT=foo
./mach python

You should see the following output (probably with a different timestamp, of course):

 0:00.88 Glean error

To fix this, you'll need to dig into the logging to diagnose why the stack trace isn't being displayed, then determine an appropriate solution that won't regress other logging behaviour.

Alex Hochheiden [:ahochheiden] [he/him]

Assignee

Updated

•

4 years ago

Assignee: nobody → ahochheiden

Status: NEW → ASSIGNED

Mitchell Hentges [:mhentges] 🦀

Updated

•

4 years ago

Comment 2

•

4 years ago

Attached file Bug 1721471 - Added stack traces to Mach logs r?mhentges, g?firefox-build-system-reviewers — Details

The custom logging formatting functions that override the defaults were not
adding stack traces to the output. The logic for formatting the stack trace
output is pulled directly from the default, as noted by the function doc. The
only difference is prefixing the elapsed time to each line.

BugBot [:suhaib / :marco/ :calixte]

Comment 3

•

4 years ago

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:ahochheiden, could you have a look please?
For more information, please visit auto_nag documentation.

Flags: needinfo?(mhentges)

Flags: needinfo?(ahochheiden)

Mitchell Hentges [:mhentges] 🦀

Comment 4

•

4 years ago

Landed now.

Flags: needinfo?(mhentges)

Flags: needinfo?(ahochheiden)

Pulsebot

Comment 5

•

4 years ago

Pushed by mhentges@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/55ad44aa4244 Added stack traces to Mach logs r=mhentges, g?firefox-build-system-reviewers

Natalia Csoregi [:nataliaCs]

Comment 6

•

4 years ago

Backed out for causing mach failures on test_logger.py

[task 2021-11-22T16:17:24.779Z]  0:09.53 ============================= test session starts ==============================
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 platform darwin -- Python 3.7.9, pytest-3.6.2, py-1.11.0, pluggy-0.6.0 -- /opt/worker/tasks/task_163758638439890/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 rootdir: /opt/worker/tasks/task_163758638439890/checkouts/gecko, inifile: /opt/worker/tasks/task_163758638439890/checkouts/gecko/config/mozunit/mozunit/pytest.ini
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 collecting ... collected 1 item
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 python/mach/mach/test/test_logger.py::TestStructuredHumanFormatter::test_non_ascii_logging TEST-UNEXPECTED-FAIL
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.779Z]  0:09.53 =================================== FAILURES ===================================
[task 2021-11-22T16:17:24.779Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.780Z]  0:09.53 _____________ TestStructuredHumanFormatter.test_non_ascii_logging ______________
[task 2021-11-22T16:17:24.780Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.780Z]  0:09.53 
[task 2021-11-22T16:17:24.780Z]  0:09.53  0:09.53 
[task 2021-11-22T16:17:24.780Z]  0:09.54 self = <mach.test.test_logger.TestStructuredHumanFormatter testMethod=test_non_ascii_logging>
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54     def test_non_ascii_logging(self):
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         # Ensures the formatter doesn't choke when non-ASCII characters are
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         # present in printed parameters.
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         formatter = StructuredHumanFormatter(time.time())
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         def on_record(record):
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54             result = formatter.format(record)
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54             relevant = result[9:]
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54             self.assertEqual(relevant, "Test: s\xe9curit\xe9")
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         logger = DummyLogger(on_record)
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         value = "s\xe9curit\xe9"
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54         logger.log(
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.780Z]  0:09.54             logging.INFO,
[task 2021-11-22T16:17:24.780Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54             "Test: {utf}",
[task 2021-11-22T16:17:24.781Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54 >           extra={"action": "action", "params": {"utf": value}},
[task 2021-11-22T16:17:24.781Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54         )
[task 2021-11-22T16:17:24.781Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54 python/mach/mach/test/test_logger.py:45:
[task 2021-11-22T16:17:24.781Z]  0:09.54  0:09.54 
[task 2021-11-22T16:17:24.781Z]  0:09.54 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

Flags: needinfo?(ahochheiden)

Alex Hochheiden [:ahochheiden] [he/him]

Assignee

Comment 7

•

4 years ago

Latest revision should resolve the failure in TestStructuredHumanFormatter.test_non_ascii_logging.

Flags: needinfo?(ahochheiden)

Pulsebot

Comment 8

•

4 years ago

Pushed by mhentges@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d40c13189ef7 Added stack traces to Mach logs r=mhentges, g?firefox-build-system-reviewers

Dão Gottwald [:dao]

Updated

•

4 years ago

Regressions: 1744665

Andreea Pavel [:apavel]

Comment 9

•

4 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/d40c13189ef7

Status: ASSIGNED → RESOLVED

Closed: 4 years ago

status-firefox97: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 97 Branch

:Gijs (he/him)

Updated

•

4 years ago

Depends on: 1744702

Bugzilla

mach logs do not include stack traces

Categories

(Firefox Build System :: Mach Core, defect, P2)

Tracking

(firefox97 fixed)

People

(Reporter: beth, Assigned: ahochheiden)

References

(Depends on 1 open bug)

Details

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Updated

Updated

Comment 1

Updated

Updated

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Updated

Comment 9

Updated

Attachment

General

Description

File Name

Content Type