731522 - Latest server-reg does not work with old-style auth backends

Status: RESOLVED FIXED

(Cloud Services Graveyard :: Server: Sync, defect)

Description

[Joachim Breuer]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.1) Gecko/20100101 Firefox/10.0.1
Build ID: 20120222115619

Steps to reproduce:

In the course of further testing WRT Bug #731515, I tried to connect a fresh profile to the existing sync account (on our non-public sync server).

The sync-server was recently updated to the hg default tip as of 2012-02-28.


Actual results:

After filling in the 'Sign In' page (account, pw, server URL, recovery key) and hitting 'Next':
Near 'Server' a red X comes up with the message "Failed to connect to the server".

The server log shows the following:

255a1
[Wed Feb 29 08:29:04 2012] [error] cc2551986f17c89a0dc4d3ce7f8255a1
[Wed Feb 29 08:29:04 2012] [error] 2012-02-29 08:29:04,388 ERROR [syncserver] Traceback (most recent call last):
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/util.py", line 304, in __call__
[Wed Feb 29 08:29:04 2012] [error]     return self.app(environ, start_response)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/paste/translogger.py", line 68, in __call__
[Wed Feb 29 08:29:04 2012] [error]     return self.application(environ, replacement_start_response)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/webob/dec.py", line 147, in __call__
[Wed Feb 29 08:29:04 2012] [error]     resp = self.call_func(req, *args, **self.kwargs)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/webob/dec.py", line 208, in call_func
[Wed Feb 29 08:29:04 2012] [error]     return self.func(req, *args, **kwargs)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 187, in __notified
[Wed Feb 29 08:29:04 2012] [error]     response = func(self, request)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 221, in __call__
[Wed Feb 29 08:29:04 2012] [error]     response = self._dispatch_request(request)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 273, in _dispatch_request
[Wed Feb 29 08:29:04 2012] [error]     response = self._dispatch_request_with_match(request, match)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 299, in _dispatch_request_with_match
[Wed Feb 29 08:29:04 2012] [error]     result = function(request, **params)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-reg/syncreg/controllers/user.py", line 128, in user_node
[Wed Feb 29 08:29:04 2012] [error]     if not self.auth.get_user_id(request.user):
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/auth/sql.py", line 116, in get_user_id
[Wed Feb 29 08:29:04 2012] [error]     user_name=user_name).fetchone()
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/util.py", line 335, in safe_execute
[Wed Feb 29 08:29:04 2012] [error]     return engine.execute(*args, **kwargs)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1788, in execute
[Wed Feb 29 08:29:04 2012] [error]     return connection.execute(statement, *multiparams, **params)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1191, in execute
[Wed Feb 29 08:29:04 2012] [error]     params)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1271, in _execute_clauseelement
[Wed Feb 29 08:29:04 2012] [error]     return self.__execute_context(context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1302, in __execute_context
[Wed Feb 29 08:29:04 2012] [error]     context.parameters[0], context=context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1401, in _cursor_execute
[Wed Feb 29 08:29:04 2012] [error]     context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1394, in _cursor_execute
[Wed Feb 29 08:29:04 2012] [error]     context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 299, in do_execute
[Wed Feb 29 08:29:04 2012] [error]     cursor.execute(statement, parameters)
[Wed Feb 29 08:29:04 2012] [error] ProgrammingError: (ProgrammingError) can't adapt type 'User' 'SELECT users.id \\nFROM users \\nWHERE users.username = %(user_name)s' {'user_name': {'username': u'a3ibvwtt4xf7ye5xddzp3jzdoxkzh4yp', 'userid': None}}
[Wed Feb 29 08:29:04 2012] [error] 
[Wed Feb 29 08:29:04 2012] [error] Traceback (most recent call last):
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/util.py", line 304, in __call__
[Wed Feb 29 08:29:04 2012] [error]     return self.app(environ, start_response)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/paste/translogger.py", line 68, in __call__
[Wed Feb 29 08:29:04 2012] [error]     return self.application(environ, replacement_start_response)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/webob/dec.py", line 147, in __call__
[Wed Feb 29 08:29:04 2012] [error]     resp = self.call_func(req, *args, **self.kwargs)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/webob/dec.py", line 208, in call_func
[Wed Feb 29 08:29:04 2012] [error]     return self.func(req, *args, **kwargs)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 187, in __notified
[Wed Feb 29 08:29:04 2012] [error]     response = func(self, request)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 221, in __call__
[Wed Feb 29 08:29:04 2012] [error]     response = self._dispatch_request(request)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 273, in _dispatch_request
[Wed Feb 29 08:29:04 2012] [error]     response = self._dispatch_request_with_match(request, match)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/baseapp.py", line 299, in _dispatch_request_with_match
[Wed Feb 29 08:29:04 2012] [error]     result = function(request, **params)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-reg/syncreg/controllers/user.py", line 128, in user_node
[Wed Feb 29 08:29:04 2012] [error]     if not self.auth.get_user_id(request.user):
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/auth/sql.py", line 116, in get_user_id
[Wed Feb 29 08:29:04 2012] [error]     user_name=user_name).fetchone()
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/deps/server-core/services/util.py", line 335, in safe_execute
[Wed Feb 29 08:29:04 2012] [error]     return engine.execute(*args, **kwargs)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1788, in execute
[Wed Feb 29 08:29:04 2012] [error]     return connection.execute(statement, *multiparams, **params)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1191, in execute
[Wed Feb 29 08:29:04 2012] [error]     params)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1271, in _execute_clauseelement
[Wed Feb 29 08:29:04 2012] [error]     return self.__execute_context(context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1302, in __execute_context
[Wed Feb 29 08:29:04 2012] [error]     context.parameters[0], context=context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1401, in _cursor_execute
[Wed Feb 29 08:29:04 2012] [error]     context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1394, in _cursor_execute
[Wed Feb 29 08:29:04 2012] [error]     context)
[Wed Feb 29 08:29:04 2012] [error]   File "/opt/mozilla-sync-server/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 299, in do_execute
[Wed Feb 29 08:29:04 2012] [error]     cursor.execute(statement, parameters)
[Wed Feb 29 08:29:04 2012] [error] ProgrammingError: (ProgrammingError) can't adapt type 'User' 'SELECT users.id \\nFROM users \\nWHERE users.username = %(user_name)s' {'user_name': {'username': u'a3ibvwtt4xf7ye5xddzp3jzdoxkzh4yp', 'userid': None}}
[Wed Feb 29 08:29:04 2012] [error] 


The users table in the database looks good, and there is a row for the username 'a3ibvwtt4xf7ye5xddzp3jzdoxkzh4yp'.

... Is there a (manual) schema update of the database required when upgrading from an older sync-server version?


Expected results:

The profile should be connected to the sync account.

Comment 1

[Joachim Breuer]

OK, found it:

https://hg.mozilla.org/services/server-reg/file/ea7aaa1f240a/syncreg/controllers/user.py

Line 128: if not self.auth.get_user_id(request.user):
             raise HTTPNotFound()

This is what appears to be causing the problem; self.auth.get_user_id() apparently wants a username string as a parameter, but is passed the whole user part of the request here.

I changed that line to read:
  if not self.auth.get_user_id(request.user.get('username')):

This allowed me to get past this particular problem; but sync is still not happening.

I'll open a different bug report for the other issue.

Comment 2

[Ryan Kelly [:rfkelly]]

Attachment: patch to fail out noisly if given an old-style auth backend

Hi Joachim,

Thanks for tracking this down.  It looks like the server-reg code is expecting to work with a "newstyle" authentication backend as of Bug 675100.  In the [auth] section of your config file, the value of the "backend" setting should be:

    [auth]
    backend = services.user.sql.SQLUser

You most likely have "services.auth.sql.SQLAuth" in there, which uses an older, deprecated API.  Unfortunately the default config files were not updated with the change for some time after the code change landed, so apologies for that.

The two different backends use different database table names.  That's good in one sense, because there should be no conflicts when changing over.  But it's also bad because the user account data will need to be re-created.

It's probably worth adding a check to fail noisily if the new code is used with an old-style auth backend.  Patch attached.

Comment 3

[James Bonacci [:jbonacci]]

Changing from Unconfirmed to New/Assigned since Ryan picked this up.
QA will take a look as well...

Comment 4

[Toby Elliott [:telliott]]

Comment on attachment 626307 [details] [diff] [review]
patch to fail out noisly if given an old-style auth backend

Can we look for the presence of something that suggests the class is good rather than vice-versa? It's quite possible a valid class could have an unrelated generate_reset_code method.

Comment 5

[Ryan Kelly [:rfkelly]]

Attachment: patch to check for new-style auth backend

Fair enough.  This patch uses the abstract-base-classness of ServicesUser to do the check using isinstance(), which will fail if the backend is missing any of the newstyle auth methods.

Frankly, we should be doing it this way within server-core itself as well, instead of using the hasattr("generate_reset_code") thing from the previous patch.

Comment 6

[Ryan Kelly [:rfkelly]]

http://hg.mozilla.org/services/server-reg/rev/aeebae08c1ff