search

mozilla-services / syncserver

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

DependencyWarning chardet and urllib3 #233

Open Emporea opened 4 years ago

Emporea commented 4 years ago

After starting the latest server version (after PR #230) this pop up in the logs, and the sync still doesnt work. But I dont know if Its because of this.

/usr/local/lib/python2.7/site-packages/requests/init.py:91: RequestsDependencyWarning: urllib3 (1.25.2) or chardet (3.0.4) doesn't match a supported version! syncserver_1 | RequestsDependencyWarning)

rfk commented 4 years ago

the sync still doesnt work.

If it's just a warning, then I'm hopeful that this isn't the cause of the problem.

Do you have any error logs in about:sync-log on your Firefox that might help understand what error it's getting? (Sorry if you posted such things in other bugs, I'm having a bit of trouble following the different threads).

Emporea commented 4 years ago

401: login failed.

1599541688419   Sync.LogManager DEBUG   Flushing file log
1599541688429   Sync.LogManager DEBUG   Log cleanup threshold time: 1598677688429
1599541688438   Sync.LogManager DEBUG   Done deleting files.
1599541814852   Sync.RemoteTabs INFO    Generating tab list with filter
1599541814852   Sync.RemoteTabs INFO    Final tab list has 0 clients with 0 tabs.
1599541874162   FirefoxAccounts INFO    Polling device commands.
1599541874164   Sync.Service    DEBUG   In sync: should login.
1599541874164   Sync.Service    INFO    User logged in successfully - verifying login.
1599541874165   FirefoxAccounts DEBUG   FxAccountsProfileClient: Requested profile
1599541874165   FirefoxAccounts DEBUG   getOAuthToken enter
1599541874165   FirefoxAccounts TRACE   getCachedToken returning cached token
1599541874165   FirefoxAccounts DEBUG   getOAuthToken returning a cached token
1599541874165   Sync.BrowserIDManager   DEBUG   unlockAndVerifyAuthState already has (or can fetch) sync keys
1599541874165   Sync.Status DEBUG   Status.login: error.login.reason.network => success.status_ok
1599541874165   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1599541874165   Sync.Service    DEBUG   Fetching unlocked auth state returned success.status_ok
1599541874166   Services.Common.RESTRequest DEBUG   GET request to https://profile.accounts.firefox.com/v1/profile
1599541874170   Services.Common.RESTRequest DEBUG   GET request to https://api.accounts.firefox.com/v1/account/device/commands?index=0
1599541874206   Sync.Resource   DEBUG   GET fail 401 https://sync.example.tld/storage/1.5/1/info/collections
1599541874206   Sync.Resource   WARN    GET request to https://sync.example.tld/storage/1.5/1/info/collections failed with status 401
1599541874206   Sync.Service    WARN    401: login failed.
1599541874206   Sync.BrowserIDManager   DEBUG   _findCluster has a pre-existing clusterURL, so fetching a new token token
1599541874207   Sync.BrowserIDManager   INFO    Getting keys
1599541874208   Sync.BrowserIDManager   INFO    Getting an assertion from: https://sync.example.tld/token/1.0/sync/1.5
1599541874208   Sync.BrowserIDManager   DEBUG   Getting a token using OAuth
1599541874208   FirefoxAccounts DEBUG   getAccessToken enter
1599541874208   FirefoxAccounts DEBUG   getOAuthToken enter
1599541874208   FirefoxAccounts TRACE   getCachedToken returning cached token
1599541874208   FirefoxAccounts DEBUG   getOAuthToken returning a cached token
1599541874208   FirefoxAccounts DEBUG   Using cached scopedKeys data for https://identity.mozilla.com/apps/oldsync
1599541874209   Services.Common.TokenServerClient   DEBUG   Beginning OAuth token exchange: https://sync.example.tld/token/1.0/sync/1.5
1599541874209   Services.Common.RESTRequest DEBUG   GET request to https://sync.example.tld/token/1.0/sync/1.5
1599541874846   Services.Common.RESTRequest DEBUG   GET https://api.accounts.firefox.com/v1/account/device/commands?index=0 200
1599541874846   Hawk    DEBUG   (Response) /account/device/commands?index=0: code: 200 - Status text: OK
1599541874846   Hawk    DEBUG   Clock offset vs https://api.accounts.firefox.com/v1: -846
1599541875044   Services.Common.RESTRequest DEBUG   GET https://sync.example.tld/token/1.0/sync/1.5 200
1599541875044   Services.Common.TokenServerClient   DEBUG   Got token response: 200
1599541875044   Services.Common.TokenServerClient   DEBUG   Successful token response
1599541875044   Sync.Status DEBUG   Status.login: success.status_ok => success.login
1599541875044   Sync.Status DEBUG   Status.service: error.login.failed => success.status_ok
1599541875045   Sync.BrowserIDManager   DEBUG   _findCluster returning https://sync.example.tld/storage/1.5/1/
1599541875045   Sync.BrowserIDManager   DEBUG   Cluster value = https://sync.example.tld/storage/1.5/1/
1599541875046   Sync.Status DEBUG   Status.login: success.login => error.login.reason.network
1599541875046   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1599541875046   Sync.ErrorHandler   ERROR   Sync encountered a login error
1599541875046   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1599541875047   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms. (why=schedule)
1599541875048   Sync.Service    DEBUG   Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.js:1043:15) JS Stack trace: onNotify@service.js:1043:15
1599541875048   Sync.Service    DEBUG   Not syncing: login returned false.
rfk commented 4 years ago

1599541875044 Services.Common.RESTRequest DEBUG GET https://sync.example.tld/token/1.0/sync/1.5 200 1599541875044 Services.Common.TokenServerClient DEBUG Got token response: 200 1599541875044 Services.Common.TokenServerClient DEBUG Successful token response

These indicate that your browser successfully got a token from the /token endpoint, so I think this is a different error to the ones reported in other bugs.

In your syncserver.ini, have you configured a secret key in the part that says INSERT_SECRET_KEY_HERE? The server is supposed to be able to run without this configured, but putting your own secret in there is more reliable.

Emporea commented 4 years ago

I am not using the syncserver.ini but an enviromental variable in a docker-compose.yml file.

rfk commented 4 years ago

Could you please try signing out of the browser, restarting Firefox, then signing back in, and grab the error log produced by doing so? It might have some more clues about what's going wrong here that are hard to tell from the above snipping (which looks like it's from an already-signed-in browser).

I also recently merged https://github.com/mozilla-services/syncserver/pull/228, if you wait for a fresh docker image that has that included and then try setting SYNCSERVER_DEBUG_ENABLED=true in your environment, it might give more info on the server side.

Emporea commented 4 years ago

This is my docker container with debug on

syncserver_1  | /usr/local/lib/python2.7/site-packages/requests/__init__.py:91: RequestsDependencyWarning: urllib3 (1.25.2) or chardet (3.0.4) doesn't match a supported version!
syncserver_1  |   RequestsDependencyWarning)
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Created new connection <sqlite3.Connection object at 0x7fb6aaf00990>
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> checked out from pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> being returned to pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> rollback-on-return
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> checked out from pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> being returned to pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> rollback-on-return
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> checked out from pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> being returned to pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> rollback-on-return
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> checked out from pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> being returned to pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> rollback-on-return
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> checked out from pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> being returned to pool
syncserver_1  | DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fb6aaf00990> rollback-on-return
syncserver_1  | INFO:mozsvc.metrics:{"code": 401, "request_time": 0.0016179084777832031, "remoteAddressChain": ["...", "..."], "agent": "Firefox/80.0.1 (Windows NT 10.0; Win64; x64) FxSync/1.82.0.20200831163820.desktop", "path": "https://sync.example.tld/storage/1.5/1/info/collections", "method": "GET"}
syncserver_1  | DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): oauth.accounts.firefox.com:443
syncserver_1  | DEBUG:urllib3.connectionpool:https://oauth.accounts.firefox.com:443 "GET /v1/jwks HTTP/1.1" 200 463
syncserver_1  | INFO:mozsvc.metrics:{"tokenserver.backend.get_user": ... , "code": 200, "uid": "...", "metrics_uid": "...", "metrics_device_id": "...", "remoteAddressChain": ["...", "..."], "agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:80.0) Gecko/20100101 Firefox/80.0", "token.oauth.verify_success": 1, "request_time": 0.7687039375305176, "email": "...@api.accounts.firefox.com", "node_type": null, "tokenserver.backend.update_user": ..., "path": "https://sync.example.tld/token/1.0/sync/1.5", "method": "GET", "tokenserver.oauth.verify": ..., "uid.first_seen_at": ...}

And these are my Firefox sync logs after signing out, restarting and signing in again ( I also did that before )

1599542840620   Sync.LogManager DEBUG   Flushing file log
1599542840628   Sync.LogManager DEBUG   Log cleanup threshold time: 1598678840628
1599542840631   Sync.LogManager DEBUG   Done deleting files.
1599542845291   FirefoxAccounts INFO    Polling device commands.
1599542845291   Sync.Service    DEBUG   User-Agent: Firefox/80.0.1 (Windows NT 10.0; Win64; x64) FxSync/1.82.0.20200831163820.desktop
1599542845291   Sync.Service    INFO    Starting sync at 2020-09-08 07:27:25 in browser session 7QMClk3NVotS
1599542845291   Sync.Service    DEBUG   In sync: should login.
1599542845291   Sync.Service    INFO    User logged in successfully - verifying login.
1599542845292   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599542845292   Sync.BrowserIDManager   DEBUG   unlockAndVerifyAuthState already has (or can fetch) sync keys
1599542845292   Sync.Status DEBUG   Status.login: error.login.reason.network => success.status_ok
1599542845293   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1599542845293   Sync.Service    DEBUG   Fetching unlocked auth state returned success.status_ok
1599542845293   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599542845299   Services.Common.RESTRequest DEBUG   GET request to https://api.accounts.firefox.com/v1/account/device/commands?index=0
1599542845335   Sync.Resource   DEBUG   GET fail 401 https://sync.example.tld/storage/1.5/1/info/collections
1599542845335   Sync.Resource   WARN    GET request to https://sync.example.tld/storage/1.5/1/info/collections failed with status 401
1599542845336   Sync.Service    WARN    401: login failed.
1599542845336   Sync.BrowserIDManager   DEBUG   _findCluster has a pre-existing clusterURL, so fetching a new token token
1599542845336   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599542845336   Sync.BrowserIDManager   INFO    Getting keys
1599542845336   Sync.BrowserIDManager   INFO    Getting an assertion from: https://sync.example.tld/token/1.0/sync/1.5
1599542845336   Sync.BrowserIDManager   DEBUG   Getting a token using OAuth
1599542845336   FirefoxAccounts DEBUG   getAccessToken enter
1599542845336   FirefoxAccounts DEBUG   getOAuthToken enter
1599542845336   FirefoxAccounts TRACE   getCachedToken returning cached token
1599542845336   FirefoxAccounts DEBUG   getOAuthToken returning a cached token
1599542845336   FirefoxAccounts DEBUG   Using cached scopedKeys data for https://identity.mozilla.com/apps/oldsync
1599542845337   Services.Common.TokenServerClient   DEBUG   Beginning OAuth token exchange: https://sync.example.tld/token/1.0/sync/1.5
1599542845337   Services.Common.RESTRequest DEBUG   GET request to https://sync.example.tld/token/1.0/sync/1.5
1599542845587   Services.Common.RESTRequest DEBUG   GET https://api.accounts.firefox.com/v1/account/device/commands?index=0 200
1599542845587   Hawk    DEBUG   (Response) /account/device/commands?index=0: code: 200 - Status text: OK
1599542845587   Hawk    DEBUG   Clock offset vs https://api.accounts.firefox.com/v1: -587
1599542845619   Services.Common.RESTRequest DEBUG   GET https://sync.example.tld/token/1.0/sync/1.5 200
1599542845619   Services.Common.TokenServerClient   DEBUG   Got token response: 200
1599542845619   Services.Common.TokenServerClient   DEBUG   Successful token response
1599542845619   Sync.Status DEBUG   Status.login: success.status_ok => success.login
1599542845620   Sync.Status DEBUG   Status.service: error.login.failed => success.status_ok
1599542845620   Sync.BrowserIDManager   DEBUG   _findCluster returning https://sync.example.tld/storage/1.5/1/
1599542845620   Sync.BrowserIDManager   DEBUG   Cluster value = https://sync.example.tld/storage/1.5/1/
1599542845620   Sync.Status DEBUG   Status.login: success.login => error.login.reason.network
1599542845620   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1599542845620   Sync.ErrorHandler   ERROR   Sync encountered a login error
1599542845620   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1599542845621   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms. (why=schedule)
1599542845621   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599542845622   Sync.Service    DEBUG   Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.js:1043:15) JS Stack trace: onNotify@service.js:1043:15
1599542845622   Sync.Service    DEBUG   Not syncing: login returned false.
1599542845622   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent

Edit: Just to add some more info. Additional docker environment variables I have are:

gu1ll0me commented 4 years ago

Same problem on my side, clients not syncing. I tried to delete the old database, signing out, restarting Firefox and signing back with no success.

Client:

1599606218194   Sync.LogManager DEBUG   Flushing file log
1599606218194   Sync.LogManager TRACE   Beginning stream copy to error-sync-1599606218194.txt: 1599606218194
1599606218201   Sync.LogManager TRACE   finished copy to: /home/USER/.mozilla/firefox/PROFILE/weave/logs/error-sync-1599606218194.txt
1599606218201   Sync.LogManager TRACE   onCopyComplete: 1599606218201
1599606218201   Sync.LogManager TRACE   Running cleanup.
1599606218201   Sync.LogManager DEBUG   Log cleanup threshold time: 1597014218201
1599606218203   Sync.LogManager DEBUG   Done deleting files.
1599606221191   Sync.Engine.Tabs.Tracker    TRACE   onTab event: TabSelect
1599606221191   Sync.SyncScheduler  TRACE   Handling weave:engine:score:updated
1599606221192   Sync.Engine.Tabs.Tracker    TRACE   onTab event: TabClose
1599606221192   Sync.SyncScheduler  TRACE   Handling weave:engine:score:updated
1599606240244   FirefoxAccounts INFO    Polling device commands.
1599606240244   Sync.Service    DEBUG   User-Agent: Firefox/80.0.1 (Linux x86_64) FxSync/1.82.0.20200831163820.desktop
1599606240244   Sync.Service    INFO    Starting sync at 2020-09-08 19:04:00 in browser session bG0DjAAwaxkz
1599606240244   Sync.Service    DEBUG   In sync: should login.
1599606240244   Sync.Service    TRACE   Event: weave:service:login:start
1599606240244   Sync.Service    INFO    User logged in successfully - verifying login.
1599606240245   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599606240245   Sync.BrowserIDManager   DEBUG   unlockAndVerifyAuthState already has (or can fetch) sync keys
1599606240245   Sync.Status DEBUG   Status.login: error.login.reason.network => success.status_ok
1599606240245   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1599606240245   Sync.Service    DEBUG   Fetching unlocked auth state returned success.status_ok
1599606240245   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599606240245   Sync.BrowserIDManager   TRACE   _ensureValidToken already has one
1599606240247   Services.Common.RESTRequest DEBUG   GET request to https://api.accounts.firefox.com/v1/account/device/commands?index=0
1599606240252   Sync.Resource   DEBUG   GET fail 401 https://DOMAIN/storage/1.5/1/info/collections
1599606240252   Sync.Resource   WARN    GET request to https://DOMAIN/storage/1.5/1/info/collections failed with status 401
1599606240252   Sync.Service    WARN    401: login failed.
1599606240252   Sync.BrowserIDManager   DEBUG   _findCluster has a pre-existing clusterURL, so fetching a new token token
1599606240252   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599606240252   Sync.BrowserIDManager   INFO    Getting keys
1599606240253   Sync.BrowserIDManager   INFO    Getting an assertion from: https://DOMAIN/token/1.0/sync/1.5
1599606240253   Sync.BrowserIDManager   DEBUG   Getting a token using OAuth
1599606240253   FirefoxAccounts DEBUG   getAccessToken enter
1599606240253   FirefoxAccounts DEBUG   getOAuthToken enter
1599606240253   FirefoxAccounts TRACE   getCachedToken returning cached token
1599606240253   FirefoxAccounts DEBUG   getOAuthToken returning a cached token
1599606240253   FirefoxAccounts DEBUG   Using cached scopedKeys data for https://identity.mozilla.com/apps/oldsync
1599606240253   Services.Common.TokenServerClient   DEBUG   Beginning OAuth token exchange: https://DOMAIN/token/1.0/sync/1.5
1599606240253   Services.Common.RESTRequest DEBUG   GET request to https://DOMAIN/token/1.0/sync/1.5
1599606240258   Services.Common.RESTRequest DEBUG   GET https://DOMAIN/token/1.0/sync/1.5 200
1599606240258   Services.Common.TokenServerClient   DEBUG   Got token response: 200
1599606240258   Services.Common.TokenServerClient   DEBUG   Successful token response
1599606240258   Sync.BrowserIDManager   TRACE   Successfully got a token
1599606240258   Sync.Status DEBUG   Status.login: success.status_ok => success.login
1599606240258   Sync.Status DEBUG   Status.service: error.login.failed => success.status_ok
1599606240258   Sync.Telemetry  TRACE   observed weave:service:login:change null
1599606240258   Sync.Telemetry  TRACE   Not sending telemetry ping for self-hosted Sync user
1599606240259   Sync.BrowserIDManager   DEBUG   _findCluster returning https://DOMAIN/storage/1.5/1/
1599606240259   Sync.BrowserIDManager   DEBUG   Cluster value = https://DOMAIN/storage/1.5/1/
1599606240259   Sync.Status DEBUG   Status.login: success.login => error.login.reason.network
1599606240259   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1599606240259   Sync.Service    TRACE   Event: weave:service:login:error
1599606240259   Sync.ErrorHandler   TRACE   Handling weave:service:login:error
1599606240259   Sync.ErrorHandler   ERROR   Sync encountered a login error
1599606240259   Sync.SyncScheduler  TRACE   Handling weave:service:login:error
1599606240259   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1599606240259   Sync.SyncScheduler  TRACE   _checkSync returned "".
1599606240259   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms. (why=schedule)
1599606240260   FirefoxAccounts TRACE   not checking freshness of profile as it remains recent
1599606240260   Sync.Service    DEBUG   Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.js:1043:15) JS Stack trace: onNotify@service.js:1043:15
1599606240260   Sync.Service    DEBUG   Not syncing: login returned false.

Server:

[2020-09-08 23:02:31 +0000] [6] [INFO] Starting gunicorn 19.6.0
[2020-09-08 23:02:31 +0000] [6] [INFO] Listening at: http://0.0.0.0:5000 (6)
[2020-09-08 23:02:31 +0000] [6] [INFO] Using worker: sync
[2020-09-08 23:02:31 +0000] [14] [INFO] Booting worker with pid: 14
/usr/local/lib/python2.7/site-packages/requests/__init__.py:91: RequestsDependencyWarning: urllib3 (1.25.2) or chardet (3.0.4) doesn't match a supported version!
  RequestsDependencyWarning)
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Created new connection <sqlite3.Connection object at 0x7fe82230f990>
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> checked out from pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> being returned to pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> rollback-on-return
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> checked out from pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> being returned to pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> rollback-on-return
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> checked out from pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> being returned to pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> rollback-on-return
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> checked out from pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> being returned to pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> rollback-on-return
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> checked out from pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> being returned to pool
DEBUG:syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog:Connection <sqlite3.Connection object at 0x7fe82230f990> rollback-on-return
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): oauth.accounts.firefox.com:443
DEBUG:urllib3.connectionpool:https://oauth.accounts.firefox.com:443 "GET /v1/jwks HTTP/1.1" 200 463
INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.00037789344787597656, "code": 200, "uid": "df8867c26669f803ea0b20be20cc01ca2ade0af1f50d265f371896a62084777c", "metrics_uid": "df8867c26669f803ea0b20be20cc01ca", "metrics_device_id": "2cb92871af5e8b28201f1c1765602a47", "remoteAddressChain": ["IP"], "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:80.0) Gecko/20100101 Firefox/80.0", "token.oauth.verify_success": 1, "request_time": 0.09323906898498535, "email": "56e4766d042d456faa6aa05b332b02fa@api.accounts.firefox.com", "node_type": null, "path": "https://DOMAIN/token/1.0/sync/1.5", "method": "GET", "tokenserver.oauth.verify": 0.09223580360412598, "uid.first_seen_at": 1599606187456}
INFO:mozsvc.metrics:{"code": 401, "request_time": 0.0007147789001464844, "remoteAddressChain": ["IP"], "agent": "Firefox/80.0.1 (Linux x86_64) FxSync/1.82.0.20200831163820.desktop", "path": "https://DOMAIN/storage/1.5/1/info/collections", "method": "GET"}
INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.0003421306610107422, "code": 200, "uid": "df8867c26669f803ea0b20be20cc01ca2ade0af1f50d265f371896a62084777c", "metrics_uid": "df8867c26669f803ea0b20be20cc01ca", "metrics_device_id": "2cb92871af5e8b28201f1c1765602a47", "remoteAddressChain": ["IP"], "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:80.0) Gecko/20100101 Firefox/80.0", "token.oauth.verify_success": 1, "request_time": 0.000926971435546875, "email": "56e4766d042d456faa6aa05b332b02fa@api.accounts.firefox.com", "node_type": null, "path": "https://DOMAIN/token/1.0/sync/1.5", "method": "GET", "tokenserver.oauth.verify": 5.1021575927734375e-05, "uid.first_seen_at": 1599606187456}
INFO:mozsvc.metrics:{"code": 401, "request_time": 0.0005648136138916016, "remoteAddressChain": ["IP"], "agent": "Firefox/80.0.1 (Linux x86_64) FxSync/1.82.0.20200831163820.desktop", "path": "https://DOMAIN/storage/1.5/1/info/collections", "method": "GET"}
INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.0003840923309326172, "code": 200, "uid": "df8867c26669f803ea0b20be20cc01ca2ade0af1f50d265f371896a62084777c", "metrics_uid": "df8867c26669f803ea0b20be20cc01ca", "metrics_device_id": "2cb92871af5e8b28201f1c1765602a47", "remoteAddressChain": ["IP"], "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:80.0) Gecko/20100101 Firefox/80.0", "token.oauth.verify_success": 1, "request_time": 0.001071929931640625, "email": "56e4766d042d456faa6aa05b332b02fa@api.accounts.firefox.com", "node_type": null, "path": "https://DOMAIN/token/1.0/sync/1.5", "method": "GET", "tokenserver.oauth.verify": 6.508827209472656e-05, "uid.first_seen_at": 1599606187456}
rfk commented 4 years ago

Aha, I bet the pinned version of server-syncstorage is missing the fix from https://github.com/mozilla-services/server-syncstorage/pull/150. I'm going to try updating the versions here to latest commit on both tokenserver and syncserver repos and we'll see if that helps.

rfk commented 4 years ago

Once a new docker image is published with https://github.com/mozilla-services/syncserver/pull/237 included, could you please try again and let me know if that helped?

ABeltramo commented 4 years ago

The warning about urllib3 is still there but syncing is now working again on my side.

Emporea commented 4 years ago

Heureka, sync works.!

gu1ll0me commented 4 years ago

It works here too! Thank you @rfk.

Emporea commented 4 years ago

@rfk should i close this issue? The dependencyWarning is still active, I can leave it open for this, even if the actual topic of this thread has changed.

rfk commented 4 years ago

Thanks, let's leave it open to track the dependency warning.

kommserv commented 4 years ago

I upgraded from 1.8.0 to 1.9.1, ran into the missing table columns error, fixed it as suggested, and at this point I noticed the RequestsDependencyWarning messages in the Apache error log.

I restarted the Apache service on the server, and logged out of Firefox on my desktop, then restarted Firefox for good measure. After logging back in to Firefox sync the warning no longer shows up and syncing seems to be working.

Edit: Strike that, the warning message is back. I was too quick to declare victory.