search

mozilla-services / syncserver

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

FreeBSD tests fail #115

Closed khanzf closed 6 years ago

khanzf commented 6 years ago

Hi all, I am trying to hack this code to work on FreeBSD 11.1. I got it to successfully compile, but the tests fail. Here is what I did so far:

sudo pkg install py27-virtualenv-15.1.0
sudo pkg install python2-2_3
sudo pkg install git-lite
sudo pkg install gmake
git clone https://github.com/mozilla-services/syncserver
cd syncserver

From here, I edit requirements.txt to include pysqlite. FreeBSD places sqlite3.h in /usr/local/include, so I added -I/usr/local/include to the end of the CFLAGS variable in Makefile.

From here, I ran a simple gmake build, which worked just fine. When I ran gmake test I received a lot of what I believe are database errors. Here is a sampling:

$ gmake test
./local/bin/flake8 ./syncserver
./local/bin/nosetests -s syncstorage.tests
EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE.EEEEEEEEEEEEESSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE.EEEEEEEEEEEEEEEEE.......E.EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE.EEEEE.EEE.EEE..SSSSSSSSSSSSSSSSS.SS..TEST THREADS APPEAR TO BE DEADLOCKED

READ THREAD TRACEBACK:
  File "/usr/local/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/local/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/local/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/tests/test_storage.py", line 138, in catch_failures_wrapper
    return func(*args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/tests/test_storage.py", line 159, in reader_thread
    write_complete.wait()
  File "/usr/local/lib/python2.7/threading.py", line 614, in wait
    self.__cond.wait(timeout)
  File "/usr/local/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

E............E.E.
======================================================================
ERROR: test_alternative_formats (syncstorage.tests.functional.test_old_storage.TestOldStorage)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/tests/functional/test_old_storage.py", line 44, in setUp
    self.app.post_json(self.root + '/storage/' + name, [])
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/webtest/utils.py", line 36, in wrapper
    return self._gen_request(method, url, **kw)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/webtest/app.py", line 755, in _gen_request
    expect_errors=expect_errors)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/tests/functional/support.py", line 43, in new_do_request
    return orig_do_request(req, *args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/webtest/app.py", line 651, in do_request
    self._check_status(status, res)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/webtest/app.py", line 683, in _check_status
    res)
AppError: Bad response: 503 Service Unavailable (not 200 OK or 3xx redirect for http://localhost:5000/1.5/58556/storage/client)
"application error: crash id 20a9eec45a734859fc29a7f8c4199448"
-------------------- >> begin captured logging << --------------------
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Created new connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0>
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
mozsvc.metrics: INFO: {"code": 200, "request_time": 0.0031092166900634766, "remoteAddressChain": ["127.0.0.1"], "agent": "", "fxa_uid": null, "syncstorage.storage.sql.pool.get": 5.0067901611328125e-05, "syncstorage.storage.sql.db.execute": 0.0006859302520751953, "path": "http://localhost:5000/1.5/58556/storage", "method": "DELETE", "device_id": null}
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> checked out from pool
syncstorage.storage.sql.dbconnect: ERROR: Caught operational db error: (pysqlite2.dbapi2.OperationalError) cannot start a transaction within a transaction [SQL: u'BEGIN EXCLUSIVE TRANSACTION /* [queryName=BEGIN_TRANSACTION_WRITE] */']
Traceback (most recent call last):
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/dbconnect.py", line 533, in report_backend_errors_wrapper
    return func(self, *args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/dbconnect.py", line 629, in execute
    return self._exec_with_cleanup(connection, query_str, **params)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/mozsvc/metrics.py", line 183, in timed_func
    return func(*args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/dbconnect.py", line 663, in _exec_with_cleanup
    return connection.execute(sqltext(query_str), **params)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 945, in execute
    return meth(self, multiparams, params)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
    context)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1393, in _handle_dbapi_exception
    exc_info
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
    cursor.execute(statement, parameters)
OperationalError: (pysqlite2.dbapi2.OperationalError) cannot start a transaction within a transaction [SQL: u'BEGIN EXCLUSIVE TRANSACTION /* [queryName=BEGIN_TRANSACTION_WRITE] */']

syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> being returned to pool
syncstorage.storage.sql.dbconnect.QueuePoolWithMaxBacklog: DEBUG: Connection <pysqlite2.dbapi2.Connection object at 0x80a1ba1f0> rollback-on-return
mozsvc: ERROR: 20a9eec45a734859fc29a7f8c4199448
mozsvc: ERROR: BackendError

(pysqlite2.dbapi2.OperationalError) cannot start a transaction within a transaction [SQL: u'BEGIN EXCLUSIVE TRANSACTION /* [queryName=BEGIN_TRANSACTION_WRITE] */']
Traceback (most recent call last):
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/mozsvc/tweens.py", line 26, in catch_backend_errors_tween
    return handler(request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/tweens.py", line 21, in excview_tween
    response = handler(request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/router.py", line 163, in handle_request
    response = view_callable(context, request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/config/views.py", line 596, in __call__
    return view(context, request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/config/views.py", line 329, in attr_view
    return view(context, request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/config/views.py", line 305, in predicate_wrapper
    return view(context, request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/config/views.py", line 245, in _secured_view
    return view(context, request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/config/views.py", line 355, in rendered_view
    result = view(context, request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/pyramid/config/views.py", line 501, in _requestonly_view
    response = view(request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/cornice/service.py", line 514, in wrapper
    response = view_(request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/views/util.py", line 54, in wrapper
    return decorator_func(target_func, *args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/views/decorators.py", line 40, in convert_storage_errors
    return viewfunc(request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/views/util.py", line 54, in wrapper
    return decorator_func(target_func, *args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/views/decorators.py", line 71, in sleep_and_retry_on_conflict
    return viewfunc(request)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/views/util.py", line 54, in wrapper
    return decorator_func(target_func, *args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/views/decorators.py", line 192, in with_collection_lock
    with lock_collection(userid, collection):
  File "/usr/local/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/__init__.py", line 226, in lock_for_write
    session.query("BEGIN_TRANSACTION_WRITE")
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/__init__.py", line 80, in convert_db_errors_wrapper
    return func(*args, **kwds)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/__init__.py", line 1043, in query
    return self.connection.query(query, params)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/dbconnect.py", line 748, in query
    res = self.execute(query, params, annotations)
  File "/usr/home/farhan/syncserver/local/lib/python2.7/site-packages/syncstorage/storage/sql/dbconnect.py", line 545, in report_backend_errors_wrapper
    raise BackendError(str(exc))
BackendError: BackendError

I do not understand this error, but I am willing to assist in helping to debug the issue. Thanks

rfk commented 6 years ago

From here, I edit requirements.txt to include pysqlite.

One quick thing to try would be, is there a system package for python sqlite support? A quick google around suggests there may be a "py-sqlite3" package. If you can find one, could you please try with that rather than installing via requirements.txt?

rfk commented 6 years ago

I spun up a freebsd EC2 instance to try this out real quick, and followed your instructions but did pkg install py27-sqlite3 rather than putting it in requirements.txt. With that configuration gmake test seems to run successfully for me.

khanzf commented 6 years ago

Hi, I installed the package py27-sqlite3. However, I still get the same errors.

It seems that the first error message is:

AppError: Bad response: 503 Service Unavailable (not 200 OK or 3xx redirect for http://localhost:5000/1.5/58556/storage/client)
"application error: crash id 20a9eec45a734859fc29a7f8c4199448"

Whereas every successive error is a variation of the following:

OperationalError: (pysqlite2.dbapi2.OperationalError) cannot start a transaction within a transaction [SQL: u'BEGIN EXCLUSIVE TRANSACTION /* [queryName=BEGIN_TRANSACTION_WRITE] */']

Without understanding the nature of the tests, might this be an indication of what is happening?

rfk commented 6 years ago

I installed the package py27-sqlite3

In a clean build, or using your existing build? If the later, it might still be trying to use the locally-installed pysqlite2 from requirements.txt.

"application error: crash id 20a9eec45a734859fc29a7f8c4199448"

This is basically the syncserver software reporting a very generic user-visible error message that might be visible to the end-user. The successive errors are the real traceback, about "cannot start a transaction". They suggest some sort of issue with the sqlite database connector, for example that it may be trying to re-use the same db connection across multiple threads.

khanzf commented 6 years ago

As discussed on IRC, I deleted the syncserver/local directory. I then ran gmake build again with the same result.

If I understand your explanation, perhaps there is still a problem with the database? If so, if you can show me where that code is, I can try to enter the virtualenv and try to resolve it.

rfk commented 6 years ago

Sorry, I should also have said "and remove pysqlite2 from your requirements.txt".

If you're still seeing tracebacks that say "pysqlite2.dbapi2.OperationalError" then it's probably still using the one build from requirements.txt rather than the one provided by your package manager.

khanzf commented 6 years ago

That appeared to be it. I added the packages:

sqlite-2.8.17_4
sqlite3-3.23.0
py36-sqlite3-3.6.5_7

And now it appears that it passed all tests, while skipping 208. Great! Unless there is something to add, we can close out this issue.

rfk commented 6 years ago

Great to to hear! :-)