Skip to content

core attempts to sync after logout

Using:

  • bitmask-dev: a031d5ce (current master)
  • soledad: a7ffb49e1169c93af3b728f5db1a5e16e6231590 (current develop)
  • leap_pycommon: c346de0e5f6b4285408a6827795bd37d3e514514 (current develop)

Steps to reproduce:

  • install packages in virtualenv, use make dev-all in bitmask-dev.
  • execute: @bitmaskctl launch@
  • go to: http://localhost:7070
  • login, wait for one sync, logout. (waiting is not mandatory, i did it just to see one sync working)
  • check logs: @/tmp/bitmaskd.log@

I would expect no more sync attempts after logout. Instead, i see that the core continues to attempt to sync, and get an InvalidAuthTokenError as a result.

2016-09-23T08:01:27-0300 [-] Loading /home/drebs/dev/leap/repos/bitmask-dev/src/leap/bitmask/core/bitmaskd.tac...
2016-09-23T08:01:27-0300 [-] Loaded.
2016-09-23T08:01:27-0300 [twisted.scripts._twistd_unix.UnixAppLogger#info] twistd 16.3.0 (/home/drebs/.venv/bin/python2 2.7.9) starting up.
2016-09-23T08:01:27-0300 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.
2016-09-23T08:01:27-0300 [-] Starting Bonafide Service
2016-09-23T08:01:27-0300 [-] Registering hook on_passphrase_entry->soledad
2016-09-23T08:01:27-0300 [-] Registering hook on_bonafide_auth->soledad
2016-09-23T08:01:27-0300 [-] Registering hook on_bonafide_auth->keymanager
2016-09-23T08:01:27-0300 [-] Starting Soledad Service
2016-09-23T08:01:27-0300 [-] Registering hook on_new_soledad_instance->keymanager
2016-09-23T08:01:27-0300 [-] Starting Keymanager Service
2016-09-23T08:01:27-0300 [-] Registering hook on_new_keymanager_instance->mail
2016-09-23T08:01:27-0300 [-] LeapIMAPFactory starting on 1984
2016-09-23T08:01:27-0300 [leap.bitmask.mail.imap.service.imap.LeapIMAPFactory#info] Starting factory 
2016-09-23T08:01:27-0300 [-] SMTPFactory starting on 2013
2016-09-23T08:01:27-0300 [leap.bitmask.mail.smtp.gateway.SMTPFactory#info] Starting factory 
2016-09-23T08:01:27-0300 [-] Starting Mail Service...
2016-09-23T08:01:27-0300 [-] Starting IMAP Service
2016-09-23T08:01:27-0300 [-] Starting SMTP Service
2016-09-23T08:01:27-0300 [-] Starting IncomingMail Service
2016-09-23T08:01:27-0300 [-] starting ZMQ dispatcher
2016-09-23T08:01:27-0300 [-] Site starting on 7070
2016-09-23T08:01:27-0300 [twisted.web.server.Site#info] Starting factory 
2016-09-23T08:01:34-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] Provider already initialized
2016-09-23T08:01:34-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] on_passphrase_entry: New Soledad Instance: drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] Adding a new Keymanager instance for drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] Adding Keymanager instance for: drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] checking if soledad has ever synced...
2016-09-23T08:01:35-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] Provider already initialized
2016-09-23T08:01:35-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] AUTH for drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] POST to https://api.cdev.bitmask.net:4430/1/sessions
2016-09-23T08:01:35-0300 [twisted.web.client._HTTP11ClientFactory#info] Starting factory 
2016-09-23T08:01:35-0300 [-] soledad has synced in the past
2016-09-23T08:01:35-0300 [-] looking up private key for drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [-] found key: 
2016-09-23T08:01:35-0300 [-] Starting Incoming Mail instance for drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [-] Mail post-sync hook: processing queued docs
2016-09-23T08:01:35-0300 [leap.bitmask.mail.incoming.service#debug] fetching mail for: b2a386cd8f06dc89a0e13863895fb328 drebs@cdev.bitmask.net
2016-09-23T08:01:35-0300 [leap.bitmask.mail.incoming.service#info] starting sync...
2016-09-23T08:01:35-0300 [leap.bitmask.mail.incoming.service#info] sync finished
2016-09-23T08:01:35-0300 [leap.bitmask.mail.incoming.service#info] processing doclist
2016-09-23T08:01:35-0300 [leap.bitmask.mail.incoming.service#debug] no docs found
2016-09-23T08:01:36-0300 [HTTP11ClientProtocol (TLSMemoryBIOProtocol),client] PUT to https://api.cdev.bitmask.net:4430/1/sessions/drebs
2016-09-23T08:01:36-0300 [twisted.web.client._HTTP11ClientFactory#info] Starting factory 
2016-09-23T08:01:36-0300 [twisted.web.client._HTTP11ClientFactory#info] Stopping factory 
2016-09-23T08:01:38-0300 [HTTP11ClientProtocol (TLSMemoryBIOProtocol),client] Provider already initialized
2016-09-23T08:01:38-0300 [HTTP11ClientProtocol (TLSMemoryBIOProtocol),client] Passing a new SRP Token to Soledad: drebs@cdev.bitmask.net
2016-09-23T08:01:38-0300 [HTTP11ClientProtocol (TLSMemoryBIOProtocol),client] Provider already initialized
2016-09-23T08:01:38-0300 [HTTP11ClientProtocol (TLSMemoryBIOProtocol),client] Passing a new SRP Token to Keymanager: drebs@cdev.bitmask.net
2016-09-23T08:01:38-0300 [twisted.python.log#info] "127.0.0.1" - - [23/Sep/2016:11:01:38 +0000] "POST /API/bonafide/user HTTP/1.1" 200 131 "http://127.0.0.1:7070/" "Mozilla/5.0 (X11; Linux x86_64; rv:48.0) Gecko/20100101 Firefox/48.0"
2016-09-23T08:01:38-0300 [twisted.web.client._HTTP11ClientFactory#info] Stopping factory 
2016-09-23T08:02:35-0300 [leap.bitmask.mail.incoming.service#debug] fetching mail for: b2a386cd8f06dc89a0e13863895fb328 drebs@cdev.bitmask.net
2016-09-23T08:02:35-0300 [leap.bitmask.mail.incoming.service#info] starting sync...
2016-09-23T08:02:35-0300 [leap.common.http._HTTP11ClientFactory#info] Starting factory 
2016-09-23T08:02:36-0300 [leap.bitmask.mail.incoming.service#info] sync finished
2016-09-23T08:02:36-0300 [leap.bitmask.mail.incoming.service#info] processing doclist
2016-09-23T08:02:36-0300 [leap.bitmask.mail.incoming.service#debug] no docs found
2016-09-23T08:02:40-0300 [_GenericHTTPChannelProtocol,1,127.0.0.1] LOGOUT for drebs@cdev.bitmask.net
2016-09-23T08:02:40-0300 [twisted.web.client._HTTP11ClientFactory#info] Starting factory 
2016-09-23T08:02:40-0300 [twisted.python.log#info] "127.0.0.1" - - [23/Sep/2016:11:02:40 +0000] "POST /API/bonafide/user HTTP/1.1" 200 31 "http://127.0.0.1:7070/" "Mozilla/5.0 (X11; Linux x86_64; rv:48.0) Gecko/20100101 Firefox/48.0"
2016-09-23T08:02:42-0300 [stdout#info] AUTH 
2016-09-23T08:02:42-0300 [stdout#info] resetting user/pass
2016-09-23T08:02:42-0300 [twisted.web.client._HTTP11ClientFactory#info] Stopping factory 
2016-09-23T08:03:35-0300 [leap.bitmask.mail.incoming.service#debug] fetching mail for: b2a386cd8f06dc89a0e13863895fb328 drebs@cdev.bitmask.net
2016-09-23T08:03:35-0300 [leap.bitmask.mail.incoming.service#info] starting sync...
2016-09-23T08:03:35-0300 [leap.bitmask.mail.incoming.service#info] sync failed: 
2016-09-23T08:03:35-0300 [leap.bitmask.mail.incoming.service#info] processing doclist
2016-09-23T08:03:35-0300 [leap.bitmask.mail.incoming.service#debug] no docs found

(from redmine: created on 2016-09-23, closed on 2016-10-06, relates #8461 (closed))