Closed Bug 976393 Opened 6 years ago Closed 6 years ago

Better logging of token server errors

Categories

(Firefox :: Sync, defect, P1)

defect

Tracking

()

RESOLVED FIXED
Firefox 30
Tracking Status
firefox29 + fixed
firefox30 + fixed

People

(Reporter: markh, Assigned: markh)

References

Details

Attachments

(1 file, 1 obsolete file)

Currently errors from the token server result in logs such as:

1392924838097   Sync.BrowserIDManager      ERROR Authentication error in _fetchTokenForUser: Client error.

Which isn't useful for diagnostics.

I'm attaching a "strawman" patch.  It has 2 parts:

* tokenserverclient - have the error objects implement a toString() method that includes everything relevant to the error.

* browserid_identity now has its AuthenticationError object be passed the initial error, and have its toString() also do the right thing.

The end result is errors in the log now look something like:

1393292203547	Sync.BrowserIDManager	ERROR	Authentication error in _fetchTokenForUser: AuthenticationError(TokenServerClientServerError({"message":"Server error.","cause":"general","response_body":"{\"uid\": 56882, \"hashalg\": \"sha256\", \"api_endpoint\": \"https://sync-1-us-east-1.sync.services.mozilla.com/1.5/56882\", \"key\": \"qEeha1YKpg4vtS3Lz81MHAHV8bQiWgd_kW1nZmNG8-4=\", \"duration\": 300, \"id\": \"eyJub2RlIjogImh0dHBzOi8vc3luYy0xLXVzLWVhc3QtMS5zeW5jLnNlcnZpY2VzLm1vemlsbGEuY29tIiwgImV4cGlyZXMiOiAxMzkzMjkyNDk2LjY2OTkzNTksICJzYWx0IjogIjRhMzJmMiIsICJ1aWQiOiA1Njg4Mn1TJXswMSgbkgP1P_nN_-78jq0cbwXN_i-QXqJTDmGNFg==\"}","response_headers":{"access-control-allow-credentials":"true","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","content-type":"application/json; charset=UTF-8","date":"Tue, 25 Feb 2014 01:36:36 GMT","server":"nginx/1.4.4","x-timestamp":"1393292196","content-length":"409","connection":"keep-alive"},"response_status":200}))

(Note the line above was done by instrumenting the code so a 200 response was actually treated as an error)

Another obvious alternative would be to ensure the tokenserverclient logs end up in the sync logs and just have them reported that way, but it's unclear that makes sense longer term (ie, when there are tokenserverclient consumers other than sync)

Anyway, casting a wide feedback net, and including Nick for any android-specific insights.
Attachment #8381066 - Flags: feedback?(nalexander)
Attachment #8381066 - Flags: feedback?(jparsons)
Attachment #8381066 - Flags: feedback?(ckarlof)
Comment on attachment 8381066 [details] [diff] [review]
0001-Bug-XXXXXX-ensure-authentication-errors-log-as-much-.patch

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

This would be a helpful and welcome improvement.

::: services/common/tokenserverclient.js
@@ +102,5 @@
> +TokenServerClientError.prototype._toStringFields = function() {
> +  let fields = {
> +    message: this.message,
> +    cause: this.cause,
> +  };

maybe add the current time in utc?
Attachment #8381066 - Flags: feedback?(jparsons) → feedback+
Comment on attachment 8381066 [details] [diff] [review]
0001-Bug-XXXXXX-ensure-authentication-errors-log-as-much-.patch

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

This is a great improvement to help us figure out what's causing some of the errors we're seeing.

::: services/common/tokenserverclient.js
@@ +54,5 @@
>  }
>  TokenServerClientNetworkError.prototype = new TokenServerClientError();
>  TokenServerClientNetworkError.prototype.constructor =
>    TokenServerClientNetworkError;
> +TokenServerClientError.prototype._toStringFields = function() {

Why is this TokenServerClientError.prototype? Should it be TokenServerClientNetworkError.prototype?
Attachment #8381066 - Flags: feedback?(ckarlof) → feedback+
(In reply to Jed Parsons (use needinfo, please) [:jedp, :jparsons] from comment #1)
> Comment on attachment 8381066 [details] [diff] [review]
> 0001-Bug-XXXXXX-ensure-authentication-errors-log-as-much-.patch

> maybe add the current time in utc?

Good idea - done.

(In reply to Chris Karlof [:ckarlof] from comment #2)
> Comment on attachment 8381066 [details] [diff] [review]

> Why is this TokenServerClientError.prototype? Should it be
> TokenServerClientNetworkError.prototype?

It should indeed, thanks.

Updated version - log entry looks like:

1393547241099	Sync.BrowserIDManager	ERROR	Background fetch for key bundle failed: AuthenticationError(TokenServerClientServerError({"now":"2014-02-28T00:27:21.097Z","message":"Server error.","cause":"general","response_body":"{\"uid\": 56880, \"hashalg\": \"sha256\", \"api_endpoint\": \"https://sync-1-us-east-1.sync.services.mozilla.com/1.5/56880\", \"key\": \"ITCp-3I6OIn9eEpMkAKL72-p74B26o9nh6QZYTPmqsE=\", \"duration\": 300, \"id\": \"eyJub2RlIjogImh0dHBzOi8vc3luYy0xLXVzLWVhc3QtMS5zeW5jLnNlcnZpY2VzLm1vemlsbGEuY29tIiwgImV4cGlyZXMiOiAxMzkzNTQ3NTMwLjY3NDY1NCwgInNhbHQiOiAiN2NkNjkwIiwgInVpZCI6IDU2ODgwfXFPo23H6FVfsMoyssyz25IVaEOjlEHetazFb4MXVKql\"}","response_headers":{"access-control-allow-credentials":"true","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","content-type":"application/json; charset=UTF-8","date":"Fri, 28 Feb 2014 00:27:10 GMT","server":"nginx/1.4.4","x-timestamp":"1393547230","content-length":"405","connection":"keep-alive"},"response_status":200}))
Attachment #8381066 - Attachment is obsolete: true
Attachment #8381066 - Flags: feedback?(nalexander)
Attachment #8383385 - Flags: review?(jparsons)
Comment on attachment 8383385 [details] [diff] [review]
0001-Bug-976393-ensure-authentication-errors-log-as-much-.patch

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

Looks good to me!  Thanks, Mark.
Attachment #8383385 - Flags: review?(jparsons) → review+
Priority: -- → P1
https://hg.mozilla.org/integration/fx-team/rev/6a9f8ca4c9b1
Assignee: nobody → mhammond
Status: NEW → ASSIGNED
https://hg.mozilla.org/mozilla-central/rev/6a9f8ca4c9b1
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 30
Comment on attachment 8383385 [details] [diff] [review]
0001-Bug-976393-ensure-authentication-errors-log-as-much-.patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): FxA sync
User impact if declined: This gives better diagnostics for reported sync errors 
Testing completed (on m-c, etc.): m-c
Risk to taking this patch (and alternatives if risky): Low
String or IDL/UUID changes made by this patch: None
Attachment #8383385 - Flags: approval-mozilla-aurora?
Attachment #8383385 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
QA Whiteboard: [qa-]
You need to log in before you can comment on or make changes to this bug.