694162 - Better logging for line-by-line processing of records

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Richard Newman [:rnewman]]

Log byte count processed so far, number of records processed so far, and ...?

Comment 1

[:Atoll]

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.

Comment 2

[Bhagya]

I would like to work on this bug. Can I be assigned to it?

Comment 3

[Patrick]

Hi can you please provide me with the source code file so I can work on this bug. Thanks

Comment 4

[Hamel Joshi]

Hi there,

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

Thanks

Comment 5

[Daksh Anand]

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

Comment 6

[Richard Newman [:rnewman]]

Fancy mentoring this one, Kit?

Comment 7

[Lina Butler [:lina]]

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!

Comment 8

[George Veneel Dogga [::TheLayman]]

Hi kit, Can I work on this?

Comment 9

[Lina Butler [:lina]]

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!

Comment 10

[Daksh Anand]

Yeah I am sorry, I am a bit busy in something else right now. you can assign it to george.

Comment 11

[Lina Butler [:lina]]

Cool, thanks for the update! George, assigning this to you, if you're still interested.

Comment 12

[Lina Butler [:lina]]

George, are you still working on this? It's OK if not; let me know and I'll un-assign you. Thanks!

Comment 13

[George Veneel Dogga [::TheLayman]]

Hey kit, I'm currently busy in academics.

Comment 14

[Lina Butler [:lina]]

Mayank is working on this.

Comment 15

[Mayank [:mayank]]

Attachment: Bug-694162.patch

Attaching patch. Please review
Thanks

Comment 16

[Lina Butler [:lina]]

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!)

Comment 17

[Mayank [:mayank]]

Attachment: Bug-694162.patch

Attaching the modified patch. Please review.
Thanks

Comment 18

[Lina Butler [:lina]]

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

Comment 19

[Lina Butler [:lina]]

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`.

Comment 20

[Mayank [:mayank]]

Attachment: Bug-694162.patch

Attaching modified patch. Please review
Thanks

Comment 21

[Lina Butler [:lina]]

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

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/49ac21ebc141
Add logging for sync records. r=kit

Comment 23

[Mayank [:mayank]]

(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!

Comment 24

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/49ac21ebc141