Quoting Ryan Kelly <[email protected]>:
"publicUrl": "https://fxa.example.com:9900";
This had no noticeable effect :(
The server should logs its config at startup, can you check in the log
to make sure the configured value is being picked up correctly?
Oh, smack my mouth and call me Clyde, I typo'd it as "publicURL"
before. Sorry for the boob.
Having corrected this I'm getting through verification/signup okay as
far as I can tell, so that's encouraging.
However, it now looks like syncserver is not happy: it's throwing a
503 on the first post-verification connection attempt. This is true
whether behind Apache, or running directly (as in the below output).
hazel syncserver # make serve
./local/bin/pserve ./syncserver.ini
/usr/local/src/syncserver/local/lib/python2.7/site-packages/tokenserver/verifiers.py:47: FutureWarning: The BrowserID certificate format has not been finalized and may change in backwards-incompatible ways. If you find that the latest version of this module cannot verify a valid BrowserID assertion, please contact the
author.
super(LocalVerifier, self).__init__(**kwargs)
Starting server in PID 6098.
serving on 0.0.0.0:5000 view at http://127.0.0.1:5000
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS
connection (1): fxa.example.com
INFO:mozsvc.metrics:{"code": 503, "request_time": 0.04334402084350586,
"remoteAddressChain": ["192.168.2.7"], "agent": "Mozilla/5.0 (X11;
Linux x86_64; rv:37.0) Gecko/20100101 Firefox/37.0",
"token.assertion.connection_error": 1,
"token.assertion.verify_failure": 1, "tokenserver.assertion.verify":
0.03910994529724121, "path":
"http://fxa.example.com:5000/token/1.0/sync/1.5";, "method": "GET"}
Something I'm not clear on: how does one configure the standalone dev
syncserver (non-proxied) to use HTTP or HTTPS; does it simply read the
scheme from the public_url key? Is the browser actually trying to
make a HTTPS connection, based on the above?
Also, is this the same URL that you configure in the content-server
settings, and that you enter as identity.fxaccounts.auth.uri in
about:config?
Not quite: the identity.fxaccounts.auth.uri value in client is
https://fxa.example.com:9900/v1
The other configs don't have the /v1 appended. Scheme, domain and
port match up though.
Would it help to switch to the mysql backend so I could snoop the data?
This may be worthwhile, if nothing else it will mean that you can edit
your account data after initial creation.
I've been able to build and run the
fxa-auth-db-mysql package, but I'm not clear on how to make
fxa-auth-server use it.
IIRC you just run fxa-auth-db-mysql as a separate (internal-only) HTTP
server, and ensure that the fxa-auth-server is talking to it via config
options.
This bit is very unclear at the moment, documentation-wise, and
config.js doesn't provide much in the way of clues either. However I
now grok that it's just a case of having the fxa-auth-db-mysql server
running before fxa-auth-server starts. I previously assumed that this
wouldn't work without further (undocumented) config, as
fxa-auth-server issues an EADDRINUSE error when it starts under these
circumstances; but I now see that this isn't fatal and works fine, and
the mysql db is now getting populated. Progress!
Are there any about:config entries on the client that I can twiddle for
more verbosity in the sync-logs?
If you search for "level" in about:config you will find some, notably
services.sync.log.appender.file.level.
OK, I've upped the above value to Debug. Doesn't seem to be increasing
the output in the sync-logs though (see below).
Do you have the server configured to send verification emails, and do
said emails come through correctly? It may be that you're hitting a
weird error path with trying to use an unverified account.
No problems with the emails, and verification certainly seems to be
getting beyond this point; and looking now in the fxa.accounts table,
the emailVerified=1 is there all right. The columns that are empty are:
uid kA wrapWrapKb authSalt verifyHash lockedAt
Post-verification, there's no indication of failure (no popunder), and
the account remains signed-in across a browser restart now.
On launch there's the following console output:
robin@hazel ~ $ firefox-bin --no-remote -P
(process:9726): GLib-CRITICAL **: g_slice_set_config: assertion
'sys_page_size == 0' failed
(process:9726): GLib-CRITICAL **: g_slice_set_config: assertion
'sys_page_size == 0' failed
1429652988127 Sync.BrowserIDManager ERROR Non-authentication error in
_fetchTokenForUser:
TokenServerClientServerError({"now":"2015-04-21T21:49:48.126Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 21:49:48 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429652988.12","x-timestamp":"1429652988"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429652988135 Sync.BrowserIDManager ERROR Background fetch for key
bundle failed:
TokenServerClientServerError({"now":"2015-04-21T21:49:48.126Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 21:49:48 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429652988.12","x-timestamp":"1429652988"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429652988136 Sync.BrowserIDManager ERROR Could not authenticate:
TokenServerClientServerError({"now":"2015-04-21T21:49:48.126Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 21:49:48 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429652988.12","x-timestamp":"1429652988"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
I note, however, that not all of these errors are appended to the
initial failed sync-log:
1429652987854 Sync.Service INFO Loading Weave 1.39.0
1429652987860 Sync.Engine.Clients DEBUG Engine initialized
1429652987862 Sync.Engine.Clients DEBUG Resetting clients last sync time
1429652987872 Sync.Engine.Bookmarks DEBUG Engine initialized
1429652987878 Sync.Engine.Forms DEBUG Engine initialized
1429652987886 Sync.Engine.History DEBUG Engine initialized
1429652987893 Sync.Engine.Passwords DEBUG Engine initialized
1429652987899 Sync.Engine.Prefs DEBUG Engine initialized
1429652987904 Sync.Engine.Tabs DEBUG Engine initialized
1429652987906 Sync.Engine.Tabs DEBUG Resetting tabs last sync time
1429652987916 Sync.Engine.Addons DEBUG Engine initialized
1429652987923 Sync.Service INFO Mozilla/5.0 (X11; Linux x86_64;
rv:37.0) Gecko/20100101 Firefox/37.0
1429652987928 Sync.SyncScheduler DEBUG Clearing sync triggers and the
global score.
1429652987930 Sync.Status DEBUG Status.service: success.status_ok =>
success.status_ok
1429652987930 Sync.Status DEBUG Status.service: success.status_ok =>
success.status_ok
1429652987931 Sync.Tracker.History INFO Adding Places observer.
1429652987956 Sync.Status DEBUG Status.service: success.status_ok =>
success.status_ok
1429652987958 Sync.Status DEBUG Status.service: success.status_ok =>
success.status_ok
1429652987959 Sync.Tracker.Clients WARN Changed IDs file clients
contains non-object value.
1429652987960 FirefoxAccounts DEBUG got keyPair
1429652987961 FirefoxAccounts DEBUG getCertificateSigned: true true
1429652987978 Sync.Tracker.Bookmarks WARN Changed IDs file bookmarks
contains non-object value.
1429652987980 Sync.Tracker.Forms WARN Changed IDs file forms contains
non-object value.
1429652987996 Sync.Tracker.Addons WARN Changed IDs file addons
contains non-object value.
1429652988054 Hawk DEBUG (Response) /certificate/sign: code: 200 -
Status text: OK
1429652988056 Hawk DEBUG Clock offset vs
https://fxa.example.com:9900/v1: -56
1429652988057 FirefoxAccounts DEBUG getCertificate got a new one: true
1429652988057 FirefoxAccounts DEBUG getAssertionFromCert
1429652988104 FirefoxAccounts DEBUG getAssertionFromCert returning
signed: true
1429652988107 Sync.BrowserIDManager DEBUG Getting a token
1429652988109 Common.TokenServerClient DEBUG Beginning BID assertion
exchange: http://fxa.example.com:5000/token/1.0/sync/1.5
1429652988125 Common.TokenServerClient DEBUG Got token response: 503
1429652988126 Common.TokenServerClient INFO Server-reported error:
{"location":"body","name":"","description":"Resource is not available"}
1429652988127 Sync.BrowserIDManager ERROR Non-authentication error in
_fetchTokenForUser:
TokenServerClientServerError({"now":"2015-04-21T21:49:48.126Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 21:49:48 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429652988.12","x-timestamp":"1429652988"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429652988128 Sync.Status DEBUG Status.login: success.login =>
error.login.reason.network
1429652988128 Sync.Status DEBUG Status.service: success.status_ok =>
error.login.failed
1429652988128 Sync.SyncScheduler DEBUG Clearing sync triggers and the
global score.
1429652988130 Sync.SyncScheduler DEBUG Next sync in 3600000 ms.
Now, this is also curious: If I trigger a sync attempt manually
(adding the button/throbber to the toolbar and clicking it), the
popunder starts to appear but is dismissed again before it's even
visible (you just get a nice split-second earth-tremor at the bottom
of the viewport), and two sync-logs are generated at the same time.
Log #1:
1429652988131 Sync.ErrorHandler DEBUG Flushing file log.
1429652988135 Sync.BrowserIDManager ERROR Background fetch for key
bundle failed:
TokenServerClientServerError({"now":"2015-04-21T21:49:48.126Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 21:49:48 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429652988.12","x-timestamp":"1429652988"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429652988136 Sync.BrowserIDManager ERROR Could not authenticate:
TokenServerClientServerError({"now":"2015-04-21T21:49:48.126Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 21:49:48 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429652988.12","x-timestamp":"1429652988"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429652988137 Sync.BrowserIDManager INFO currentAuthState returning
error.login.reason.network due to previous failure
1429652988137 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429652988137 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429652988142 Sync.ErrorHandler DEBUG Log cleanup threshold time:
1428788988142
1429652988144 Sync.ErrorHandler DEBUG No logs to clean up.
1429652991959 Sync.BrowserIDManager INFO currentAuthState returning
error.login.reason.network due to previous failure
1429652991959 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429652991959 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429653095131 Sync.Tracker.Bookmarks DEBUG Saving changed IDs to bookmarks
1429653110936 Sync.Tracker.History DEBUG Saving changed IDs to history
1429653452148 Sync.Tracker.History DEBUG Saving changed IDs to history
1429653820550 Sync.BrowserIDManager INFO currentAuthState returning
error.login.reason.network due to previous failure
1429653820550 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429653820551 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429653820551 Sync.BrowserIDManager INFO currentAuthState returning
error.login.reason.network due to previous failure
1429653820551 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429653820551 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429653820552 Sync.ErrorHandler DEBUG Beginning user-triggered sync.
1429653820553 Sync.Service DEBUG User-Agent: Firefox/37.0.1
FxSync/1.39.0.20150402191859.
1429653820553 Sync.Service INFO Starting sync at 2015-04-21 23:03:40
1429653820553 Sync.Service DEBUG In sync: should login.
1429653820554 Sync.BrowserIDManager INFO currentAuthState returning
error.login.reason.network due to previous failure
1429653820555 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429653820555 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429653820555 Sync.BrowserIDManager INFO currentAuthState returning
error.login.reason.network due to previous failure
1429653820555 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429653820555 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429653820562 Sync.BrowserIDManager INFO Waiting for user to be verified.
1429653820562 FirefoxAccounts DEBUG already verified
1429653820563 Sync.BrowserIDManager INFO Starting fetch for key bundle.
1429653820563 FirefoxAccounts DEBUG already verified
1429653820564 Sync.BrowserIDManager INFO Getting an assertion from:
http://fxa.example.com:5000/token/1.0/sync/1.5
1429653820564 FirefoxAccounts DEBUG enter getAssertion()
1429653820578 FirefoxAccounts DEBUG getKeyPair: already have a keyPair
1429653820578 FirefoxAccounts DEBUG getCertificate already had one
1429653820578 FirefoxAccounts DEBUG getAssertionFromCert
1429653820591 FirefoxAccounts DEBUG getAssertionFromCert returning
signed: true
1429653820593 Sync.BrowserIDManager DEBUG Getting a token
1429653820595 Common.TokenServerClient DEBUG Beginning BID assertion
exchange: http://fxa.example.com:5000/token/1.0/sync/1.5
1429653820609 Common.TokenServerClient DEBUG Got token response: 503
1429653820609 Common.TokenServerClient INFO Server-reported error:
{"location":"body","name":"","description":"Resource is not available"}
1429653820610 Sync.BrowserIDManager ERROR Non-authentication error in
_fetchTokenForUser:
TokenServerClientServerError({"now":"2015-04-21T22:03:40.609Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 22:03:40 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429653820.61","x-timestamp":"1429653820"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429653820611 Sync.Status DEBUG Status.login:
error.login.reason.network => error.login.reason.network
1429653820611 Sync.Status DEBUG Status.service: error.login.failed =>
error.login.failed
1429653820611 Sync.SyncScheduler DEBUG Clearing sync triggers and the
global score.
1429653820612 Sync.SyncScheduler DEBUG Next sync in 3600000 ms.
Log #2:
1429653820612 Sync.ErrorHandler DEBUG Flushing file log.
1429653820615 Sync.BrowserIDManager ERROR Background fetch for key
bundle failed:
TokenServerClientServerError({"now":"2015-04-21T22:03:40.609Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 22:03:40 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429653820.61","x-timestamp":"1429653820"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429653820615 Sync.BrowserIDManager ERROR Could not authenticate:
TokenServerClientServerError({"now":"2015-04-21T22:03:40.609Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"server":"PasteWSGIServer/0.5 Python/2.7.9","date":"Tue, 21 Apr 2015 22:03:40 GMT","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1429653820.61","x-timestamp":"1429653820"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < lazyImport/getter/<@main.js:20:5 <
WeaveService.prototype.observe/<.notify<@Weave.js:154:13
1429653820616 Sync.SyncScheduler DEBUG Clearing sync triggers and the
global score.
1429653820617 Sync.SyncScheduler DEBUG Next sync in 3600000 ms.
This behaviour is consistent: always the two logs created at the same
time. Should I be seeing this? It seems odd.
Cheers,
Robin Bankhead
_______________________________________________
Sync-dev mailing list
[email protected]
https://mail.mozilla.org/listinfo/sync-dev
