mozilla/syncserver:latest appears broken - tried testing inside docker the latest image and faced errors

[mariusft]

Running inside docker:

/app # export SYNCSERVER_PUBLIC_URL="http://localhost:5001"
/app # gunicorn --threads 4 --paste syncserver/tests.ini &

Server launched successfully:

[2022-02-15 17:57:34 +0000] [489] [INFO] Starting gunicorn 19.10.0
[2022-02-15 17:57:34 +0000] [489] [INFO] Listening at: http://0.0.0.0:5001 (489)
[2022-02-15 17:57:34 +0000] [489] [INFO] Using worker: threads
[2022-02-15 17:57:34 +0000] [496] [INFO] Booting worker with pid: 496

Issuing the test procedure:

/app # /usr/local/bin/python -m syncstorage.tests.functional.test_storage --use-token-server http://localhost:5001/token/1.0/sync/1.5

Fails:

ERROR:mozsvc:Uncaught exception while processing request:
GET http://localhost:5001/token/1.0/sync/1.5
Uncaught exception:
  File "/usr/local/lib/python2.7/site-packages/mozsvc/tweens.py", line 59, in log_uncaught_exceptions_tween
    return handler(request)
  File "/usr/local/lib/python2.7/site-packages/mozsvc/tweens.py", line 26, in catch_backend_errors_tween
    return handler(request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 43, in excview_tween
    response = _error_handler(request, exc)
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 17, in _error_handler
    reraise(*exc_info)
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 41, in excview_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/router.py", line 148, in handle_request
    registry, request, context, context_iface, view_name
  File "/usr/local/lib/python2.7/site-packages/pyramid/view.py", line 667, in _call_view
    response = view_callable(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/config/views.py", line 169, in __call__
    return view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/config/views.py", line 188, in attr_view
    return view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/config/views.py", line 214, in predicate_wrapper
    return view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/viewderivers.py", line 436, in rendered_view
    result = view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/viewderivers.py", line 144, in _requestonly_view
    response = view(request)
  File "/usr/local/lib/python2.7/site-packages/cornice/service.py", line 514, in wrapper
    response = view_(request)
  File "/usr/local/lib/python2.7/site-packages/tokenserver/views.py", line 370, in return_token
    user = backend.get_user(service, email)
  File "/app/syncserver/staticnode.py", line 135, in get_user
    res = self._engine.execute(_GET_USER_RECORDS, **params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2166, in execute
    return connection.execute(statement, *multiparams, **params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 988, in execute
    return meth(self, multiparams, params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1107, in _execute_clauseelement
    distilled_params,
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1248, in _execute_context
    e, statement, parameters, cursor, context
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1466, in _handle_dbapi_exception
    util.raise_from_cause(sqlalchemy_exception, exc_info)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 383, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1244, in _execute_context
    cursor, statement, parameters, context
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 552, in do_execute
    cursor.execute(statement, parameters)
<class 'sqlalchemy.exc.OperationalError'>
OperationalError('(sqlite3.OperationalError) no such column: keys_changed_at',)

[2022-02-15 17:57:47 +0000] [496] [ERROR] Error handling request /token/1.0/sync/1.5
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/site-packages/gunicorn/workers/gthread.py", line 280, in handle
    keepalive = self.handle_request(req, conn)
  File "/usr/local/lib/python2.7/site-packages/gunicorn/workers/gthread.py", line 329, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/local/lib/python2.7/site-packages/pyramid/router.py", line 270, in __call__
    response = self.execution_policy(environ, self)
  File "/usr/local/lib/python2.7/site-packages/pyramid/router.py", line 279, in default_execution_policy
    return request.invoke_exception_view(reraise=True)
  File "/usr/local/lib/python2.7/site-packages/pyramid/view.py", line 778, in invoke_exception_view
    reraise_(*exc_info)
  File "/usr/local/lib/python2.7/site-packages/pyramid/router.py", line 277, in default_execution_policy
    return router.invoke_request(request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/router.py", line 249, in invoke_request
    response = handle_request(request)
  File "/usr/local/lib/python2.7/site-packages/tokenserver/tweens.py", line 15, in set_x_timestamp_header_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tweens.py", line 128, in convert_non_json_responses_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tweens.py", line 104, in convert_cornice_errors_to_respcodes_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tweens.py", line 58, in set_default_accept_header_tween
    return handler(request)
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tweens.py", line 30, in set_x_timestamp_header_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/mozsvc/tweens.py", line 94, in fuzz_backoff_headers_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/mozsvc/tweens.py", line 59, in log_uncaught_exceptions_tween
    return handler(request)
  File "/usr/local/lib/python2.7/site-packages/mozsvc/tweens.py", line 26, in catch_backend_errors_tween
    return handler(request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 43, in excview_tween
    response = _error_handler(request, exc)
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 17, in _error_handler
    reraise(*exc_info)
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 41, in excview_tween
    response = handler(request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/router.py", line 148, in handle_request
    registry, request, context, context_iface, view_name
  File "/usr/local/lib/python2.7/site-packages/pyramid/view.py", line 667, in _call_view
    response = view_callable(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/config/views.py", line 169, in __call__
    return view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/config/views.py", line 188, in attr_view
    return view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/config/views.py", line 214, in predicate_wrapper
    return view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/viewderivers.py", line 436, in rendered_view
    result = view(context, request)
  File "/usr/local/lib/python2.7/site-packages/pyramid/viewderivers.py", line 144, in _requestonly_view
    response = view(request)
  File "/usr/local/lib/python2.7/site-packages/cornice/service.py", line 514, in wrapper
    response = view_(request)
  File "/usr/local/lib/python2.7/site-packages/tokenserver/views.py", line 370, in return_token
    user = backend.get_user(service, email)
  File "/app/syncserver/staticnode.py", line 135, in get_user
    res = self._engine.execute(_GET_USER_RECORDS, **params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2166, in execute
    return connection.execute(statement, *multiparams, **params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 988, in execute
    return meth(self, multiparams, params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1107, in _execute_clauseelement
    distilled_params,
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1248, in _execute_context
    e, statement, parameters, cursor, context
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1466, in _handle_dbapi_exception
    util.raise_from_cause(sqlalchemy_exception, exc_info)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 383, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1244, in _execute_context
    cursor, statement, parameters, context
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 552, in do_execute
    cursor.execute(statement, parameters)
OperationalError: (sqlite3.OperationalError) no such column: keys_changed_at
[SQL: select
    uid, generation, client_state, created_at, replaced_at,
    keys_changed_at, node
from
    users
where
    email = ?
and
    service = ?
order by
    created_at desc, uid desc
limit
    20
]
[parameters: (u'########@########.s3-us-west-2.amazonaws.com', u'########')]
(Background on this error at: http://sqlalche.me/e/e3q8)
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/runpy.py", line 174, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/usr/local/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tests/functional/test_storage.py", line 2361, in <module>
    res = run_live_functional_tests(TestStorage, sys.argv)
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tests/functional/support.py", line 211, in run_live_functional_tests
    creds = authenticate_to_token_server(url, opts.email, opts.audience)
  File "/usr/local/lib/python2.7/site-packages/syncstorage/tests/functional/support.py", line 143, in authenticate_to_token_server
    r.raise_for_status()
  File "/usr/local/lib/python2.7/site-packages/requests/models.py", line 940, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: http://localhost:5001/token/1.0/sync/1.5

[Emporea]

Cannot reproduce this issue.

[mariusft]

I see a new image was pushed couple of hours back, let me test that one: sha256:016162bf39d8486d5710b4ae5bcaaebd8bd60b55db6cf468b8f720b526bd68b7

Previous image was: sha256:74b3ebb68b4c591a70221255d4e26be67b7ecc87d95395f3cd82de4f9713b74a

[mariusft]

# docker image inspect mozilla/syncserver

[
    {
        "Id": "sha256:a61ad35f05cabf9ad4d46ee817b70ce8f52844329d319386ff31562f62af5e05",
        "RepoTags": [
            "mozilla/syncserver:latest"
        ],
        "RepoDigests": [
            "mozilla/syncserver@sha256:016162bf39d8486d5710b4ae5bcaaebd8bd60b55db6cf468b8f720b526bd68b7"
        ],

# docker container ls

CONTAINER ID   IMAGE                           COMMAND                  CREATED              STATUS              PORTS                                                                                                                                   NAMES
8b3f31a51bc8   mozilla/syncserver:latest       "/usr/bin/dumb-init …"   About a minute ago   Up About a minute   0.0.0.0:45000->5000/tcp, :::45000->5000/tcp

# docker exec -u 0 -it 8b3f31a51bc8 /bin/sh /app # vi syncserver/tests.ini

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

[app:main]
use = egg:SyncServer

[syncserver]
# This must be edited to point to the public URL of your server.
public_url = http://localhost:5001/

# This defines the database in which to store all server data.
sqluri = sqlite:///:memory:

# This is a secret key used for signing authentication tokens.
#secret = INSERT_SECRET_KEY_HERE

/app # export SYNCSERVER_PUBLIC_URL="http://localhost:5001" /app # gunicorn --threads 4 --paste syncserver/tests.ini &

/app # [2022-02-17 07:46:39 +0000] [48] [INFO] Starting gunicorn 19.10.0
[2022-02-17 07:46:39 +0000] [48] [INFO] Listening at: http://0.0.0.0:5001 (48)
[2022-02-17 07:46:39 +0000] [48] [INFO] Using worker: threads
[2022-02-17 07:46:39 +0000] [55] [INFO] Booting worker with pid: 55

/app # /usr/local/bin/python -m syncstorage.tests.functional.test_storage --use-token-server http://localhost:5001/token/1.0/sync/1.5

Truncated a little bit the output, but the same errors are reported with the latest image as well:

ERROR:mozsvc:Uncaught exception while processing request:
GET http://localhost:5001/token/1.0/sync/1.5
Uncaught exception:
...
  File "/usr/local/lib/python2.7/site-packages/pyramid/tweens.py", line 41, in excview_tween
    response = handler(request)
...
    cursor.execute(statement, parameters)
OperationalError: (sqlite3.OperationalError) no such column: keys_changed_at
[SQL: select
    uid, generation, client_state, created_at, replaced_at,
    keys_changed_at, node
from
    users
...
  File "/usr/local/lib/python2.7/site-packages/requests/models.py", line 940, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: http://localhost:5001/token/1.0/sync/1.5

[mariusft]

tested with mozilla/syncserver:feature.update-sqlalchemy which by the way is missing 'futures' package, installed missing package and is working:

/usr/local/bin/python -m syncstorage.tests.functional.test_storage --use-token-server http://localhost:5001/token
/1.0/sync/1.5
s.....s..........................s..................s...s..s
----------------------------------------------------------------------
Ran 60 tests in 99.852s

OK (skipped=6)

[mariusft]

So it appears this started from: mozilla/syncserver:1.9.0 mozilla/syncserver:1.9.1 Is failing since then, just tested all those images.

[binarydad]

I only came here because I tried updating my docker image for mozilla/syncserver from an image created October of 2021. I updated and while the logs didn't appear to show error, I could no longer sync. For example, on FF desktop, the page that listed all the things to sync (such as Bookmarks, History, Open Tabs) showed only Logins. Syncing no longer worked and I could no longer see open tabs on other synced devices.

Is this really being deprecated? I see https://github.com/mozilla-services/syncstorage-rs is mentioned, but is this safe to start using? Any additional info is appreciated. Thanks!

[mariusft]

Internal sync test still didn't work but I've figure it out what that error means, apparently with the new release sqlite database changed and is no longer compatible, this will require old db removal

[mixxit]

my secrets have been broken for so long and i didnt notice until today - when will this be fixed?

OperationalError('(sqlite3.OperationalError) no such column: keys_changed_at',