Better logging for line-by-line processing of records

RESOLVED FIXED in Firefox 54

Status

()

defect
RESOLVED FIXED
8 years ago
3 years ago

People

(Reporter: rnewman, Assigned: mayank, Mentored)

Tracking

unspecified
Firefox 54
Points:
---

Firefox Tracking Flags

(firefox54 fixed)

Details

(Whiteboard: [good first bug][lang=js])

Attachments

(1 attachment, 2 obsolete attachments)

Log byte count processed so far, number of records processed so far, and ...?
byte position of the processing error is useful.

content-length header value, if available, is useful.

"are there other bytes following this parse error" is something we'd really like to know with the " \r" debug log.  can probably discern that from the previous two ideas.
Whiteboard: [good first bug]
Whiteboard: [good first bug] → [good first bug][lang=js][mentor=rnewman]
I would like to work on this bug. Can I be assigned to it?
Mentor: rnewman
Whiteboard: [good first bug][lang=js][mentor=rnewman] → [good first bug][lang=js]
Hi can you please provide me with the source code file so I can work on this bug. Thanks
Hi there,

I would like to work on this bug item if possible.

Thanks
Hi, I'm interested in trying to correct this bug and start my open source contribution with this bug. Can someone please specify the steps to follow as I am new to this? I have already setup Mozzila central for ubuntu but don't where to look in the code base to correct this error
Flags: needinfo?(rnewman)
Fancy mentoring this one, Kit?
Mentor: rnewman → kit
Flags: needinfo?(rnewman) → needinfo?(kit)
Thanks for taking this on, Daksh! From your comment, it sounds like you've already built Firefox, so let's get started.

Sync downloads new records from the server in a newline-delimited format. There are several layers that handle this, but this is the function that handles record processing, so that's where you'll want to add the logging: http://searchfox.org/mozilla-central/rev/3f614bdf91a2379a3e2c822da84e524f5e742121/services/sync/modules/record.js#786-798. It looks like the `Collection` class doesn't have a logger yet, but it's pretty easy to add; check out `RecordManager` in that file for an example of how it does logging.

For logging the content length of the response, you'll need to have access to the channel (http://searchfox.org/mozilla-central/rev/0aed9484bd3e97206fd1949ee4a4992ef300a81f/netwerk/protocol/http/nsIHttpChannel.idl#313). Looks like that's not currently passed to `_onProgress`, so you'll want to pass it in here: http://searchfox.org/mozilla-central/rev/3f614bdf91a2379a3e2c822da84e524f5e742121/services/sync/modules/resource.js#524,544 There's also an `X-Weave-Records` response header that might be useful to log.

I don't think this will need any new tests; you'll just want to make sure the existing tests pass. :-) `./mach xpcshell-test services/sync/tests/unit/test_records_*.js services/sync/tests/unit/test_resource_*.js` should be enough for a quick check, and, if those pass, you can run the full `services/sync` test suite to make sure.

Does that help? Please flag me if you have any questions, or find me on IRC!
Assignee: nobody → daksh.anand
Component: Firefox Sync: Backend → Sync
Flags: needinfo?(kit)
Product: Cloud Services → Firefox
Hi kit, Can I work on this?
I think Daksh is already working on this. Daksh, if you're stuck, is there anything I can do to help? If you don't have time to work on this, or if you'd like to work on a different bug, no problem; please let me know so that I can reassign this one to George. Thanks!
Flags: needinfo?(daksh.anand)
Yeah I am sorry, I am a bit busy in something else right now. you can assign it to george.
Cool, thanks for the update! George, assigning this to you, if you're still interested.
Assignee: daksh.anand → georgeveneeldogga
Status: NEW → ASSIGNED
Flags: needinfo?(daksh.anand)
George, are you still working on this? It's OK if not; let me know and I'll un-assign you. Thanks!
Flags: needinfo?(georgeveneeldogga)
Hey kit, I'm currently busy in academics.
Assignee: georgeveneeldogga → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(georgeveneeldogga)
Mayank is working on this.
Assignee: nobody → mayanksri18
Posted patch Bug-694162.patch (obsolete) — Splinter Review
Attaching patch. Please review
Thanks
Attachment #8836801 - Flags: review?(kit)
Comment on attachment 8836801 [details] [diff] [review]
Bug-694162.patch

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

Good start, thanks for working on this!

::: services/sync/modules/record.js
@@ +600,4 @@
>    // Used for batch download operations -- note that this is explicitly an
>    // opaque value and not (necessarily) a number.
>    this._offset = null;
> +  this._log = Log.repository.getLogger(this._logName);

It looks like `Collection` inherits from `Resource`, which already has a logger. Let's take this out.

@@ +787,5 @@
> +    this._onProgress = function(httpChannel) {
> +      let newline, length = 0;
> +
> +      // Content-Length of the value of this response header
> +      let contentLength = httpChannel.getResponseHeader('Content-Length');

I *think* `getResponseHeader` can throw if the header is missing. To be safe, let's put the call in a `try...catch`, and use a default value for logging if it's missing.

@@ +795,5 @@
>          let json = this._data.slice(0, newline);
>          this._data = this._data.slice(newline + 1);
>  
> +        // Add the json length for this record
> +        length += json.length;

Let's log the length and content length below this line, instead of at the end of the loop. It's possible for a chunk to include multiple records, so logging here will do what we want in that case.

@@ +802,5 @@
>          let record = new coll._recordObj();
>          record.deserialize(json);
>          coll._onRecord(record);
>        }
> +      this.log.trace("Record: Content-Length = " + contentLength +

`this._log`; the test will fail as written. (`mach test services/sync/tests/unit/test_telemetry.js` is usually a good check. That runs several syncs, and it's a lot faster than running the entire Sync test suite!)
Attachment #8836801 - Flags: review?(kit) → feedback+
Posted patch Bug-694162.patch (obsolete) — Splinter Review
Attaching the modified patch. Please review.
Thanks
Attachment #8837249 - Flags: review?(kit)
Comment on attachment 8837249 [details] [diff] [review]
Bug-694162.patch

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

Looks great, thanks! If try is happy, I'm happy: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b130093070f2cb604967e320b0533d55acdb79fa
Attachment #8837249 - Flags: review?(kit) → review+
Comment on attachment 8837249 [details] [diff] [review]
Bug-694162.patch

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

I see a couple of failures on try. Fix those up, make sure the tests pass, and then this should be ready to land! \o/ Thanks again for your work.

::: services/sync/modules/record.js
@@ +786,5 @@
> +    this._onProgress = function(httpChannel) {
> +      let newline, length = 0, contentLength = "unknown";
> +      try {
> +          // Content-Length of the value of this response header
> +          contentLength = httpChannel.getResponseHeader('Content-Length');

Double-quoted strings, please, so that ESLint doesn't complain.

@@ +795,5 @@
>          let json = this._data.slice(0, newline);
>          this._data = this._data.slice(newline + 1);
>  
> +        length += json.length;
> +        this._log.trace("Record: Content-Length = " + contentLength +

I think the `this` value is wrong here. We probably want `coll._log`.
Attachment #8837249 - Flags: review+
Attaching modified patch. Please review
Thanks
Attachment #8838632 - Flags: review?(kit)
Comment on attachment 8838632 [details] [diff] [review]
Bug-694162.patch

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

Looks great, and try is happy: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c0e2daaf68f95591485ed8ed4deadc93059bc3b8
Attachment #8838632 - Flags: review?(kit) → review+
Attachment #8836801 - Attachment is obsolete: true
Attachment #8837249 - Attachment is obsolete: true
(In reply to Kit Cambridge [:kitcambridge] from comment #21)
> Comment on attachment 8838632 [details] [diff] [review]
> Bug-694162.patch
> 
> Review of attachment 8838632 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks great, and try is happy:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=c0e2daaf68f95591485ed8ed4deadc93059bc3b8

Thanks Kit!
https://hg.mozilla.org/mozilla-central/rev/49ac21ebc141
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 54
You need to log in before you can comment on or make changes to this bug.