685941 - resp.obj is null in prod PHX upload of tabs

Status: RESOLVED INCOMPLETE

(Cloud Services :: General, defect)

Description

[Richard Newman [:rnewman]]

1315591153584	Sync.Engine.Tabs	INFO	1 outgoing items pre-reconciliation
1315591153584	Sync.Engine.Tabs	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1315591153636	Sync.Engine.Tabs	INFO	Uploading all of 1 records
1315591153636	Sync.Collection	DEBUG	POST Length: 26724
1315591183125	Sync.Collection	DEBUG	mesg: POST success 200 https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
1315591183125	Sync.Collection	DEBUG	POST success 200 https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
1315591183126	Sync.Service	DEBUG	tabs failed: resp.obj is null JS Stack trace: ("all")@engines.js:1005 < innerBind("all")@util.js:1172 < SyncEngine__uploadOutgoing()@engines.js:1041 < SyncEngine__sync()@engines.js:1092 < WrappedNotify()@util.js:177 < Engine_sync()@engines.js:399 < WeaveSvc__syncEngine([object Object])@service.js:1598 < ()@service.js:1490 < WrappedNotify()@util.js:177 < WrappedLock()@util.js:132 < _lockedSync()@service.js:1397 < ()@service.js:1388 < WrappedCatch()@util.js:106 < sync()@service.js:1376

Timestamps translate to 

Fri Sep  9 10:59:13 PDT 2011

Comment 1

[Richard Newman [:rnewman]]

petef reports that non-empty body was returned, according to zeus logs. Filed two followups to avoid behaving like an idiot when we get bad bodies.

Comment 2

[Richard Newman [:rnewman]]

Got this this morning. Either hotel wifi or 4G tethered connection.

Timestamp is Sat Sep 17 11:16:11 PDT 2011.

1316283298752	Sync.Collection	DEBUG	POST Length: 26768
1316283371275	Sync.Collection	DEBUG	mesg: POST success 200 https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
1316283371275	Sync.Collection	DEBUG	POST success 200 https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
1316283371276	Sync.Service	DEBUG	tabs failed: resp.obj is null JS Stack trace: ("all")@engines.js:1005 < innerBind("all")@util.js:1172 < SyncEngine__uploadOutgoing()@engines.js:1041 < SyncEngine__sync()@engines.js:1092 < WrappedNotify()@util.js:177 < Engine_sync()@engines.js:399 < WeaveSvc__syncEngine([object Object])@service.js:1598 < ()@service.js:1490 < WrappedNotify()@util.js:177 < WrappedLock()@util.js:132 < _lockedSync()@service.js:1397 < ()@service.js:1388 < WrappedCatch()@util.js:106 < sync()@service.js:1376

Comment 3

[Richard Newman [:rnewman]]

Got this again just now.

1317278872519	Sync.Collection	DEBUG	mesg: POST success 200 https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
1317278872519	Sync.Collection	DEBUG	POST success 200 https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
1317278872519	Sync.Service	DEBUG	tabs failed: resp.obj is null JS Stack trace: ("all")@engines.js:1005 < innerBind("all")@util.js:1172 < SyncEngine__uploadOutgoing()@engines.js:1041 < SyncEngine__sync()@engines.js:1092 < WrappedNotify()@util.js:177 < Engine_sync()@engines.js:399 < WeaveSvc__syncEngine([object Object])@service.js:1598 < ()@service.js:1490 < WrappedNotify()@util.js:177 < WrappedLock()@util.js:132 < _lockedSync()@service.js:1397 < ()@service.js:1388 < WrappedCatch()@util.js:106 < sync()@service.js:1376

Stable wifi connection at home, during ordinary browsing.

Comment 4

[:Atoll]

(In reply to Richard Newman [:rnewman] from comment #3)
> Got this again just now.
> 
> 1317278872519	Sync.Collection	DEBUG	mesg: POST success 200
> https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
> 1317278872519	Sync.Collection	DEBUG	POST success 200
> https://phx-sync223.services.mozilla.com/1.1/holygoat/storage/tabs
> 1317278872519	Sync.Service	DEBUG	tabs failed: resp.obj is null JS Stack

PHX received 6 POST requests for /1.1/holygoat/storage/tabs between 2011-09-28 23:00 PST8PDT and 23:57.  The closest to the timestamp above was nearly a minute off.  All 6 of them replied with 200 OK, 278 bytes.

Can you run a debug build that writes the entire response object received including headers, so we can see if you're getting Content-Length: 0 or some sort of non-Zeus fake reply or something?

Comment 5

[Richard Newman [:rnewman]]

I suspect I've figured this out. Test fragment:

const DELAY_TIMEOUT = 500;
function server_delayed(request, response) {
  response.seizePower();
  response.write("HTTP/1.1 200 OK\r\n" +
                 "Content-Length: 100\r\n" +
                 "\r\n");
  
  Utils.namedTimer(function () {
    response.finish();
  },
  DELAY_TIMEOUT - 100,
  this,
  "_delayTimer");
}

...

  let res20 = new Resource("http://localhost:8080/delay");
  res20.ABORT_TIMEOUT = DELAY_TIMEOUT;
  error = undefined;
  try {
    content = res20.get();
  } catch (ex) {
    error = ex;
    _("Error is " + Utils.exceptionStr(ex));
  }
  do_check_true(!error);
  _("Status: "  + content.status);
  _("Success: " + content.success);
  _("Headers: " + JSON.stringify(content.headers));
  _("Content is " + JSON.stringify(content));
  do_check_eq(content.obj, null);

Prints:

1317627896288	Sync.Resource	DEBUG	mesg: GET success 200 http://localhost:8080/delay
1317627896288	Sync.Resource	DEBUG	GET success 200 http://localhost:8080/delay

TEST-PASS | /Users/rnewman/moz/hg/services-central/obj-ff-dbg/_tests/xpcshell/services/sync/tests/unit/test_resource.js | [run_test : 477] true == true
Status: 200
Success: true
Headers: {"content-length":"100"}
Content is "null"

TEST-PASS | /Users/rnewman/moz/hg/services-central/obj-ff-dbg/_tests/xpcshell/services/sync/tests/unit/test_resource.js | [run_test : 482] null == null


I believe this test simulates the behavior of a server writing the start of the response but never writing the body before the connection is finished (in this case, after 400msec). Note that the client sees a 200 with an empty body, which parses as null.

All pretty obvious.

If the client hits its timeout, an exception is thrown.

We have an open bug to check Content-Length against the response, which will cause an error to be raised elsewhere, but the real solution would be to not have headers be written when a connection will be terminated.

Comment 6

[Richard Newman [:rnewman]]

Fascinating:

1348498147088	Sync.Engine.Tabs	INFO	1 outgoing items pre-reconciliation
1348498147089	Sync.Engine.Tabs	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1348498147213	Sync.Engine.Tabs	INFO	Uploading all of 1 records
1348498147215	Sync.Collection	DEBUG	POST Length: 26980
1348498147361	Sync.Collection	DEBUG	mesg: POST success 200 https://phx-sync542.services.mozilla.com/1.1/holygoat/storage/tabs
1348498147361	Sync.Collection	DEBUG	POST success 200 https://phx-sync542.services.mozilla.com/1.1/holygoat/storage/tabs
1348498147362	Sync.Status	DEBUG	Status for engine tabs: error.engine.reason.unknown_fail
1348498147362	Sync.Status	DEBUG	Status.service: success.status_ok => error.sync.failed_partial
1348498147363	Sync.ErrorHandler	DEBUG	tabs failed: resp.obj.failed is not an object JS Stack trace: @engines.js:1200 < [e-mail]:477 < [e-mail]:1236 < [e-mail]:1286 < [e-mail]:142 < [e-mail]:481 < [e-mail]:1399 < [e-mail]:1292 < [e-mail]:142 < [e-mail]:97 < [e-mail]:1192 < @service.js:1183 < [e-mail]:71 < [e-mail]:1171
1348498147363	Sync.Service	INFO	Sync completed at 2012-09-24 07:49:07 after 16.06 secs.
1348498147363	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms.
1348498147364	Sync.ErrorHandler	DEBUG	Some engines did not sync correctly.

Comment 7

[Ryan Kelly [:rfkelly]]

This bug is all about ancient infrastructure that no longer exists, I don't think there's value in keeping it open.