1191825 - |TelemetryStorage.loadAbortedSession| should catch PingReadError

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P3)

Description

[Alessio Placitelli [:Dexter]]

|TelemetryStorage.loadPingFile| is no longer throwing OS.File exceptions, due to changes landed with bug 1187340. We throw PingReadError instead [1], bug |TelemetryStorage.loadAbortedSessionPing| was not updated [2], so an error is logged into the browser console if no aborted-session ping can be found at startup:

16:06:58.429 1438870018429	Toolkit.Telemetry	ERROR	TelemetryStorage::loadAbortedSessionPing - error removing ping: PingReadError JS Stack trace: [e-mail]:80:15 < TelemetryStorageImpl.loadPingFile<@TelemetryStorage.jsm:1445:131 Log.jsm:749:0

We should catch PingReadError in |loadAbortedSessionPing| at [2].

[1] - http://hg.mozilla.org/mozilla-central/annotate/22476236b3e1/toolkit/components/telemetry/TelemetryStorage.jsm#l1445
[2] - http://hg.mozilla.org/mozilla-central/annotate/22476236b3e1/toolkit/components/telemetry/TelemetryStorage.jsm#l1529

Comment 1

[Georg Fritzsche [:gfritzsche]]

(In reply to Alessio Placitelli [:Dexter - PTO Aug 10th-28th] from comment #0)
> |TelemetryStorage.loadPingFile| is no longer throwing OS.File exceptions,
> due to changes landed with bug 1187340. We throw PingReadError instead [1],
> bug |TelemetryStorage.loadAbortedSessionPing| was not updated [2], so an
> error is logged into the browser console if no aborted-session ping can be
> found at startup:
> 
> 16:06:58.429 1438870018429	Toolkit.Telemetry	ERROR
> TelemetryStorage::loadAbortedSessionPing - error removing ping:
> PingReadError JS Stack trace: [e-mail]:80:15 <
> TelemetryStorageImpl.loadPingFile<@TelemetryStorage.jsm:1445:131
> Log.jsm:749:0
> 
> We should catch PingReadError in |loadAbortedSessionPing| at [2].
> 
> [1] -
> http://hg.mozilla.org/mozilla-central/annotate/22476236b3e1/toolkit/
> components/telemetry/TelemetryStorage.jsm#l1445
> [2] -
> http://hg.mozilla.org/mozilla-central/annotate/22476236b3e1/toolkit/
> components/telemetry/TelemetryStorage.jsm#l1529

I propose we add a second argument to PingReadError, so we have PingReadError(message=..., becauseNoSuchFile=false) and add that as a property:
http://hg.mozilla.org/mozilla-central/annotate/22476236b3e1/toolkit/components/telemetry/TelemetryStorage.jsm#l78

Then we can change [1] to:
  throw new PingReadError(e.message, ex.becauseNoSuchFile);

And [2] should just work fine as it is now.

Lets change this to "removeAbortedSessionPing - error loading ping" while we're here:
http://hg.mozilla.org/mozilla-central/annotate/22476236b3e1/toolkit/components/telemetry/TelemetryStorage.jsm#l1532

Comment 2

[Georg Fritzsche [:gfritzsche]]

Robert, would you be interested in taking this?

Comment 3

[rthyberg]

yeah Ill start working on it

Comment 4

[rthyberg]

Attachment: updated_ping_read_error

Heres my first shot. When I used ex.becauseNoSuchFile it said that ex wasnt defined and was unable to catch the error so I used e.becauseNoSuchFile. Was that wrong?

Comment 5

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8653742 [details] [diff] [review]
updated_ping_read_error

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

Thanks, this looks good.

Can you test that it prints the error before the patch and the expected output after it?
You can turn on full Telemetry logging in about:config with:
* toolkit.telemetry.log.level, integer, 0
* toolkit.telemetry.log.dump, boolean, true

You need to properly quit Firefox (i.e. no crashes on closing it and no CTRL^C), then start it again.
60sec after startup, Telemetry fully initializes and tries to load that ping file.
If there was no crash, we should not find that file and then print the error (and after the patch the proper tracing).

::: toolkit/components/telemetry/TelemetryStorage.jsm
@@ +1536,5 @@
>        ping = yield this.loadPingFile(gAbortedSessionFilePath);
>      } catch (ex if ex.becauseNoSuchFile) {
>        this._log.trace("loadAbortedSessionPing - no such file");
>      } catch (ex) {
> +      this._log.error("removeAbortedSessionPing - error removing ping", ex)

This should be: "loadAbortedSessionPing - error loading ping"

Comment 6

[rthyberg]

Attachment: updated_ping_read_error

So I tried to test it but to be honest I really didnt understand. I didnt see a loadAbortedSession or any thrown execptions in the logs.

Comment 7

[Alessio Placitelli [:Dexter]]

(In reply to rthyberg from comment #6)
> So I tried to test it but to be honest I really didnt understand. I didnt
> see a loadAbortedSession or any thrown execptions in the logs.

You should have set MOZILLA_OFFICIAL and MOZ_TELEMETRY_REPORTING in your .mozconfig, otherwise Telemetry might behave differently from what you would expect (some behaviours are disabled without those flags).

I've manually tested your latest patch and it correctly prints "loadAbortedSessionPing - no such file" when no aborted-session ping is there.

Comment 9

[Georg Fritzsche [:gfritzsche]]

Robert, can you confirm that?

Comment 10

[rthyberg]

Sorry I didnt realise you were wating for me. And no I cant confirm it. I tried setting those ootions in my .mozconfig with "mk_add_option MOZILLA_OFFICAL=1" and "MOZ_TELEMETRY_REPORTING=1". Did I set this correctly because now I dont get any output like I was getting before.

Comment 11

[Alessio Placitelli [:Dexter]]

(In reply to rthyberg from comment #10)
> Sorry I didnt realise you were wating for me. And no I cant confirm it. I
> tried setting those ootions in my .mozconfig with "mk_add_option
> MOZILLA_OFFICAL=1" and "MOZ_TELEMETRY_REPORTING=1". Did I set this correctly
> because now I dont get any output like I was getting before.

I think you should add that section to the .mozconfig

# Telemetry Enabled Mozconfig
export MOZILLA_OFFICIAL=1
export MOZ_TELEMETRY_REPORTING=1

I won't work with mk_add_option.

Comment 12

[rthyberg]

ive done that and its still not working. Sorry this is kinda frustrating for me, can you share your mozconfig with me so we can move forward?

Comment 13

[Georg Fritzsche [:gfritzsche]]

Alessio, maybe you can make sure it works/fails as expected with and without the patch and then land this?

Sorry about the frustrations Robert, lets get moving forward here.
I'll be out for PTO in a bit but you can ask Alessio about anything thats unclear.

Comment 14

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8654008 [details] [diff] [review]
updated_ping_read_error

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

Thanks, this looks fine and simple enough, lets see that we can confirm it works and get it landed.

Lets make the message a bit more clearer, maybe "Bug 1191825 - Don't log errors if we can't find an aborted-session ping on disk."?

Comment 15

[Alessio Placitelli [:Dexter]]

As expected, w\o the patch applied the log contains the following line:

1441354155733   Toolkit.Telemetry       ERROR   TelemetryStorage::loadAbortedSessionPing - error removing ping: PingReadError JS Stack trac
: [e-mail]:80:15 < TelemetryStorageImpl.loadPingFile<@TelemetryStorage.jsm:1448:13
1441354155734   Toolkit.Telemetry       TRACE   TelemetryController::checkAbortedSessionPing - found aborted-session ping: false

With the patch applied:

441355277758   Toolkit.Telemetry       TRACE   TelemetryStorage::loadAbortedSessionPing - no such file
441355277758   Toolkit.Telemetry       TRACE   TelemetryController::checkAbortedSessionPing - found aborted-session ping: false

With an aborted-session ping available, the log prints, as expected:

1441355920233   Toolkit.Telemetry       TRACE   TelemetryController::checkAbortedSessionPing - found aborted-session ping: true

with or without the patch attached.

We can land this, as it works :-) My .mozconfig file only contains 

# Telemetry Enabled Mozconfig
export MOZILLA_OFFICIAL=1
export MOZ_TELEMETRY_REPORTING=1

rthyberg, could you only change the commit message to ""Bug 1191825 - Don't log errors if we can't find an aborted-session ping on disk. r=gfritzsche" and attach the new patch?

Thank you for your efforts and great work!

Comment 16

[rthyberg]

Attachment: updated_ping_read_error

Alright here we go.

Comment 17

[Alessio Placitelli [:Dexter]]

Great, thanks rthyberg!

Would you mind pushing your patch to Try as well so we can get this landed? For instructions on how to push to try, see [0].

If you need help with that, please don't hesitate to get in touch with me or drop by #introduction on Mozilla IRC.

[0] - https://wiki.mozilla.org/ReleaseEngineering/TryServer#Pushing_to_try

Comment 18

[rthyberg]

ya ill  do it tommorow as its pretty late here

Comment 19

[rthyberg]

 https://treeherder.mozilla.org/#/jobs?repo=try&revision=94b40d05a2c0

Comment 20

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/76ee6c1608fa

Comment 21

[Alessio Placitelli [:Dexter]]

Thanks rthyberg, I've pushed this to fx-team:  https://treeherder.mozilla.org/#/jobs?repo=fx-team&revision=76ee6c1608fa

Comment 22

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/76ee6c1608fa