[FAS3] No longer able to login after most recent changes in FAS_3.0 branch

[skrzepto]

Summary

When logging into fasadmin or any other account you create it errors saying

TypeError: can't compare offset-naive and offset-aware datetimes

Steps to reproduce

1. Run init and generate fake-users in fas-admin
2. Login into any account

   Expected results

3. login succesfully

   Misc. Notes

I came across this when trying to run my unit tests but they were all failing. One thing I noticed is that if you comment out line 295 in fas/security https://github.com/skrzepto/fas/blob/115507f3748a70313d4c7dbac48f8ae0f1930268/fas/security.py#L295

it works as expected. I went through the recent git logs and I can't seem to pinpoint what change caused this.

Error Log

FROM people 
WHERE people.username = ?
 LIMIT ? OFFSET ?) AS anon_1 LEFT OUTER JOIN signed_license_agreement AS signed_license_agreement_1 ON anon_1.people_id = signed_license_agreement_1.person_id
2016-07-26 07:46:47,146 INFO  [waitress:4107][sqlalchemy.engine.base.Engine:base][_execute_context:1100] (u'simon', 1, 0)
2016-07-26 07:46:47,156 DEBUG [waitress:4107][fas.models.register:register][save_account_activity:50] Found record from remote IP(127.0.0.1): {}
2016-07-26 07:46:47,156 DEBUG [waitress:4107][fas.models.register:register][save_account_activity:53] Parsing user_agent: {'device': {'brand': None, 'model': None, 'family': 'Other'}, 'os': {'major': None, 'patch_minor': None, 'minor': None, 'family': 'Linux', 'patch': None}, 'user_agent': {'major': '1', 'minor': '2', 'family': 'Vivaldi', 'patch': '490'}, 'string': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.103 Safari/537.36 Vivaldi/1.2.490.43'}
2016-07-26 07:46:47,157 DEBUG [waitress:4107][fas.models.register:register][save_account_activity:56] Found clien from user_agent: Vivaldi
2016-07-26 07:46:47,157 DEBUG [waitress:4107][fas.models.register:register][save_account_activity:59] Found device from user_agent: Other
2016-07-26 07:46:47,157 DEBUG [waitress:4107][fas.models.register:register][save_account_activity:83] Set remote location to: Unknown
2016-07-26 07:46:47,162 INFO  [waitress:4107][sqlalchemy.engine.base.Engine:base][_rollback_impl:666] ROLLBACK
2016-07-26 07:46:47,168 ERROR [waitress:4107][pyramid_debugtoolbar:toolbar][toolbar_tween:227] Exception at http://0.0.0.0:6543/login
traceback url: http://0.0.0.0:6543/_debug_toolbar/exception?token=b273499f91dc4180eae2&tb=140000199386960
Traceback (most recent call last):
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid_debugtoolbar/toolbar.py", line 209, in toolbar_tween
    response = _handler(request)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid_debugtoolbar/panels/performance.py", line 57, in resource_timer_handler
    result = handler(request)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/tweens.py", line 62, in excview_tween
    reraise(*attrs['exc_info'])
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/tweens.py", line 22, in excview_tween
    response = handler(request)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid_tm/__init__.py", line 101, in tm_tween
    reraise(*exc_info)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid_tm/__init__.py", line 83, in tm_tween
    response = handler(request)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/router.py", line 158, in handle_request
    view_name
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/view.py", line 547, in _call_view
    response = view_callable(context, request)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/viewderivers.py", line 442, in rendered_view
    result = view(context, request)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/viewderivers.py", line 123, in _class_requestonly_view
    response = getattr(inst, attr)()
  File "/home/skrzepto/Documents/repo/fas/fas/views/home.py", line 76, in login
    result = process_login(self.request, person, password)
  File "/home/skrzepto/Documents/repo/fas/fas/security.py", line 295, in process_login
    notify(LoginSucceeded(request, person))
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/registry.py", line 91, in notify
    [ _ for _ in self.subscribers(events, None) ]
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/zope/interface/registry.py", line 328, in subscribers
    return self.adapters.subscribers(objects, provided)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/zope/interface/adapter.py", line 596, in subscribers
    subscription(*objects)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/pyramid/config/adapters.py", line 103, in derived_subscriber
    return subscriber(arg[0])
  File "/home/skrzepto/Documents/repo/fas/fas/subscribers/people.py", line 107, in check_ssh_key
    for m in person.group_membership:
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/attributes.py", line 237, in __get__
    return self.impl.get(instance_state(instance), dict_)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/attributes.py", line 583, in get
    value = self.callable_(state, passive)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/strategies.py", line 544, in _load_for_state
    return self._emit_lazyload(session, state, ident_key, passive)
  File "<string>", line 1, in <lambda>
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/strategies.py", line 614, in _emit_lazyload
    result = q.all()
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2613, in all
    return list(self)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2760, in __iter__
    self.session._autoflush()
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1293, in _autoflush
    self.flush()
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2019, in flush
    self._flush(objects)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2137, in _flush
    transaction.rollback(_capture_exception=True)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
    compat.reraise(exc_type, exc_value, exc_tb)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2101, in _flush
    flush_context.execute()
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
    rec.execute(self)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
    uow
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 170, in save_obj
    mapper, table, update)
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 634, in _emit_update_statements
    lambda rec: (
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 462, in _collect_update_commands
    value, state.committed_state[propkey]) is not True:
  File "/home/skrzepto/.virtualenvs/fas-python2.7/lib/python2.7/site-packages/sqlalchemy/sql/type_api.py", line 279, in compare_values
    return x == y
TypeError: can't compare offset-naive and offset-aware datetimes

[pypingou]

Could you try with the changes from #193 ?

[skrzepto]

@pypingou still crashes for me same way. Does it work for you, it could be my local setup?

[pypingou]

It works for me but I'm using a dump of FAS2's db upgraded, so not a FAS3 db generated by FAS3 :)

[skrzepto]

Thanks, updated my issue with that specific info. I am using the FAS3 db generated by FAS3.

[skrzepto]

okay figured it out, at least on my machine why its failing

the recent change

from

-    person.login_timestamp = datetime.datetime.utcnow()

To

+    person.login_timestamp = datetime.datetime.now(pytz.timezone('UTC'))

[skrzepto]

@pypingou

from the commits message you mentioned you wanted the timezone to be set on the login_timestamp. does utcnow() not do that?

---

edit

I think we can update the model for the login to be timezone aware so this change can be compatible

[skrzepto]

No luck changing the people model and account activity model :/

[pypingou]

does utcnow() not do that?

Unfortunately not :(

[skrzepto]

@pypingou how important is adding the tzinfo? https://github.com/fedora-infra/fas/blob/FAS_3.0/fas/subscribers/login.py#L102

Since all our dates are utcnow.

---

edit

good blog post on the topic

http://lucumr.pocoo.org/2011/7/15/eppur-si-muove/

[pypingou]

how important is adding the tzinfo?

Well, the issue is when you work on a FAS2 db converted to FAS3, for some reasons the date/times in there are stored with timezone info, this means we need to work with timezone everywhere as otherwise python complains (rightfully) that it cannot work with a date that is tz aware and a date that isn't at the same time.

So, for a FAS2 db upgraded, it is most important to be TZ aware.

[skrzepto]

@pypingou When you tested the login, were you using postgres db or sqlite?

[laxathom]

Hey, so this is the data models which are not tz aware which lead you to this issue when generating the db from scratch. @pypingou Can I push a fix to your branch avoiding me to cherry-pick a commit and by the same time review your PR?

[skrzepto]

@laxathom could you check out my pr for the login fix, if its good pypingou could rebase his branch

[pypingou]

@pypingou Can I push a fix to your branch avoiding me to cherry-pick a commit and by the same time review your PR?

Sure thing, feel free to ping me if you want another set of eyes on this commit

[laxathom]

Done.

[skrzepto]

@laxathom I'm assuming you pushed changes to the Misc Fixes and the first time logging into fasadmin works. Then when I log out and log back in, the error persists.

[skrzepto]

Issue is still present in most recent version of fas3. DB: postgres local

[skrzepto]

Seems if you comment out https://github.com/fedora-infra/fas/blob/FAS_3.0/fas/security.py#L295 login works fine

[skrzepto]

@pypingou @laxathom

I mentioned this above but could someone explain why timezone info was important in

fas/subscribers/login.py
103:    person.login_timestamp = datetime.datetime.now(pytz.utc)

it seems in table people column login_timestamp doesn't have tz aware attribute which is why it throws the error.

Could we change it back to

-    person.login_timestamp = datetime.datetime.utcnow()

This fixes the login time stamp issue but keeps it in utc date format without timezone awareness.

Thoughts?

[pypingou]

The issue is that FAS2 has timezone aware date/times, so that's why we need to have them also in FAS3, otherwise migrating from one to the other is somewhere between most-painful to really-don't-want-to-try :)

[skrzepto]

@pypingou can you check out my PR #222 I believe it satisfies your request for keeping timezone aware

[ryanlerch]

Closing this issue as the FAS project is now archived, not actively developed, and unmaintained.

FAS was replaced in March 2021 by Fedora Accounts (https://accounts.fedoraproject.org).

If this issue is a Feature Request that you forsee might be beneficial to Fedora Accounts, please refile it against Noggin