1768961 - shutdown logging from pingsender: "pingsender: sending [...] to https://incoming.telemetry.mozilla.org/[...]", and several "You are running in background task mode" and "You are running in headless mode."

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P2)

Description

[Daniel Holbert [:dholbert]]

STR that reliably reproduce this on one of my machines at least (Microsoft Surface 3 running Ubuntu 22.04):

1. Start Firefox Nightly from the terminal with a fresh profile, e.g. like so (using an empty directory /tmp/foo2 in this case to store the profile):

$ mkdir /tmp/foo2; firefox  -no-remote -profile /tmp/foo2

2. After a few seconds, quit Firefox (by e.g. closing both first-run tabs, via Ctrl+W)

ACTUAL RESULTS:
This logging appears in my terminal:

*** You are running in background task mode. ***
*** You are running in headless mode.
*** You are running in background task mode. ***
*** You are running in headless mode.
console.log: "pingsender: sending /tmp/foo2/saved-telemetry-pings/eeb82679-3f38-444f-918e-03c2be3cb922 to https://incoming.telemetry.mozilla.org/submit/telemetry/eeb82679-3f38-444f-918e-03c2be3cb922/new-profile/Firefox/102.0a1/nightly/20220511094252?v=4"
*** You are running in background task mode. ***
*** You are running in headless mode.
console.log: "pingsender: sending /tmp/foo2/saved-telemetry-pings/d9ebee13-e91a-4230-aa8a-4703c9853c05 to https://incoming.telemetry.mozilla.org/submit/telemetry/d9ebee13-e91a-4230-aa8a-4703c9853c05/event/Firefox/102.0a1/nightly/20220511094252?v=4"
*** You are running in background task mode. ***
*** You are running in headless mode.
console.log: "pingsender: sending /tmp/foo2/saved-telemetry-pings/1dba969a-6cac-4a68-9859-b2845535ff73 to https://incoming.telemetry.mozilla.org/submit/telemetry/1dba969a-6cac-4a68-9859-b2845535ff73/health/Firefox/102.0a1/nightly/20220511094252?v=4"
console.log: "pingsender: sending /tmp/foo2/saved-telemetry-pings/a725d1c1-57a6-4cc7-917c-b6f65d745ae5 to https://incoming.telemetry.mozilla.org/submit/telemetry/a725d1c1-57a6-4cc7-917c-b6f65d745ae5/first-shutdown/Firefox/102.0a1/nightly/20220511094252?v=4"

EXPECTED RESULTS:
No such logging.

Given the mention of pingsender in the logging, I'm assuming this is fallout from bug 1746983.

Comment 1

[Daniel Holbert [:dholbert]]

Note that the console.log logging arrives "late" / asynchronously, so it often prints after my next terminal prompt (as if it were part of my next manually-entered command, but of course it's not; it's just logging). This makes this log-spew a bit more annoying than it otherwise would be.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1746983

Comment 3

[Nick Alexander :nalexander [he/him] (PTO Feb 24-March 3)]

Mmm. It's not clear that this logging serves much purpose, so I think launching with output redirect to /dev/null or its equivalent makes the most sense. I imagine that old-style pingsender does not console logging at all so we never saw this.

I'll investigate.

Comment 4

[Pascal Chevrel:pascalc]

Nick, is that still an issue?

Comment 5

[Nick Alexander :nalexander [he/him] (PTO Feb 24-March 3)]

(In reply to Pascal Chevrel:pascalc from comment #4)

Nick, is that still an issue?

No: we backed out pingsender2 for other issues, namely https://bugzilla.mozilla.org/show_bug.cgi?id=1770473. But it will be when we go to reland.

I took a look at silencing these messages and nsIProcess, which invokes the external binary, does not support redirecting its output. That means that addressing this globally will be challenging. I can think of two possible solutions:

1. Cover-up the issue locally. Mute the single pingsender log line, and then either remove the *** lines or make them conditional on the background task name. Ugly, but probably solves the problem.
2. Cover-up the issue globally. Close output console/handles conditional on the background task name. Ugly in a different way.

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:chutten, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 7

[Pascal Chevrel:pascalc]

Setting 102 as unaffected as the regressor was backed out

Comment 8

[Donal Meehan [:dmeehan]]

Setting 103 as unaffected, regressor was backed out from central

Comment 9

[Nick Alexander :nalexander [he/him] (PTO Feb 24-March 3)]

Kagami: I just realized that the background tasks runner invocation is not based on nsIProcess but instead on some Chromium process launching code (see https://bugzilla.mozilla.org/show_bug.cgi?id=1791675). Two questions:

1. do you think this detached issue might impact the existing launches of pingsender.exe at shutdown around TelemetrySendImpl.runPingSender?

2. it rather looks like LaunchApp might be able to close stdout/stderr (equivalently, redirect to /dev/null?). If so, I could address this issue in a more pleasant manner. Is that true?

Comment 10

[Kagami Rosylight [:saschanaz] (they/them)]

(In reply to Nick Alexander :nalexander [he/him] from comment #9)

1. do you think this detached issue might impact the existing launches of pingsender.exe at shutdown around TelemetrySendImpl.runPingSender?

Assuming "this detached issue" means the title of bug 1791675, it depends. The detached issue happens when it runs with --wait-for-browser since then it tries to shutdown every related processes together with the main process (via Windows Job.)

It shouldn't matter in non-test environment without that flag, but if you have any tests that run pingsender at shutdown then yes it matters, on Windows.

2. it rather looks like LaunchApp might be able to close stdout/stderr (equivalently, redirect to /dev/null?). If so, I could address this issue in a more pleasant manner. Is that true?

I'm not familiar with that part, maybe ping :jld?

Comment 11

[Nick Alexander :nalexander [he/him] (PTO Feb 24-March 3)]

Attachment: Bug 1768961 - Avoid logging from pingsender. r?nrishel

The main reason to do this is to avoid polluting developer's terminals
after Firefox exits; regular users shouldn't see pingsender
logging at all.

It's not technically difficult to actually launch with null stdout and
stderr, but it is quite onerous: we have at least two ways to launch
processes (LaunchApp and nsIProcess), with platform specific
differences and implementation specific options. This approach is at
least brief and easy to understand.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ee9c07675ca1
Avoid logging from pingsender. r=nrishel

Comment 13

[Norisz Fay [:noriszfay]]

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