1602573 - moz-phab producing excessive amount of unwanted output

Status: RESOLVED FIXED

(Conduit :: moz-phab, defect, P2)

Description

[Robin Steuber (they/them) [:bytesized]]

Attachment: mozphab_output.txt

I went to run moz-phab today, it took quite a while (I was submitting a couple of patches that touch a lot of files, so not unexpected). Once it had finished, I went back to the console window and saw that my entire scrollback was full of output from moz-phab. Clearly this is not desired behavior.

The command I ran seemed simple enough: moz-phab submit bookmark1 bookmark2

I'm posting two versions of the output I've seen. The first time I encountered this, I saw significantly longer output that included an entire section that I have not been able to replicate since. But the first time I encountered it, it went off the end of my scrollback, so that output is incomplete.

Note that both of these output files might seem short if you have word wrap turned off. But since the console wraps lines, they are overwhelmingly long in that context. Also of note is that there is a Python traceback in both versions of the output.

I'm running Windows 10. The patch stack I was submitting is attached to Bug 1585482.

Comment 1

[Robin Steuber (they/them) [:bytesized]]

Attachment: mozphab_output_original_cut_off_by_scrollback.txt

Comment 2

[Piotr Zalewa [:zalun]]

I can't confirm. It looks like it's printing everything. What is your MozPhab version? moz-phab version

Comment 3

[Robin Steuber (they/them) [:bytesized]]

> moz-phab version
MozPhab (0.1.65)

Comment 4

[Mitchell Hentges [:mhentges] 🦀]

(associated Slack conversation)

Comment 5

[:glob ✱]

The error is UnicodeEncodeError: 'charmap' codec can't encode characters in position 248871-248873: character maps to <undefined> which is triggered by logger.debug("%s %s" % (url.geturl(), api_call_args)).

The string formatting is applied regardless of the logging level, so any unicode weirdness in api_call_args would result in an error at this line.

Changing logging calls to be lazily evaluated, in this case logger.debug("%s %s", url.geturl(), api_call_args), would allow the code to continue past this statement (and probably fail later on, hopefully without dumping the entire JSON payload). pylint's W1201 rule catches this.

I suspect the core issue is a malformed unicode character (perhaps the source isn't UTF8 because Windows?).

Comment 6

[Piotr Zalewa [:zalun]]

Attachment: Bug 1602573 - Let logger format the string. r=mhentges

https://docs.python.org/3/howto/logging-cookbook.html#formatting-styles

Comment 7

[Piotr Zalewa [:zalun]]

Is the issue solved?
I will try to reproduce it tomorrow.

Comment 8

[Robin Steuber (they/them) [:bytesized]]

It seems to be solved. I'm no longer seeing the unexpected output.

Comment 9

[Robin Steuber (they/them) [:bytesized]]

Attachment: mozphab_output_part2.txt

Let me know if I should file a new bug for this, but it seemed to be related so I thought I would post it here. I got the attached output today, which was also unwanted.

Comment 10

[Robin Steuber (they/them) [:bytesized]]

Attachment: mozphab_output_part3.txt

Here's another instance of what looks like the same problem as last time.

Comment 11

[:glob ✱]

Traceback (most recent call last):
  File "c:\mozilla-build\python3\lib\logging\__init__.py", line 1028, in emit
    stream.write(msg + self.terminator)
  File "c:\mozilla-build\python3\lib\encodings\cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
UnicodeEncodeError: 'charmap' codec can't encode character '\u26a0' in position 97664: character maps to <undefined>

moz-phab is using cp1252 encoding when writing to the debug log file.

Comment 12

[:glob ✱]

Attachment: Bug 1602573 - Fix debug log file encoding on Windows; r=zalun

Comment 13

[:glob ✱]

https://github.com/mozilla-conduit/review/commit/f0ecf006433764bd60d92da8628d85a7cd4746cd