692386 - NS_ERROR_NET_RESET not preceded by requested URL

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P3)

Description

[:Atoll]

User reported that sync is broken.  Log shows lots of NS_ERROR_NET_RESET exceptions (for reasons that make sense due to production work right now).  Log does not show the HTTP request that triggered NS_ERROR_NET_RESET.  Please log said http request.

1317883051533	Sync.Service	DEBUG	User-Agent: Firefox/10.0a1 FxSync/1.12.0.20111005030932.
1317883051533	Sync.Service	INFO	Starting sync at 2011-10-06 01:37:31
1317883051534	Sync.SyncScheduler	DEBUG	Clearing sync triggers.
1317883051534	Sync.Service	INFO	In sync().
1317883082481	Sync.Service	DEBUG	Exception: NS_ERROR_NET_RESET JS Stack trace: Res_get()@resource.js:473 < _fetchInfo(...)@service.js:582 < ()@service.js:1318 < WrappedNotify()@util.js:148 < WrappedLock()@util.js:103 < _lockedSync()@service.js:1282 < ()@service.js:1273 < WrappedCatch()@util.js:77 < sync()@service.js:1261
1317883092626	Sync.SyncScheduler	DEBUG	Global Score threshold hit, triggering sync.
1317883092778	Sync.Service	DEBUG	User-Agent: Firefox/10.0a1 FxSync/1.12.0.20111005030932.
1317883092778	Sync.Service	INFO	Starting sync at 2011-10-06 01:38:12
1317883092778	Sync.SyncScheduler	DEBUG	Clearing sync triggers.
1317883092779	Sync.Service	INFO	In sync().
1317883101523	Sync.Resource	DEBUG	mesg: GET success 200 https://phx-sync317.services.mozilla.com/1.1/kwierso/info/collections
1317883101523	Sync.Resource	DEBUG	GET success 200 https://phx-sync317.services.mozilla.com/1.1/kwierso/info/collections
1317883101524	Sync.Service	DEBUG	Fetching global metadata record
1317883101524	Sync.Service	DEBUG	Weave Version: 1.12.0 Local Storage: 5 Remote Storage: 5
1317883101524	Sync.Service	INFO	Sync key is up-to-date: no need to upgrade.
1317883101524	Sync.Service	DEBUG	Fetching and verifying -- or generating -- symmetric keys.
1317883101524	Sync.Service	INFO	Testing info/collections: {"passwords":1317878540.6,"tabs":1317882776.17,"adblockplus":1317736518.24,"clients":1317881517.78,"crypto":1292021282.22,"forms":1317879918.8,"client":1309470557.51,"meta":1308266153.7,"key":1285352625.83,"bookmarks":1317588358.1,"prefs":1317528092.15,"history":1317882746.57}
1317883101524	Sync.CollectionKeys	INFO	Testing for updateNeeded. Last modified: 1292021282.22
1317883101524	Sync.Service	DEBUG	Refreshing client list.
1317883101525	Sync.Engine.Clients	INFO	0 outgoing items pre-reconciliation
1317883101525	Sync.Engine.Clients	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883101526	Sync.Service	INFO	Updating enabled engines: 7 clients.
1317883101526	Sync.Engine.Bookmarks	INFO	0 outgoing items pre-reconciliation
1317883101527	Sync.Engine.Bookmarks	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883101529	Sync.Engine.Forms	INFO	1 outgoing items pre-reconciliation
1317883101529	Sync.Engine.Forms	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883101532	Sync.Engine.Forms	INFO	Uploading all of 1 records
1317883101533	Sync.Collection	DEBUG	POST Length: 297
1317883111040	Sync.Collection	DEBUG	mesg: POST success 200 https://phx-sync317.services.mozilla.com/1.1/kwierso/storage/forms
1317883111040	Sync.Collection	DEBUG	POST success 200 https://phx-sync317.services.mozilla.com/1.1/kwierso/storage/forms
1317883111042	Sync.Engine.History	INFO	12 outgoing items pre-reconciliation
1317883111042	Sync.Engine.History	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883111056	Sync.Engine.History	INFO	Uploading all of 12 records
1317883111057	Sync.Collection	DEBUG	POST Length: 6223
1317883121147	Sync.ErrorHandler	DEBUG	Beginning user-triggered sync.
1317883121148	Sync.Service	DEBUG	User-Agent: Firefox/10.0a1 FxSync/1.12.0.20111005030932.
1317883121148	Sync.Service	INFO	Starting sync at 2011-10-06 01:38:41
1317883121148	Sync.Service	DEBUG	Exception: Could not acquire lock. Label: "service.js: sync". No traceback available
1317883121148	Sync.Service	INFO	Cannot start sync: already syncing?
1317883176466	Sync.ErrorHandler	DEBUG	history failed: NS_ERROR_NET_RESET JS Stack trace: Res_post()@resource.js:487 < (...)@engines.js:1112 < innerBind("all")@util.js:1071 < SyncEngine__uploadOutgoing()@engines.js:1160 < SyncEngine__sync()@engines.js:1211 < WrappedNotify()@util.js:148 < Engine_sync()@engines.js:517 < WeaveSvc__syncEngine([object Object])@service.js:1482 < ()@service.js:1375 < WrappedNotify()@util.js:148 < WrappedLock()@util.js:103 < _lockedSync()@service.js:1282 < ()@service.js:1273 < WrappedCatch()@util.js:77 < sync()@service.js:1261
1317883176466	Sync.Engine.Passwords	INFO	1 outgoing items pre-reconciliation
1317883176467	Sync.Engine.Passwords	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883176472	Sync.Engine.Passwords	INFO	Uploading all of 1 records
1317883176473	Sync.Collection	DEBUG	POST Length: 561
1317883209467	Sync.ErrorHandler	DEBUG	passwords failed: NS_ERROR_NET_RESET JS Stack trace: Res_post()@resource.js:487 < (...)@engines.js:1112 < innerBind("all")@util.js:1071 < SyncEngine__uploadOutgoing()@engines.js:1160 < SyncEngine__sync()@engines.js:1211 < WrappedNotify()@util.js:148 < Engine_sync()@engines.js:517 < WeaveSvc__syncEngine([object Object])@service.js:1482 < ()@service.js:1375 < WrappedNotify()@util.js:148 < WrappedLock()@util.js:103 < _lockedSync()@service.js:1282 < ()@service.js:1273 < WrappedCatch()@util.js:77 < sync()@service.js:1261
1317883209468	Sync.Engine.Prefs	INFO	0 outgoing items pre-reconciliation
1317883209468	Sync.Engine.Prefs	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883209469	Sync.Engine.Tabs	INFO	1 outgoing items pre-reconciliation
1317883209469	Sync.Engine.Tabs	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883209582	Sync.Engine.Tabs	INFO	Uploading all of 1 records
1317883209582	Sync.Collection	DEBUG	POST Length: 1848
1317883241501	Sync.ErrorHandler	DEBUG	tabs failed: NS_ERROR_NET_RESET JS Stack trace: Res_post()@resource.js:487 < (...)@engines.js:1112 < innerBind("all")@util.js:1071 < SyncEngine__uploadOutgoing()@engines.js:1160 < SyncEngine__sync()@engines.js:1211 < WrappedNotify()@util.js:148 < Engine_sync()@engines.js:517 < WeaveSvc__syncEngine([object Object])@service.js:1482 < ()@service.js:1375 < WrappedNotify()@util.js:148 < WrappedLock()@util.js:103 < _lockedSync()@service.js:1282 < ()@service.js:1273 < WrappedCatch()@util.js:77 < sync()@service.js:1261
1317883241501	Sync.Engine.AdblockPlus	INFO	0 outgoing items pre-reconciliation
1317883241502	Sync.Engine.AdblockPlus	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1317883241502	Sync.Service	INFO	Sync completed at 2011-10-06 01:40:41 after 148.72 secs.
1317883241502	Sync.ErrorHandler	DEBUG	Some engines did not sync correctly.

Comment 1

[Mark Hammond [:markh] [:mhammond]]

https://bbs.archlinux.org/viewtopic.php?id=197331 is a similar report google found for me.

Comment 2

[Mark Hammond [:markh] [:mhammond]]

Oops - sorry for the noise - I mis-read the intention of this bug (it's only to log the URL, not to try and solve the underlying error)

Comment 3

[arumugaabinesh]

Can I work on this issue?

Comment 4

[Mark Hammond [:markh] [:mhammond]]

(In reply to arumugaabinesh from comment #3)
> Can I work on this issue?

Yes. If you are unsure how to get started, you probably should join the mozilla IRC server's #sync channel and chat with some people there. Note that due to timezones you may need to wait some time for a reply though.

Comment 5

[Leni Kadali [:leni1] [GMT+3]]

Hello. Interested in solving this bug. How do I get started?

Comment 6

[Mark Hammond [:markh] [:mhammond]]

(In reply to Leni Kadali from comment #5)
> Hello. Interested in solving this bug. How do I get started?

Thanks for getting involved in Firefox!

You should make sure you've got a Firefox build up and running (see https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Introduction for more), then for this particular bug, the simplest answer is probably to ensure a this._log.warn call is made at http://searchfox.org/mozilla-central/rev/17ebac68112bd635b458e831670c1e506ebc17ad/services/sync/modules/resource.js#421, and ensure that log message includes the URL we were trying to fetch. To test, you should configure sync and ensure sync has run once, then disconnect your network and hit the "sync now" button - you should then see an error hit (although probably with some error other than NS_ERROR_NET_RESET, but that's OK). Once you've verified the log includes the URL, you can upload the patch, and we can take things from there!

Comment 7

[meghasharma4910]

Hey, I guess this bug hasn't been resolved yet. So, can I take it up?

Comment 8

[Mark Hammond [:markh] [:mhammond]]

(In reply to meghasharma4910 from comment #7)
> Hey, I guess this bug hasn't been resolved yet. So, can I take it up?

Yes, feel free - once you put a patch up (or tell us that you have one ready) we'll assign it to you. Please see the other comments above this for detailed instructions.

Comment 9

[meghasharma4910]

I've started working on the bug, though was facing some problems with the setup. I'll try to send the patch as soon as possible.

Comment 10

[Jeremy Lempereur [:o0ignition0o]]

Hey there :) I was wondering if someone is still working on this issue ? If not may I try to tackle it ? :)

Comment 11

[Jeremy Lempereur [:o0ignition0o]]

Ok I guess I'm almost there, but there's one last question I need to ask before submitting the patch : 

> 1514075983257	Sync.ErrorHandler	ERROR	Sync encountered an error: [Exception... "NS_ERROR_ABORT"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: resource://services-sync/resource.js :: Channel_onStopRequest :: line 425"  data: no] Stack trace: Channel_onStopRequest()@resource://services-sync/resource.js:425


It feels like even after I fiddled with the .js file a bit I still cannot see my changes. Is there any sort of js cache I'm supposed to disable somewhere? 

I tried to stop and ./mach run and ./mach build ... I must be missing a ./mach | yarn | grunt command or something :/

Comment 12

[Mark Hammond [:markh] [:mhammond]]

"./mach build" followed by "./mach run" certainly should pick up any changes to js files - what file are you editing, and what change did you make?

Comment 13

[Jeremy Lempereur [:o0ignition0o]]

As I tried to run hg diff to show you the patch I wanted to submit, I found out my repository was not up to date. After running hg pull -u I noticed the whole setup changed, and there's now a this._log.debug call https://searchfox.org/mozilla-central/source/services/common/rest.js#484 

I noticed something interesting while trying to reproduce the bug though : I synced my account, before turning my WiFi connection off, and I got two new messages : 

> 1514122896433	Sync.ErrorHandler	ERROR	Sync encountered an error: [Exception... "Abort"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "<unknown>"  data: no] No traceback available

and after I clicked on the "sync" button again I got : 

> 1514122926355	Sync.ErrorHandler	ERROR	Sync encountered an error: [Exception... "The lookup of the hostname failed"  nsresult: "0x804b001e (NS_ERROR_UNKNOWN_HOST)"  location: "<unknown>"  data: no] No traceback available


I'm trying to figure out how to log the request URLs, maybe it could prove useful ? 
As far as I understand it seems I need to log the URL right before a "weave:service:sync:error" event is dispatched.

Comment 14

[Jeremy Lempereur [:o0ignition0o]]

I think the logs are verbose enough in the _logResponse method : https://searchfox.org/mozilla-central/source/services/sync/modules/resource.js#219

Is there anything  I could do to improve the (already pretty neat) logging ? :)

Comment 15

[Mark Hammond [:markh] [:mhammond]]

(In reply to Jeremy Lempereur from comment #14)
> Is there anything  I could do to improve the (already pretty neat) logging ?
> :)

I had a bit of a play with this, and while it's difficult to test (because the network disconnected will prevent us getting to this code), I think a single line at https://searchfox.org/mozilla-central/rev/51cd1093c5c2113e7b041e8cc5c9bf2186abda13/services/sync/modules/resource.js#174, with, say:

      this._log.warn(`Request to ${this.uri.spec} failed`, e)

Should cause us to always log the URL when the request fails. As you mention, I think most other paths are fine, so this one line change should do it!

Thanks!

Comment 16

[Jeremy Lempereur [:o0ignition0o]]

Attachment: Bug 692386 - sync: Add missing requested URL on NS_ERROR_NET_RESET.

The requested URL was logged on almost each failing request exception.
Added a warn message to log the request method and url when any request fails.

Review commit: https://reviewboard.mozilla.org/r/209854/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/209854/

Comment 17

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8939520 [details]
Bug 692386 - sync: Add missing requested URL on NS_ERROR_NET_RESET.

https://reviewboard.mozilla.org/r/209854/#review215558

Awesome, thanks!

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2992db73415f
sync: Add missing requested URL on NS_ERROR_NET_RESET. r=markh

Comment 19

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/2992db73415f