Potential "audience mismatch" error when running behind TLS-terminating reverse proxy

[1wilkens]

Hi,

I am running syncserver in docker with user authentication via the default https://account.mozilla.com server. Today I upgraded from an ancient version and Firefox does not longer sync and instead immediately prompts to reconnect to sync.

I tried to identify the issue suspecting db schema changes but eventually tracked it down to the syncserver return 401 Unauthorized responses although my login is clearly valid on https://accounts.firefox.com. Unfortunately the logging output of the syncserver is very sparse, revealing nothing about the failing requests while the about:sync-log is so verbose that I had trouble even finding the 401.

I also tried native serving via make serve instead of docker for the same result. Interestingly make test runs just fine while I am not able to make the tests pass on either my docker or native server which both fail with a traceback ultimately pointing to requests.exceptions.HTTPError: 401 Client Error: Unauthorized for url: http://localhost:5000/token/1.0/sync/1.5 Is the test suite supposed to fail on real setups as the user is invalid?

To run the tests I ran: /local/bin/python -m syncstorage.tests.functional.test_storage --use-token-server http://localhost:5000/token/1.0/sync/1.5/ as shown in the Makefile.

Is there any way to increase logging for syncserver to investigate this issue? I have no idea where to start to look for the offending code =/

Let me know if there is anything more I can provide to narrow down the issue. If desired I can post an example sync-log but I am not sure if that helps.

EDIT: After changing the log level in syncserver/__init__.py:136 to Info, I found the following:

INFO:mozsvc.metrics:{"code": 401, "request_time": 0.0019838809967041016, "remoteAddressChain": ["172.17.0.1"], "agent": "python-requests/2.13.0", "token.assertion.audience_mismatch_error": 1, "token.assertion.verify_failure": 1, "tokenserver.assertion.verify": 0.00024199485778808594, "path": "http://<redacted>/token/1.0/sync/1.5", "method": "GET"}

which indicates a problem with the audience value? I saw that this value is configurable in the tests but I am not sure what is expected here, any ideas?

[rfk]

Could you please post your syncserver.ini config file, with any secrets etc removed?

Is the test suite supposed to fail on real setups as the user is invalid?

Yes; the test suite uses identity assertions for a dummy domain, so they won't pass if it's configured for real-life use.

[1wilkens]

As I used to run syncserver in docker, I configured everything through env variables (/var/syncserver is a docker volume).

SYNCSERVER_PUBLIC_URL=http://ff.mydomain.com
SYNCSERVER_SECRET=<redacted>
SYNCSERVER_SQLURI=sqlite:////var/syncserver/syncserver.db
SYNCSERVER_BATCH_UPLOAD_ENABLED=true

I tried to replicate above settings in syncserver.ini (comments stripped). sqluri is set to memory for easier testing

[server:main]
use = egg:gunicorn
host = 0.0.0.0
port = 5000
workers = 1
timeout = 30

[app:main]
use = egg:SyncServer

[syncserver]
public_url = http://ff.mydomain.com
sqluri = sqlite:///:memory:

secret = <redacted>

I tried both testing via the real domain (docker/make serve behind an nginx reverse proxy) and via localhost with force_wsgi_environ=true both resulting in the above error messages.

EDIT: I just tried both the Firefox sync and test again against both version even after a password change on https://accounts.firefox.com and both with and without "identity_provider" set, all resulting in the same error..

EDIT2: After searching the sync-logs I found the following parts. First Firefox tries to sync and receives 401.

1534868689626   Services.Common.RESTRequest TRACE   onStartRequest: GET https://ff.1wilkens.org/token/1.0/sync/1.5
1534868689626   Services.Common.RESTRequest TRACE   Channel for GET https://ff.1wilkens.org/token/1.0/sync/1.5 returned status code 0
1534868689626   Services.Common.RESTRequest DEBUG   GET https://ff.mydomain.com/token/1.0/sync/1.5 401
1534868689626   Services.Common.RESTRequest TRACE   GET body: {"status": "invalid-credentials", "errors": [{"location": "body", "name": "", "description": "Unauthorized"}]}
1534868689626   Services.Common.TokenServerClient   DEBUG   Got token response: 401
1534868689626   Services.Common.RESTResponse    TRACE   Processing response headers.
1534868689627   Services.Common.TokenServerClient   INFO    Server-reported error: {"location":"body","name":"","description":"Unauthorized"}
1534868689627   Sync.BrowserIDManager   WARN    Token server returned 401, refreshing certificate and retrying token fetch

Next it tries to refresh the token and cert as described which suceeds!

1534868689836   Services.Common.RESTRequest TRACE   onStartRequest: POST https://oauth.accounts.firefox.com/v1/authorization
1534868689840   Services.Common.RESTRequest TRACE   Channel for POST https://oauth.accounts.firefox.com/v1/authorization returned status code 0
1534868689840   Services.Common.RESTRequest DEBUG   POST https://oauth.accounts.firefox.com/v1/authorization 200
1534868689840   Services.Common.RESTRequest TRACE   POST body: {"access_token":"<redacted>","token_type":"bearer","expires_in":1209599,"scope":"profile","auth_at":1534868687}
1534868689843   Services.Common.RESTRequest DEBUG   GET request to https://profile.accounts.firefox.com/v1/profile
1534868689843   Services.Common.RESTRequest TRACE   HTTP Header authorization: ***** (suppressed)
1534868689843   Services.Common.RESTRequest TRACE   HTTP Header accept: application/json
1534868689846   FirefoxAccounts DEBUG   _updateAccountData with items: ["oauthTokens"]
1534868689847   FirefoxAccounts DEBUG   writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens"]
1534868689848   FirefoxAccounts TRACE   starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens"]
1534868689858   Services.Common.RESTRequest TRACE   onStartRequest: POST https://api.accounts.firefox.com/v1/certificate/sign
1534868689859   Services.Common.RESTRequest TRACE   Channel for POST https://api.accounts.firefox.com/v1/certificate/sign returned status code 0
1534868689859   Services.Common.RESTRequest DEBUG   POST https://api.accounts.firefox.com/v1/certificate/sign 200
1534868689859   Services.Common.RESTRequest TRACE   POST body: {"cert":"<redacted>"}
1534868689859   Hawk    DEBUG   (Response) /certificate/sign: code: 200 - Status text: OK
1534868689860   Services.Common.RESTResponse    TRACE   Processing response headers.
1534868689860   Hawk    DEBUG   Clock offset vs https://api.accounts.firefox.com/v1: -860
1534868689860   FirefoxAccounts DEBUG   getCertificate got a new one: true

But the following request to syncserver fails with the same error.

1534868689889   Services.Common.RESTRequest TRACE   onStartRequest: GET https://ff.1wilkens.org/token/1.0/sync/1.5
1534868689890   Services.Common.RESTRequest TRACE   Channel for GET https://ff.1wilkens.org/token/1.0/sync/1.5 returned status code 0
1534868689890   Services.Common.RESTRequest DEBUG   GET https://ff.mydomain.com/token/1.0/sync/1.5 401
1534868689890   Services.Common.RESTRequest TRACE   GET body: {"status": "invalid-credentials", "errors": [{"location": "body", "name": "", "description": "Unauthorized"}]}
1534868689890   Services.Common.TokenServerClient   DEBUG   Got token response: 401
1534868689890   Services.Common.RESTResponse    TRACE   Processing response headers.
1534868689891   Services.Common.TokenServerClient   INFO    Server-reported error: {"location":"body","name":"","description":"Unauthorized"}
1534868689891   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: {"details":{"now":"2018-08-21T16:24:49.891Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"nginx","date":"Tue, 21 Aug 2018 16:24:49 GMT","content-type":"application/json; charset=UTF-8","content-length":"110","x-weave-timestamp":"1534868689.88","x-timestamp":"1534868689","x-firefox-spdy":"h2"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1534868689892   Sync.Status DEBUG   Status.login: success.login => error.login.reason.account
1534868689892   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1534868689893   Sync.BrowserIDManager   INFO    Failed to fetch the cluster URL: {"details":{"now":"2018-08-21T16:24:49.891Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"nginx","date":"Tue, 21 Aug 2018 16:24:49 GMT","content-type":"application/json; charset=UTF-8","content-length":"110","x-weave-timestamp":"1534868689.88","x-timestamp":"1534868689","x-firefox-spdy":"h2"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1534868689893   Sync.BrowserIDManager   DEBUG   Cluster value = null
1534868689893   Sync.Status DEBUG   Status.sync: success.sync => error.sync.reason.no_node_found
1534868689893   Sync.Status DEBUG   Status.service: error.login.failed => error.sync.failed

Any more ideas? ;)

[rfk]

You have this as http in your config:

SYNCSERVER_PUBLIC_URL=http://ff.mydomain.com public_url = http://ff.mydomain.com

But Firefox is talking to it over https:

GET https://ff.mydomain.com/token/1.0/sync/1.5

That likely explains the "audience mismatch" error, Firefox will be sending an identity assertion meant for "https://ff.mydomain.com" but the server will be expecting t to match "http://ff.mydomain.com".

[1wilkens]

Well TLS is terminated the reverse proxy. I initially set the PUBLIC_URL to https and syncserver complained that it got http (from nginx) so I changed it. However I don't think that's the root of the problem as syncserver does not accept any requests if configured that way without force_wsgi_environ=true set.

[rfk]

Does it work if public_url uses https and force_wsgi_environ is set to true?

[1wilkens]

I just had the same idea.. Yeah that works, although I am 100% sure it used to work the other way before. Thanks for your quick help. Should we close this or should we leave it open to warn others about this behaviour?

I would think that running behing a reverse proxy is common practice and the error message definitely does not hint at the actual problem (neither the one in Firefox, the one given by syncserver when the mismatch is detected and when the sync fails).

[rfk]

I would think that running behing a reverse proxy is common practice

Ideally, the reverse proxy will inject special headers like X-Forwarded-Proto into the request, and the downstream app will use them to reconstruct what its public-facing URI is supposed to be. For example, here's how the gunicorn docs recommend doing this for nginx:

https://github.com/benoitc/gunicorn/blob/9cf5b13f93a3ac712cbabb3b41e34eb6ec9d5eb6/docs/source/deploy.rst#nginx-configuration

You may find that by tweaking your nginx config and/or your gunicorn command-line options according to the above guide, you can get the app to correctly determine its own public_url and then flip force_wsgi_environ back to false.

[rfk]

I'm also open to improving the error message here:

https://github.com/mozilla-services/syncserver/blob/master/syncserver/__init__.py#L230

So that it helps point users in this direction, if you have suggestions.

[1wilkens]

My nginx configuration already set the header but gunicorn did not respect it due to it not originating from localhost (because of the docker setup). The fix is to tell gunicorn about trusted remote ips via a commandline argument. I setup a PR to make this argument configurable through an env variable and while it probably needs a small note in README.md as well it works for my setup.

[rfk]

Aha, that explains it. Do you happen to know if docker uses a small set of known IP addresses that we could allow by default?

[1wilkens]

AFAIK each docker network is a local /16 subnet under '172' beginning at '172.17/16" with the host machine being the standard gateway at '172.17.0.1'. For most setups this IP should be enough (and is indeed for my setup). Additionally docker allows for complete customization of subnets and IP addresses but users of these features probably already know what they are doing anyways. I could add the '172.17.0.1' to the list of allowed IPs in the PR. As that is a local IP it should be okay to do so unconditionally I think.

[rfk]

I could add the '172.17.0.1' to the list of allowed IPs in the PR. As that is a local IP it should be okay to do so unconditionally I think.

This sounds good to me, thanks!

[sehucke]

The trusted reverse proxy IP address should be configurable. By default, Docker assigns IP addresses (ranges as well es single IPs) automatically at container/network startup. It depends on startup order which segment you get. And this could change when you do updates. When you use docker-compose with network segmentation each network gets its own 172.x.0.0 address range.

[republicus]

I'm not using docker but instead lxc containers for various services. I'm not interested in changing my entire network manually to see syncserver run more natively... I agree that the forwarded-ips should be configurable or somehow include all RFC1918 addresses:

10.0.0.0/8
172.16.0.0/12
192.168.0.0/16

I was having the same issue using a reverse proxy via apache's mod_proxy But, from this issue I was able to get it working by modifying how gunicorn starts. Thanks rfk and 1wilkens

I researched more than i probably should have to get this going so ill share for posterity if that's okay:

Change directory into your syncserver folder and change the allowed ips to include your reverse proxy host: ./local/bin/gunicorn_paster --forwarded-allow-ips "127.0.0.1,10.0.0.10" syncserver.ini

The only information I found concerning reverse proxies and overcoming common problems with syncserver was for Nginx. This is my reverse proxy config in apache with mod_proxy et al. Note: CentOS 7 Apache HTTPD needs updated to support the necessary setting of the headers.. I used the CodeIT repo which brought me to --version 2.4.38

<VirtualHost *:443>
ServerName sync.example.com

       <Proxy *>
        Order deny,allow
        Allow from all
       </Proxy>

SSLEngine On
SSLProxyEngine On
SSLCertificateFile /path/to/cert.cer
SSLCertificateKeyFile /path/to/priv.key

RequestHeader set X-Forwarded-Proto https
RequestHeader set X-Forwarded-Proto expr=%{REQUEST_SCHEME}
RequestHeader set X-Forwarded-Port 443

ProxyRequests Off
ProxyPreserveHost On
ProxyPass / http://10.0.0.10:5000/
ProxyPassReverse / http://10.0.0.10:5000/
</VirtualHost>

[rfk]

Thanks for sharing! If you feel inspired, I'd be happy to review a PR to add this into the self-hosting docs here:

https://github.com/mozilla-services/docs/blob/master/source/howtos/run-sync-1.5.rst#apache--mod_wsgi

The existing sample config there is probably quite out of date.