search

mozilla-services / syncserver

Run-Your-Own Firefox Sync Server
Mozilla Public License 2.0
1.87k stars 145 forks source link

Token.assertion.invalid_signature_error on Fresh Install #32

Closed Fmstrat closed 10 years ago

Fmstrat commented 10 years ago

Self hosted FxA and Sync, FxA seems to operate fine but sync 1.5 is throwing errors. It seems there is a hard coded verifier URL in ./local/lib/python2.7/site-packages/tokenserver/verifiers.py of "verifier.accounts.firefox.com," but I'm not sure exactly what that's doing, or why a self-hosted service would be using the firefox.com servers. The below configurations were used with a fresh git, and a reset fxa and sync database.

The below errors occurred when registering a new user and after the verification of email. Email shows as verified in the fxa database.

As a note, the sync database tables are created, but no records are placed in the DB.

Sync output:

[Wed Jul 23 17:19:23 2014] [error] INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): verifier.accounts.firefox.com
[Wed Jul 23 17:19:24 2014] [error] INFO:mozsvc.metrics:{"code": 200, "request_time": 0.5247030258178711, "remoteAddressChain": ["192.168.3.99"], "token.assertion.invalid_signature_error": 1, "agent": "Mozilla/5.0 (Windows NT 6.2; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0", "token.assertion.verify_failure": 1, "tokenserver.assertion.verify": 0.5226249694824219, "path": "https://firefox-vm.domain.local:1443/token/1.0/sync/1.5", "method": "GET"}

Firefox's sync error-log:

1406150201322   Sync.Service    INFO    Loading Weave 1.33.0
1406150201323   Sync.Engine.Clients DEBUG   Engine initialized
1406150201323   Sync.Engine.Clients DEBUG   Resetting clients last sync time
1406150201326   Sync.Engine.Bookmarks   DEBUG   Engine initialized
1406150201327   Sync.Engine.Forms   DEBUG   Engine initialized
1406150201329   Sync.Engine.History DEBUG   Engine initialized
1406150201330   Sync.Engine.Passwords   DEBUG   Engine initialized
1406150201331   Sync.Engine.Prefs   DEBUG   Engine initialized
1406150201332   Sync.Engine.Tabs    DEBUG   Engine initialized
1406150201333   Sync.Engine.Tabs    DEBUG   Resetting tabs last sync time
1406150201335   Sync.Engine.Addons  DEBUG   Engine initialized
1406150201336   Sync.Service    INFO    Mozilla/5.0 (Windows NT 6.2; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0
1406150201337   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1406150201337   Sync.Status DEBUG   Status.login: success.login => error.login.reason.no_username
1406150201337   Sync.Status DEBUG   Status.service: success.status_ok => service.client_not_configured
1406150201337   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.no_username
1406150201337   Sync.Status DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1406150201340   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.no_username
1406150201340   Sync.Status DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1406150201340   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.no_username
1406150201340   Sync.Status DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1406150201340   FirefoxAccounts DEBUG   setSignedInUser - aborting any existing flows
1406150201340   Sync.Tracker.Clients    WARN    Changed IDs file clients contains non-object value.
1406150201342   Sync.Tracker.Passwords  WARN    Changed IDs file passwords contains non-object value.
1406150201343   Sync.Tracker.Addons WARN    Changed IDs file addons contains non-object value.
1406150201344   FirefoxAccounts INFO    An accountState promise was resolved, but was actually rejected due to a different user being signed in. Originally resolved with: null
1406150201348   FirefoxAccounts DEBUG   Notifying observers of fxaccounts:onlogin
1406150201348   Sync.BrowserIDManager   DEBUG   observed fxaccounts:onlogin
1406150201348   FirefoxAccounts DEBUG   startVerifiedCheck {"email":"firefox@domain.com","uid":"1d032a9bb6e445d58b2530a8b652ff6d","unwrapBKey":"6bbd3c3ebae84b44a158a5e39c579293dbb70cb536c23c256f7a643b67c81622","keyFetchToken":"b17f7c7c7259df986f39bd326a160223ef2cfcb094c9dd1dc4e0615c200bcbb5","sessionToken":"fd3648c941e36e17fd8cf6919a5e090fb2cbb84eb50333f50083d2f908e5699d","sessionTokenContext":"fx_desktop_v1","customizeSync":false}
1406150201348   FirefoxAccounts DEBUG   whenVerified promise starts polling for verified email
1406150201348   FirefoxAccounts DEBUG   entering pollEmailStatus: start
1406150201352   FirefoxAccounts DEBUG   startVerifiedCheck {"email":"firefox@domain.com","uid":"1d032a9bb6e445d58b2530a8b652ff6d","unwrapBKey":"6bbd3c3ebae84b44a158a5e39c579293dbb70cb536c23c256f7a643b67c81622","keyFetchToken":"b17f7c7c7259df986f39bd326a160223ef2cfcb094c9dd1dc4e0615c200bcbb5","sessionToken":"fd3648c941e36e17fd8cf6919a5e090fb2cbb84eb50333f50083d2f908e5699d","sessionTokenContext":"fx_desktop_v1","customizeSync":false}
1406150201352   Sync.BrowserIDManager   INFO    Username changed. Removing stored credentials.
1406150201352   Sync.BrowserIDManager   INFO    Waiting for user to be verified.
1406150201377   FirefoxAccounts DEBUG   (Response) /recovery_email/status: code: 200 - Status text: OK
1406150201377   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.domain.local:19000/v1: 18623
1406150201377   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"firefox@domain.com","verified":false}
1406150201377   FirefoxAccounts DEBUG   polling with step = 3000
1406150201377   FirefoxAccounts DEBUG   time remaining: 297000
1406150201377   FirefoxAccounts DEBUG   started timer 19
1406150204378   FirefoxAccounts DEBUG   entering pollEmailStatus: timer
1406150204402   FirefoxAccounts DEBUG   (Response) /recovery_email/status: code: 200 - Status text: OK
1406150204403   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.domain.local:19000/v1: 18597
1406150204403   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"firefox@domain.com","verified":false}
1406150204403   FirefoxAccounts DEBUG   polling with step = 3000
1406150204403   FirefoxAccounts DEBUG   time remaining: 294000
1406150204403   FirefoxAccounts DEBUG   started timer 20
1406150207404   FirefoxAccounts DEBUG   entering pollEmailStatus: timer
1406150207425   FirefoxAccounts DEBUG   (Response) /recovery_email/status: code: 200 - Status text: OK
1406150207425   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.domain.local:19000/v1: 18575
1406150207426   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"firefox@domain.com","verified":false}
1406150207426   FirefoxAccounts DEBUG   polling with step = 3000
1406150207426   FirefoxAccounts DEBUG   time remaining: 291000
1406150207426   FirefoxAccounts DEBUG   started timer 21
1406150210427   FirefoxAccounts DEBUG   entering pollEmailStatus: timer
1406150210449   FirefoxAccounts DEBUG   (Response) /recovery_email/status: code: 200 - Status text: OK
1406150210449   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.domain.local:19000/v1: 18551
1406150210449   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"firefox@domain.com","verified":true}
1406150210458   Sync.BrowserIDManager   INFO    Starting fetch for key bundle.
1406150210458   FirefoxAccounts DEBUG   fetchKeys: true
1406150210461   Sync.BrowserIDManager   INFO    Fetching assertion and token from: https://firefox-vm.domain.local:1443/token/1.0/sync/1.5
1406150210461   FirefoxAccounts DEBUG   already verified
1406150210647   FirefoxAccounts DEBUG   (Response) /account/keys: code: 200 - Status text: OK
1406150210648   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.domain.local:19000/v1: 18352
1406150210649   FirefoxAccounts DEBUG   Keys Obtained: kA=true, kB=true
1406150210657   FirefoxAccounts DEBUG   Notifying observers of fxaccounts:onverified
1406150210658   Sync.BrowserIDManager   DEBUG   Getting an assertion
1406150210658   FirefoxAccounts DEBUG   enter getAssertion()
1406150210665   FirefoxAccounts DEBUG   got keyPair
1406150210666   FirefoxAccounts DEBUG   getCertificateSigned: true true
1406150210874   FirefoxAccounts DEBUG   (Response) /certificate/sign: code: 200 - Status text: OK
1406150210874   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.domain.local:19000/v1: 18126
1406150210874   FirefoxAccounts DEBUG   getCertificate got a new one: true
1406150210875   FirefoxAccounts DEBUG   getAssertionFromCert
1406150210877   FirefoxAccounts DEBUG   getAssertionFromCert returning signed: true
1406150210877   Sync.BrowserIDManager   DEBUG   Getting a token
1406150213120   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: AuthenticationError(TokenServerClientServerError({"now":"2014-07-23T21:16:53.119Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"date":"Wed, 23 Jul 2014 21:17:09 GMT","server":"Apache/2.2.15 (CentOS)","x-weave-timestamp":"1406150232.13","x-timestamp":"1406150232","content-length":"110","connection":"close","content-type":"application/json; charset=UTF-8"},"response_status":401}))
1406150213120   Sync.Status DEBUG   Status.login: error.login.reason.no_username => error.login.reason.account
1406150213120   Sync.Status DEBUG   Status.service: service.client_not_configured => error.login.failed
1406150213120   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.

syncserver.ini:

[server:main]
use = egg:Paste#http
host = 0.0.0.0
port = 5000

[app:main]
use = egg:syncserver

[syncserver]
# This must be edited to point to the public URL of your server,
# i.e. the URL as seen by Firefox.
public_url = https://firefox-vm.domain.local:1443/

# This defines the database in which to store all server data.
#sqluri = sqlite:////tmp/syncserver.db
sqluri = pymysql://root@localhost/sync

# This is a secret key used for signing authentication tokens.
# It should be long and randomly-generated.
# The following command will give a suitable value on *nix systems:
#
#    head -c 20 /dev/urandom | sha1sum
#
# If not specified then the server will generate a temporary one at startup.
secret = REMOVEDBUTCHANGED

# Set this to "false" to disable new-user signups on the server.
# Only request by existing accounts will be honoured.
# allow_new_users = false

auth-config.json:

{
    "env": "prod",
    "publicUrl": "https://firefox-vm.domain.local:19000",
    "db": {
        "backend": "mysql"
    },
    "listen": {
        "host": "0.0.0.0",
        "port": 9000
    },
    "useHttps": false,
    "contentServer": {
        "url": "https://firefox-vm.domain.local:13030"
    },
    "smtp": {
        "host": "mail-vm.domain.local",
        "port": 25,
        "secure": false,
        "sender": "administrator@domain.com",
        "redirectDomain": "domain.com",
        "resendBlackoutPeriod": 0
    },
    "log": {
        "level": "trace"
    },
    "customsUrl": "none"
}

content-config.json:

{
  "fxaccount_url": "https://firefox-vm.domain.local:19000",
  "public_url": "https://firefox-vm.domain.local:13030",
  "fxaccount_proxy": {
    "enabled": false
  },
  "oauth_url": "http://127.0.0.1:9010",
  "oauth_proxy": {
    "enabled": true
  },
  "client_sessions": {
    "cookie_name": "session",
    "secret": "REMOVEDBUTCHANGED",
    "duration": 86400000
  },
  "env": "production",
  "static_max_age" : 0,
  "i18n": {
    "supportedLanguages": ["af", "an", "ar", "as", "ast", "be", "bg", "bn-BD", "bn-IN", "br", "bs", "ca", "cs", "cy", "da", "de", "el", "en-GB", "en-US", "en-ZA", "eo", "es", "es-AR", "es-CL", "es-MX", "et", "eu", "fa", "ff", "fi", "fr", "fy", "fy-NL", "ga", "ga-IE", "gd", "gl", "gu", "gu-IN", "he", "hi-IN", "hr", "ht", "hu", "hy-AM", "id", "is", "it", "it-CH", "ja", "kk", "km", "kn", "ko", "ku", "lij", "lt", "lv", "mai", "mk", "ml", "mr", "ms", "nb-NO", "ne-NP", "nl", "nn-NO", "or", "pa", "pa-IN", "pl", "pt", "pt-BR", "pt-PT", "rm", "ro", "ru", "si", "sk", "sl", "son", "sq", "sr", "sr-LATN", "sv", "sv-SE", "ta", "te", "th", "tr", "uk", "ur", "vi", "xh", "zh-CN", "zh-TW", "zu"]
  },
  "route_log_format": "dev_fxa",
  "static_directory": "app",
  "metrics": {
    "sample_rate": 0
  },
  "use_https": false,
  "port": 3030,
  "http_port": 3080,
}

apache conf:

SSLPassPhraseDialog  builtin
SSLSessionCache         shmcb:/var/cache/mod_ssl/scache(512000)
SSLSessionCacheTimeout  300
SSLMutex default
SSLRandomSeed startup file:/dev/urandom  256
SSLRandomSeed connect builtin
SSLCryptoDevice builtin

LoadModule wsgi_module modules/mod_wsgi.so

<Directory /opt/sync-server/syncserver>
  Order deny,allow
  Allow from all
</Directory>

WSGISocketPrefix /var/run/wsgi
#WSGIPythonHome /opt/sync-server/syncserver/local/lib/python2.7
#WSGIPythonHome /opt/rh/python27/root/usr/bin/python

Listen 1443
<VirtualHost _default_:1443>
    ServerName firefox-vm.domain.local
    DocumentRoot /opt/sync-server/syncserver
    WSGIProcessGroup sync
    WSGIDaemonProcess sync user=firefox group=firefox processes=2 threads=25 python-path=/opt/sync-server/syncserver/local/lib/python2.7/site-packages/
    WSGIPassAuthorization On
    WSGIScriptAlias / /opt/sync-server/syncserver/syncserver.wsgi
    LogLevel warn
    SSLEngine on
    SSLProtocol all -SSLv2
    SSLCipherSuite ALL:!ADH:!EXPORT:!SSLv2:RC4+RSA:+HIGH:+MEDIUM:+LOW
    SSLCertificateFile /etc/pki/tls/domain/remote.domain.com-reissue.cer
    SSLCertificateKeyFile /etc/pki/tls/domain/remote.domain.com-reissue.key
    SSLCertificateChainFile /etc/pki/tls/domain/RapidSSL_CA_bundle.crt
    <Files ~ "\.(cgi|shtml|phtml|php3?)$">
        SSLOptions +StdEnvVars
    </Files>
    <Directory "/var/www/cgi-bin">
        SSLOptions +StdEnvVars
    </Directory>
    SetEnvIf User-Agent ".*MSIE.*" \
        nokeepalive ssl-unclean-shutdown \
        downgrade-1.0 force-response-1.0
    CustomLog logs/access_log_1443 combined
    ErrorLog logs/error_log_1443
</VirtualHost>

Listen 13030
<VirtualHost _default_:13030>
    ServerName firefox-vm.domain.local
    LogLevel warn
    SSLEngine on
    SSLProtocol all -SSLv2
    SSLCipherSuite ALL:!ADH:!EXPORT:!SSLv2:RC4+RSA:+HIGH:+MEDIUM:+LOW
    SSLCertificateFile /etc/pki/tls/domain/remote.domain.com-reissue.cer
    SSLCertificateKeyFile /etc/pki/tls/domain/remote.domain.com-reissue.key
    SSLCertificateChainFile /etc/pki/tls/domain/RapidSSL_CA_bundle.crt
    <Files ~ "\.(cgi|shtml|phtml|php3?)$">
        SSLOptions +StdEnvVars
    </Files>
    <Directory "/var/www/cgi-bin">
        SSLOptions +StdEnvVars
    </Directory>
    SetEnvIf User-Agent ".*MSIE.*" \
        nokeepalive ssl-unclean-shutdown \
        downgrade-1.0 force-response-1.0
    ProxyPass / http://localhost:3030/
    ProxyPassReverse / http://localhost:3030/
    CustomLog logs/access_log_13030 combined
    ErrorLog logs/error_log_13030
</VirtualHost>

Listen 19000
<VirtualHost _default_:19000>
    ServerName firefox-vm.domain.local
    LogLevel warn
    SSLEngine on
    SSLProtocol all -SSLv2
    SSLCipherSuite ALL:!ADH:!EXPORT:!SSLv2:RC4+RSA:+HIGH:+MEDIUM:+LOW
    SSLCertificateFile /etc/pki/tls/domain/remote.domain.com-reissue.cer
    SSLCertificateKeyFile /etc/pki/tls/domain/remote.domain.com-reissue.key
    SSLCertificateChainFile /etc/pki/tls/domain/RapidSSL_CA_bundle.crt
    <Files ~ "\.(cgi|shtml|phtml|php3?)$">
        SSLOptions +StdEnvVars
    </Files>
    <Directory "/var/www/cgi-bin">
        SSLOptions +StdEnvVars
    </Directory>
    SetEnvIf User-Agent ".*MSIE.*" \
        nokeepalive ssl-unclean-shutdown \
        downgrade-1.0 force-response-1.0
    ProxyPass / http://localhost:9000/
    ProxyPassReverse / http://localhost:9000/
    CustomLog logs/access_log_19000 combined
    ErrorLog logs/error_log_19000
</VirtualHost>
rfk commented 10 years ago

I guess what's going on is that the default remote verifier at verifier.accounts.firefox.com is trying to verify the assertion from your local install, but can't reach it to fetch the /.well-known/browserid file. One option is to run your own copy of the verifier server:

https://github.com/mozilla/browserid-verifier

And add a [browserid] section to your syncserver.ini, to configure it like this:

[browserid]
backend = tokenserver.verifiers.RemoteVerifier
verifier_url = url-of-your-self-hosted-verifier
audiences = your-public-url-with-no-trailing-slash

Slightly simpler might be to use the local verification capabilities of PyBrowserID, which is already included with the tokenserver codebase. There are some pending API/format changes between PyBrowserID and the hosted verifier, but for now it works fine and lets you avoid running Yet Another Server:

[browserid]
backend = tokenserver.verifiers.LocalVerifier
audiences = your-public-url-with-no-trailing-slash
Fmstrat commented 10 years ago

Thanks @rfk. This issue might make sense to put an update into the default syncserver.ini file that users receive to ensure they don't have the same issue.

That being said, the above change didn't seem to work for me. I added this to my syncserver.ini file:

[browserid]
backend = tokenserver.verifiers.LocalVerifier
audiences = https://firefox-vm.domain.local:1443

However, the Firefox Sync error log now shows:

1406209157497   Sync.Status DEBUG   Status.service: success.status_ok => success.status_ok
1406209157497   Sync.Status DEBUG   Status.service: success.status_ok => success.status_ok
1406209157509   FirefoxAccounts DEBUG   got keyPair
1406209157509   FirefoxAccounts DEBUG   getCertificateSigned: true true
1406209157510   Sync.Tracker.Clients    WARN    Changed IDs file clients contains non-object value.
1406209157537   Sync.Tracker.Passwords  WARN    Changed IDs file passwords contains non-object value.
1406209157538   Sync.Tracker.Addons WARN    Changed IDs file addons contains non-object value.
1406209157675   FirefoxAccounts DEBUG   (Response) /certificate/sign: code: 200 - Status text: OK
1406209157675   FirefoxAccounts DEBUG   Clock offset vs https://firefox-vm.nowsci.local:15900/v1: -675
1406209157676   FirefoxAccounts DEBUG   getCertificate got a new one: true
1406209157676   FirefoxAccounts DEBUG   getAssertionFromCert
1406209157678   FirefoxAccounts DEBUG   getAssertionFromCert returning signed: true
1406209157678   Sync.BrowserIDManager   DEBUG   Getting a token
1406209157692   Sync.BrowserIDManager   ERROR   Non-authentication error in _fetchTokenForUser: Client error.
1406209157692   Sync.Status DEBUG   Status.login: success.login => error.login.reason.network
1406209157692   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1406209157692   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1406209157693   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms.

It no longer attempts to connect to the remote server, but still errors out. Since this is running through WSGI as the apache user, where would the /.well-known/browserid file be? It doesn't seem to get created on my system. Time-sync seems OK, as I've heard this issue has occurred because of that, too.

Fmstrat commented 10 years ago

I found the fix to work once the public URL matched a hostname valid for the SSL cert, so the above recommendation worked. I've created a pull request that adds some pre-commented elements to syncserver.ini to make this more clear for future administrators. Thanks!

Pull request: https://github.com/mozilla-services/syncserver/pull/34