nginx/syncserver 503 error / connection_error/ verify_failure

codeling commented 9 years ago

Following this guide (in german), after getting the auth server running, I'm having a problem running the sync server. It is set up behind a nginx ssl reverse proxy, just as the auth and auth-api server (which both seem to work fine). The sync server only shows this in his output (line breaks inserted for readability):

$ make serve
./local/bin/pserve ./syncserver.ini
/home/mozillasync/syncserver/local/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 29076.
!!!
!!! WARNING: This command is deprecated.
!!! 
!!!     You should now use the `--paste` option. Ex.:
!!! 
!!!         gunicorn --paste development.ini
!!!     
!!!

INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): myurl.com
INFO:mozsvc.metrics:{"code": 503, "request_time": 0.19293904304504395,
"remoteAddressChain": ["myexternalip", "127.0.0.1"],
"agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:35.0) Gecko/20100101 Firefox/35.0",
"token.assertion.connection_error": 1, "token.assertion.verify_failure": 1,
"tokenserver.assertion.verify": 0.18337583541870117,
"path": "https://myurl.com/token/1.0/sync/1.5", "method": "GET"}

The "INFO" messages repeat every time a sync seems to run. Is this related to the browserid check? I thought I had configured the browserID verification appropriately:

[browserid]
backend = tokenserver.verifiers.LocalVerifier
audiences = *

The ngnix log has this in the error log:

2015/01/26 00:27:40 [error] 2334#0: *388 connect() failed (111: Connection refused) while connecting to upstream, client: 91.119.55.0, server: mydomain, request: "GET /token/1.0/sync/1.5 HTTP/1.1", upstream: "http://127.0.0.1:5000/token/1.0/sync/1.5", host: "mydomain"

I'm at a loss at how to proceed. What do the errors refer? Any additional logs I could check? Sorry if this is not the correct place to report this, if so could you point me to the correct one?

Any help is much appreciated!

rfk commented 9 years ago

Does it work if you use the default remote verifier rather than the LocalVerifier class?

Can you access the /.well-known/browserid on your auth-server instance, both from the internet at large and from a local connection on your syncserver machine?

codeling commented 9 years ago

Thanks for the quick answer!

Does it work if you use the default remote verifier rather than the LocalVerifier class?

No, but the error is slightly different (again, linebreaks inserted for readability):

INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): verifier.accounts.firefox.com
INFO:mozsvc.metrics:{"code": 401, "request_time": 1.9383349418640137,
"remoteAddressChain": ["myexternalip", "127.0.0.1"],
"token.assertion.invalid_signature_error": 1,
"agent": "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0",
"token.assertion.verify_failure": 1, "tokenserver.assertion.verify": 1.928689956665039,
"path": "https://mytokenserverurl/token/1.0/sync/1.5", "method": "GET"}

Can you access the /.well-known/browserid on your auth-server instance, both from the internet at large and from a local connection on your syncserver machine?

Yes, I can access it - what should it show? At the moment it looks like this: firefix-sync-wellknown maybe a stupid question, am I supposed to replace "browserid" by anything specific or was it meant literally (I entered it literally for now).

I'm wondering whether it is related to this problem: https://github.com/mozilla-services/syncserver/issues/32 ? Where can I find this sync error-log mentioned in that issue?

rfk commented 9 years ago

That URL should be serving a JSON document with your server's public key; for comparison here's how it looks on the Mozilla-hosted auth server:

https://api.accounts.firefox.com/.well-known/browserid

codeling commented 9 years ago

Ah you mean the API accounts server, not the account content server (which is what I tried above ;)). The location you gave on api account server is reachable and delivers

{"public-key":{"algorithm":"RS","n":"somereallylongnumber","e":"65537"},"authentication":"/.well-known/browserid/sign_in.html","provisioning":"/.well-known/browserid/provision.html"}

So that should be fine, right?

rfk commented 9 years ago

In your error log, where it says Starting new HTTPS connection (1): myurl.com, does it appear to be connecting to the API accounts server or the content server? From what I can see, I suspect it's failing to load this public key document for some reason, so I wonder if it's fetching it from the wrong server.

codeling commented 9 years ago

does it appear to be connecting to the API accounts server or the content server?

I couldn't tell, as it isn't telling me the port (both run on the same machine on different ports). Where do I configure the URL/port/... it's using for that key document lookup?

rfk commented 9 years ago

I couldn't tell, as it isn't telling me the port

Are there any requests for this document in nginx logs from either server?

codeling commented 9 years ago

Are there any requests for this document in nginx logs from either server?

requests for the ".well-known/browserid"? I didn't see any access to these except the manual one I did now

Edit: I just realized that the guide always uses default ports (3030, 5000, 9000). I am using different ones (for the reverse-proxy ports, the local services do run on those default ports). Any special caveats when not using those default ports? Are they maybe hardcoded somewhere?

allo- commented 9 years ago

The requests module from the virtualenv does not use system certificates. if you happen to use a CA like cacert, you need to include it in the requests certstore (in the venv) or patch requests like the system package python-requests (debian/ubuntu) does:

--- a/requests/certs.py
+++ b/requests/certs.py
@@ -18,8 +18,8 @@
 except ImportError:
     def where():
         """Return the preferred certificate bundle."""
-        # vendored bundle inside Requests
-        return os.path.join(os.path.dirname(__file__), 'cacert.pem')
+        # On Debian systems use ca-certificates
+        return '/etc/ssl/certs/ca-certificates.crt'

codeling commented 9 years ago

if you happen to use a CA like cacert, you need to include it in the requests certstore

That could be it - though I'm using a startssl certificate at the moment I think which should be included in typical cert stores, right?

allo- commented 9 years ago

add here: https://github.com/mozilla-services/tokenserver/blob/master/tokenserver/views.py#L74 a print repr(e) and have a look at the console output.

codeling commented 9 years ago

Seems you were right about the certificate, print repr(e) yields:

ConnectionError(u'Failed to GET https://myauthapidomain/.well-known/browserid. Reason: [Errno 1] _ssl.c:510: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed',)

But the certs.py fix doesn't work somehow:

ConnectionError(u'Failed to GET https://myauthapidomain/.well-known/browserid. Reason: [Errno 185090050] _ssl.c:344: error:0B084002:x509 certificate routines:X509_load_cert_crl_file:system lib',)

Unfortunately that error doesn't mean anything to me, what does it express? The file /etc/ssl/certs/ca-certificates.crt does exist. Running on Ubuntu server 14.04.1 here, is there a difference in the certificate file format maybe to Debian?

codeling commented 9 years ago

Ok I have solved that problem. I had to add the CA's certificates to the referenced .pem file. Now the browserID verification runs through. The sync still won't run though because of the auth apparently still having problems - the session is not persisted somehow, after logging I'm immediately logged out again - but that's another issue. Thanks for the help!

allo- commented 9 years ago

maybe a little bit of documentation or configuration (own_certs_path = /foo.pem) should be added?

codeling commented 9 years ago

That would be good I guess. Also a more clear error message what exactly fails about the browserid request might be nice.

codeling commented 9 years ago

Now trying with the Mozilla auth server, I still get a problem in the sync log:

1423178401738   FirefoxAccounts DEBUG   getCertificate got a new one: true
1423178401739   FirefoxAccounts DEBUG   getAssertionFromCert
1423178401740   FirefoxAccounts DEBUG   getAssertionFromCert returning signed: true
1423178401741   Sync.BrowserIDManager   DEBUG   Getting a token
1423178401908   Sync.BrowserIDManager   ERROR   Non-authentication error in _fetchTokenForUser: Non-JSON response.
1423178401908   Sync.Status DEBUG   Status.login: success.login => error.login.reason.network
1423178401908   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1423178401908   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1423178401909   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms.

I don't see any information on what request it exactly was trying when it got the "Non-JSON response". I'd be very glad to hear where I can check the details on that - thanks!

Edit: In the output of the syncserver I now get

INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): api.accounts.firefox.com
INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.007000923156738281, "code": 401,
"request_time": 1.023833990097046, "remoteAddressChain": ["myexternalip", "127.0.0.1"],
"agent": "Mozilla/5.0 (Windows NT 6.3; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0",
"tokenserver.assertion.verify": 1.0073809623718262, "token.assertion.verify_success": 1,
"path": "https://mysyncserver/token/1.0/sync/1.5", "method": "GET"}

(again spaces inserted for readability) which seems to indicate token verification success? But still no luck with sync - the sync database is empty...

and starting from now I also get the same behavior as described here: https://github.com/mozilla/fxa-auth-server/issues/869 (being logged out again after having logged in successfully, and the same error messages as noted there). So the problem doesn't seem to lie in the fxa-auth-server but in the sync server somehow - if with both my self-setup and the "official" auth server I get the exact same behavior - the same in both cases is only the sync server (or the clients of course ;))... can somebody shed a light? I'm at my wits end :o.

rfk commented 9 years ago

INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.007000923156738281, "code": 401

The assertion is verifying correctly, but you're still getting an authentication error form the tokenserver. Is there addition information from this request in the client-side log?

It may be worth deleting your local sync/tokenserver database and starting from a clean slate in case it's got some old records in there that are confusing things.

codeling commented 9 years ago

Is there addition information from this request in the client-side log?

There is, yes:

1423175931872   FirefoxAccounts DEBUG   got keyPair
1423175931872   FirefoxAccounts DEBUG   getCertificateSigned: true true
1423175932522   FirefoxAccounts ERROR   error POSTing /certificate/sign: {"code":401,"errno":110,"error":"Unauthorized","message":"Invalid authentication token in request signature","info":"https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format","log":[]}
1423175932522   FirefoxAccounts ERROR   HAWK.signCertificate error: {"code":401,"errno":110,"error":"Unauthorized","message":"Invalid authentication token in request signature","info":"https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format","log":[]}
1423175932523   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: AuthenticationError([object Object])
1423175932523   Sync.Status DEBUG   Status.login: success.login => error.login.reason.account
1423175932523   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1423175932523   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.

and

1423175932525   Sync.BrowserIDManager   ERROR   Background fetch for key bundle failed: AuthenticationError([object Object])
1423175932525   Sync.BrowserIDManager   ERROR   Could not authenticate: AuthenticationError([object Object])
1423175932525   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.account due to previous failure
1423175932525   Sync.Status DEBUG   Status.login: error.login.reason.account => error.login.reason.account
1423175932525   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed

and

1423175940943   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: AuthenticationError(TokenServerClientServerError({"now":"2015-02-05T22:39:00.943Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"nginx/1.4.6 (Ubuntu)","date":"Thu, 05 Feb 2015 22:38:59 GMT","content-type":"application/json; charset=UTF-8","content-length":"110","connection":"keep-alive","x-weave-timestamp":"1423175939.36","x-timestamp":"1423175939"},"response_status":401}))
1423175940943   Sync.Status DEBUG   Status.login: error.login.reason.account => error.login.reason.account
1423175940943   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed

It may be worth deleting your local sync/tokenserver database and starting from a clean slate in case it's got some old records in there that are confusing things.

The token database still is empty - there are tables but they all have zero rows.

Edit: By the way, occasionally the sync server shuts down and reports this:

Exiting 1 (-v to see traceback)

Where would I need to add the "-v"?

rfk commented 9 years ago

Where would I need to add the "-v"?

This I have never seen before; there's probably an equivalent flag you can add to the [server:main] section of syncserver.ini but I've no idea what it would be...

rfk commented 9 years ago

So this:

1423175931872   FirefoxAccounts DEBUG   got keyPair
1423175931872   FirefoxAccounts DEBUG   getCertificateSigned: true true
1423175932522   FirefoxAccounts ERROR   error POSTing /certificate/sign: {"code":401,"errno":110,"error":"Unauthorized","message":"Invalid authentication token in request signature","info":"https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format","log":[]}
1423175932522   FirefoxAccounts ERROR   HAWK.signCertificate error: {"code":401,"errno":110,"error":"Unauthorized","message":"Invalid authentication token in request signature","info":"https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format","log":[]}
1423175932523   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: AuthenticationError([object Object])
``

And this:

You're receiving notifications because you commented. 3 participants codeling Ryan Kelly allo- Lock issue codeling codeling commented 11 days ago

Following this guide (in german), after getting the auth server running, I'm having a problem running the sync server. It is set up behind a nginx ssl reverse proxy, just as the auth and auth-api server (which both seem to work fine). The sync server only shows this in his output (line breaks inserted for readability):

$ make serve ./local/bin/pserve ./syncserver.ini /home/mozillasync/syncserver/local/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 29076. !!! !!! WARNING: This command is deprecated. !!! !!! You should now use the --paste option. Ex.: !!! !!! gunicorn --paste development.ini !!!
!!!

INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): myurl.com INFO:mozsvc.metrics:{"code": 503, "request_time": 0.19293904304504395, "remoteAddressChain": ["myexternalip", "127.0.0.1"], "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:35.0) Gecko/20100101 Firefox/35.0", "token.assertion.connection_error": 1, "token.assertion.verify_failure": 1, "tokenserver.assertion.verify": 0.18337583541870117, "path": "https://myurl.com/token/1.0/sync/1.5", "method": "GET"}

The "INFO" messages repeat every time a sync seems to run. Is this related to the browserid check? I thought I had configured the browserID verification appropriately:

[browserid] backend = tokenserver.verifiers.LocalVerifier audiences = *

The ngnix log has this in the error log:

2015/01/26 00:27:40 [error] 2334#0: *388 connect() failed (111: Connection refused) while connecting to upstream, client: 91.119.55.0, server: mydomain, request: "GET /token/1.0/sync/1.5 HTTP/1.1", upstream: "http://127.0.0.1:5000/token/1.0/sync/1.5", host: "mydomain"

I'm at a loss at how to proceed. What do the errors refer? Any additional logs I could check? Sorry if this is not the correct place to report this, if so could you point me to the correct one?

Any help is much appreciated! Ryan Kelly Owner rfk commented 11 days ago

Does it work if you use the default remote verifier rather than the LocalVerifier class?

Can you access the /.well-known/browserid on your auth-server instance, both from the internet at large and from a local connection on your syncserver machine? codeling codeling commented 11 days ago

Thanks for the quick answer!

Does it work if you use the default remote verifier rather than the LocalVerifier class?

No, but the error is slightly different (again, linebreaks inserted for readability):

INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): verifier.accounts.firefox.com INFO:mozsvc.metrics:{"code": 401, "request_time": 1.9383349418640137, "remoteAddressChain": ["myexternalip", "127.0.0.1"], "token.assertion.invalid_signature_error": 1, "agent": "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0", "token.assertion.verify_failure": 1, "tokenserver.assertion.verify": 1.928689956665039, "path": "https://mytokenserverurl/token/1.0/sync/1.5", "method": "GET"}

Can you access the /.well-known/browserid on your auth-server instance, both from the internet at large and from a local connection on your syncserver machine?

Yes, I can access it - what should it show? At the moment it looks like this: firefix-sync-wellknown maybe a stupid question, am I supposed to replace "browserid" by anything specific or was it meant literally (I entered it literally for now).

I'm wondering whether it is related to this problem: #32 ? Where can I find this sync error-log mentioned in that issue? Ryan Kelly Owner rfk commented 11 days ago

That URL should be serving a JSON document with your server's public key; for comparison here's how it looks on the Mozilla-hosted auth server:

https://api.accounts.firefox.com/.well-known/browserid codeling codeling commented 11 days ago

Ah you mean the API accounts server, not the account content server (which is what I tried above ;)). The location you gave on api account server is reachable and delivers

{"public-key":{"algorithm":"RS","n":"somereallylongnumber","e":"65537"},"authentication":"/.well-known/browserid/sign_in.html","provisioning":"/.well-known/browserid/provision.html"}

So that should be fine, right? Ryan Kelly Owner rfk commented 11 days ago

In your error log, where it says Starting new HTTPS connection (1): myurl.com, does it appear to be connecting to the API accounts server or the content server? From what I can see, I suspect it's failing to load this public key document for some reason, so I wonder if it's fetching it from the wrong server. codeling codeling commented 11 days ago

does it appear to be connecting to the API accounts server or the content server?

I couldn't tell, as it isn't telling me the port (both run on the same machine on different ports). Where do I configure the URL/port/... it's using for that key document lookup? Ryan Kelly Owner rfk commented 11 days ago

I couldn't tell, as it isn't telling me the port

Are there any requests for this document in nginx logs from either server? codeling codeling commented 11 days ago

Are there any requests for this document in nginx logs from either server?

requests for the ".well-known/browserid"? I didn't see any access to these except the manual one I did now

Edit: I just realized that the guide always uses default ports (3030, 5000, 9000). I am using different ones (for the reverse-proxy ports, the local services do run on those default ports). Any special caveats when not using those default ports? Are they maybe hardcoded somewhere? allo- allo- commented 10 days ago

The requests module from the virtualenv does not use system certificates. if you happen to use a CA like cacert, you need to include it in the requests certstore (in the venv) or patch requests like the system package python-requests (debian/ubuntu) does:

--- a/requests/certs.py +++ b/requests/certs.py @@ -18,8 +18,8 @@ except ImportError: def where(): """Return the preferred certificate bundle."""

vendored bundle inside Requests
return os.path.join(os.path.dirname(file), 'cacert.pem')
On Debian systems use ca-certificates
return '/etc/ssl/certs/ca-certificates.crt'

codeling codeling commented 10 days ago

if you happen to use a CA like cacert, you need to include it in the requests certstore

That could be it - though I'm using a startssl certificate at the moment I think which should be included in typical cert stores, right? allo- allo- commented 10 days ago

add here: https://github.com/mozilla-services/tokenserver/blob/master/tokenserver/views.py#L74 a print repr(e) and have a look at the console output. codeling codeling commented 10 days ago

Seems you were right about the certificate, print repr(e) yields:

ConnectionError(u'Failed to GET https://myauthapidomain/.well-known/browserid. Reason: [Errno 1] _ssl.c:510: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed',)

But the certs.py fix doesn't work somehow:

ConnectionError(u'Failed to GET https://myauthapidomain/.well-known/browserid. Reason: [Errno 185090050] _ssl.c:344: error:0B084002:x509 certificate routines:X509_load_cert_crl_file:system lib',)

Unfortunately that error doesn't mean anything to me, what does it express? The file /etc/ssl/certs/ca-certificates.crt does exist. Running on Ubuntu server 14.04.1 here, is there a difference in the certificate file format maybe to Debian? codeling codeling commented 9 days ago

Ok I have solved that problem. I had to add the CA's certificates to the referenced .pem file. Now the browserID verification runs through. The sync still won't run though because of the auth apparently still having problems - the session is not persisted somehow, after logging I'm immediately logged out again - but that's another issue. Thanks for the help! codeling codeling closed this 9 days ago allo- allo- commented 9 days ago

maybe a little bit of documentation or configuration (own_certs_path = /foo.pem) should be added? codeling codeling commented 9 days ago

That would be good I guess. Also a more clear error message what exactly fails about the browserid request might be nice. codeling codeling referenced this issue in mozilla/fxa-auth-server 3 days ago Open self-hosted server / trouble staying logged in / strange errors #869 codeling codeling reopened this 3 days ago codeling codeling commented 3 days ago

Now trying with the Mozilla auth server, I still get a problem in the sync log:

1423178401738 FirefoxAccounts DEBUG getCertificate got a new one: true 1423178401739 FirefoxAccounts DEBUG getAssertionFromCert 1423178401740 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1423178401741 Sync.BrowserIDManager DEBUG Getting a token 1423178401908 Sync.BrowserIDManager ERROR Non-authentication error in _fetchTokenForUser: Non-JSON response. 1423178401908 Sync.Status DEBUG Status.login: success.login => error.login.reason.network 1423178401908 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1423178401908 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1423178401909 Sync.SyncScheduler DEBUG Next sync in 3600000 ms.

I don't see any information on what request it exactly was trying when it got the "Non-JSON response". I'd be very glad to hear where I can check the details on that - thanks!

Edit: In the output of the syncserver I now get

INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): api.accounts.firefox.com INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.007000923156738281, "code": 401, "request_time": 1.023833990097046, "remoteAddressChain": ["myexternalip", "127.0.0.1"], "agent": "Mozilla/5.0 (Windows NT 6.3; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0", "tokenserver.assertion.verify": 1.0073809623718262, "token.assertion.verify_success": 1, "path": "https://mysyncserver/token/1.0/sync/1.5", "method": "GET"}

(again spaces inserted for readability) which seems to indicate token verification success? But still no luck with sync - the sync database is empty...

and starting from now I also get the same behavior as described here: mozilla/fxa-auth-server#869 (being logged out again after having logged in successfully, and the same error messages as noted there). So the problem doesn't seem to lie in the fxa-auth-server but in the sync server somehow - if with both my self-setup and the "official" auth server I get the exact same behavior - the same in both cases is only the sync server (or the clients of course ;))... can somebody shed a light? I'm at my wits end :o. Ryan Kelly Owner rfk commented 3 days ago

INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.007000923156738281, "code": 401

The assertion is verifying correctly, but you're still getting an authentication error form the tokenserver. Is there addition information from this request in the client-side log?

It may be worth deleting your local sync/tokenserver database and starting from a clean slate in case it's got some old records in there that are confusing things. codeling

1423175932525 Sync.BrowserIDManager ERROR Background fetch for key bundle failed: AuthenticationError([object Object])


Are both auth-server-related errors.  It looks like your login session has been invalidated somehow.  You may need to disconnect and reconnect to sync in your browser, or perhaps try with a clean Firefox profile.

codeling commented 9 years ago

This I have never seen before; there's probably an equivalent flag you can add to the [server:main] section of syncserver.ini but I've no idea what it would be...

I've now tried adding the syslog = true to the [server:main] section, I'll check later what happens!

Are both auth-server-related errors. It looks like your login session has been invalidated somehow. You may need to disconnect and reconnect to sync in your browser, or perhaps try with a clean Firefox profile.

I have tried numerous times to connect / login / restart Firefox. With a new profile, I get this:

1423483658727   Sync.Service    INFO    Loading Weave 1.37.0
1423483658729   Sync.Engine.Clients DEBUG   Engine initialized
1423483658729   Sync.Engine.Clients DEBUG   Resetting clients last sync time
1423483658732   Sync.Engine.Bookmarks   DEBUG   Engine initialized
1423483658734   Sync.Engine.Forms   DEBUG   Engine initialized
1423483658736   Sync.Engine.History DEBUG   Engine initialized
1423483658739   Sync.Engine.Passwords   DEBUG   Engine initialized
1423483658740   Sync.Engine.Prefs   DEBUG   Engine initialized
1423483658742   Sync.Engine.Tabs    DEBUG   Engine initialized
1423483658743   Sync.Engine.Tabs    DEBUG   Resetting tabs last sync time
1423483658746   Sync.Engine.Addons  DEBUG   Engine initialized
1423483658747   Sync.Service    INFO    Mozilla/5.0 (Windows NT 6.1; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0
1423483658749   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1423483658749   Sync.Status DEBUG   Status.login: success.login => error.login.reason.no_username
1423483658750   Sync.Status DEBUG   Status.service: success.status_ok => service.client_not_configured
1423483658750   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.no_username
1423483658750   Sync.Status DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1423483658765   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.no_username
1423483658765   Sync.Status DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1423483658766   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.no_username
1423483658766   Sync.Status DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1423483658773   Sync.Tracker.Clients    WARN    Changed IDs file clients contains non-object value.
1423483658774   Sync.Tracker.Bookmarks  WARN    Changed IDs file bookmarks contains non-object value.
1423483658774   Sync.Tracker.Forms  WARN    Changed IDs file forms contains non-object value.
1423483658775   Sync.Tracker.History    WARN    Changed IDs file history contains non-object value.
1423483658776   Sync.Tracker.Passwords  WARN    Changed IDs file passwords contains non-object value.
1423483658778   Sync.Tracker.Addons WARN    Changed IDs file addons contains non-object value.
1423483688913   FirefoxAccounts DEBUG   setSignedInUser - aborting any existing flows
1423483688927   FirefoxAccounts DEBUG   Notifying observers of fxaccounts:onlogin
1423483688927   Sync.BrowserIDManager   DEBUG   observed fxaccounts:onlogin
1423483688927   FirefoxAccounts DEBUG   startVerifiedCheck {"email":"myemail","uid":"5d2b2a8e3e274ff9a75c8f80d20071c2","sessionToken":"e3048b80e97c9654256e977ffaffd8b6f6d82951b78601d2af3b924b054314d6","sessionTokenContext":"fx_desktop_v1","unwrapBKey":"5bed270ae6eb48ff9d6734d8017747ccf01da0ea805485812c11f82a0f0922a3","keyFetchToken":"a05ae2d957abe2afb9770cccb3f6dbe624f27e8004ee67065bb31f8e862dc844","customizeSync":false}
1423483688927   FirefoxAccounts DEBUG   whenVerified promise starts polling for verified email
1423483688927   FirefoxAccounts DEBUG   entering pollEmailStatus: start
1423483688933   FirefoxAccounts DEBUG   startVerifiedCheck {"email":"myemail","uid":"5d2b2a8e3e274ff9a75c8f80d20071c2","sessionToken":"e3048b80e97c9654256e977ffaffd8b6f6d82951b78601d2af3b924b054314d6","sessionTokenContext":"fx_desktop_v1","unwrapBKey":"5bed270ae6eb48ff9d6734d8017747ccf01da0ea805485812c11f82a0f0922a3","keyFetchToken":"a05ae2d957abe2afb9770cccb3f6dbe624f27e8004ee67065bb31f8e862dc844","customizeSync":false}
1423483688934   Sync.BrowserIDManager   INFO    Username changed. Removing stored credentials.
1423483688934   Sync.BrowserIDManager   INFO    Waiting for user to be verified.
1423483689120   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"myemail","verified":true}
1423483689136   FirefoxAccounts DEBUG   Notifying observers of fxaccounts:update
1423483689136   Sync.BrowserIDManager   INFO    Starting fetch for key bundle.
1423483689137   FirefoxAccounts DEBUG   fetchKeys: true
1423483689139   Sync.BrowserIDManager   INFO    Fetching assertion and token from: https://mysyncserverdomain/token/1.0/sync/1.5
1423483689139   FirefoxAccounts DEBUG   already verified
1423483689340   FirefoxAccounts DEBUG   Keys Obtained: kA=true, kB=true
1423483689354   FirefoxAccounts DEBUG   Notifying observers of fxaccounts:onverified
1423483689356   Sync.BrowserIDManager   DEBUG   Getting an assertion
1423483689356   FirefoxAccounts DEBUG   enter getAssertion()
1423483689370   FirefoxAccounts DEBUG   got keyPair
1423483689370   FirefoxAccounts DEBUG   getCertificateSigned: true true
1423483689574   FirefoxAccounts DEBUG   getCertificate got a new one: true
1423483689574   FirefoxAccounts DEBUG   getAssertionFromCert
1423483689575   FirefoxAccounts DEBUG   getAssertionFromCert returning signed: true
1423483689575   Sync.BrowserIDManager   DEBUG   Getting a token
1423483689804   Sync.BrowserIDManager   ERROR   Non-authentication error in _fetchTokenForUser: Client error.
1423483689804   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.network
1423483689804   Sync.Status DEBUG   Status.service: service.client_not_configured => error.login.failed
1423483689804   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1423483689804   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms.

rfk commented 9 years ago

That log looks like everything went well with a fresh profile, until it hit some sort of network-level error:

1423483689804 Sync.BrowserIDManager ERROR Non-authentication error in _fetchTokenForUser: Client error. 1423483689804 Sync.Status DEBUG Status.login: error.login.reason.no_username => error.login.reason.network

Is it possible there were connectivity issues during the run?

codeling commented 9 years ago

For this particular instance the availability could have been problematic since the syncserver was constantly restarting (when started manually it would only show "Exiting 1 (-v to see traceback)" as shown above, but now every time).

Quite frankly, I don't have that much time to invest for now so I will leave this be and use the provided servers. Thanks a lot for your support though!

mozilla-services / syncserver

nginx/syncserver 503 error / connection_error/ verify_failure #52

vendored bundle inside Requests

On Debian systems use ca-certificates