getlantern/lantern — Issue #141: Lantern re-lights after sign-off
Author: forkner
Created: 2012-01-31 00:35:54+00:00
State: open
Labels: ARENDT, critical, proxy

Looks like Xmpp client is still connected and processing messages after sign off on a thread.
Steps for me to reproduce:

Start lantern in Get mode
Wait a bit until the controller has started sending roster updates
Sign off
Wait...
Lamp/Flame icon re-lights

Here is the trimmed log output of this scenario, note after disconnect, there is still a bunch of message processing going on

```
814614 2012-01-30 16:30:36,912 DEBUG [qtp1523242039-137] lantern.DefaultLanternApi.processCall (DefaultLanternApi.java:49) - Got API call SIGNOUT for full URI: /api/signout
814615 2012-01-30 16:30:36,913 INFO [qtp1523242039-137] lantern.DefaultLanternApi.handleSignout (DefaultLanternApi.java:153) - Signing out
814615 2012-01-30 16:30:36,913 INFO [qtp1523242039-137] lantern.Proxifier.stopProxying (Proxifier.java:130) - Unproxying Lantern
814615 2012-01-30 16:30:36,913 INFO [qtp1523242039-137] lantern.Proxifier.unproxyOsxPacFile (Proxifier.java:304) - Unproxying!!
814616 2012-01-30 16:30:36,914 INFO [qtp1523242039-137] lantern.Proxifier.unproxyOsxPacFile (Proxifier.java:306) - Done unproxying!!
814616 2012-01-30 16:30:36,914 INFO [qtp1523242039-137] lantern.MacProxyManager.runScript (MacProxyManager.java:350) - Got args: [-e, tell application "System Events"
tell security preferences
get require password to unlock
end tell
end tell
]
814834 2012-01-30 16:30:37,132 INFO [qtp1523242039-137] lantern.Proxifier.osxPrefPanesLocked (Proxifier.java:330) - Result of script is: false

814834 2012-01-30 16:30:37,132 INFO [qtp1523242039-137] lantern.MacProxyManager.runScript (MacProxyManager.java:350) - Got args: [-e, do shell script "./configureNetworkServices.bash off" without altering line endings]
816445 2012-01-30 16:30:38,743 INFO [qtp1523242039-137] lantern.Proxifier.proxyOsxViaScript (Proxifier.java:186) - Result of script is:

816446 2012-01-30 16:30:38,744 INFO [qtp1523242039-137] lantern.DefaultXmppHandler.disconnect (DefaultXmppHandler.java:328) - Disconnecting!!
816446 2012-01-30 16:30:38,744 INFO [qtp1523242039-137] lantern.SystemTrayImpl.onConnectivityStateChanged (SystemTrayImpl.java:184) - Got connectivity state changed DISCONNECTING
816447 2012-01-30 16:30:38,745 INFO [Thread-1] lantern.SystemTrayImpl.run (SystemTrayImpl.java:213) - Customizing image on OSX...
816451 2012-01-30 16:30:38,749 INFO [qtp1523242039-137] lantern.DefaultXmppHandler.processPresence (DefaultXmppHandler.java:556) - Got presence: [ REDACTED ]

[ REPEATS MANY TIMES ]

816498 2012-01-30 16:30:38,796 INFO [Smack Listener Processor (1)] lantern.DefaultXmppHandler.accept (DefaultXmppHandler.java:308) - Filtered out packet:
816500 2012-01-30 16:30:38,798 INFO [qtp1523242039-137] lantern.DefaultXmppHandler.processPresence (DefaultXmppHandler.java:556) - Got presence: [ REDACTED ]

[ REPEATS MANY TIMES ]

816515 2012-01-30 16:30:38,813 INFO [qtp1523242039-137] xmpp.ControlXmppP2PClient.connectionClosed (ControlXmppP2PClient.java:1024) - XMPP connection closed. Creating new connection.
816515 2012-01-30 16:30:38,813 INFO [qtp1523242039-137] xmpp.ControlXmppP2PClient.connectionClosed (ControlXmppP2PClient.java:1026) - Not maintaining connection when the user has explictly logged out.
816565 2012-01-30 16:30:38,863 INFO [Smack Listener Processor (1)] lantern.DefaultXmppHandler.accept (DefaultXmppHandler.java:308) - Filtered out packet:
816666 2012-01-30 16:30:38,964 INFO [qtp1523242039-137] lantern.SystemTrayImpl.onConnectivityStateChanged (SystemTrayImpl.java:184) - Got connectivity state changed DISCONNECTED
816667 2012-01-30 16:30:38,965 INFO [Thread-1] lantern.SystemTrayImpl.run (SystemTrayImpl.java:213) - Customizing image on OSX...
816694 2012-01-30 16:30:38,992 INFO [qtp1523242039-137] lantern.DefaultLanternApi.returnJson (DefaultLanternApi.java:255) - Returning json...
821667 2012-01-30 16:30:43,965 INFO [Smack Listener Processor (1)] lantern.DefaultXmppHandler.processPresence (DefaultXmppHandler.java:556) - Got presence: [ REDACTED ]
825068 2012-01-30 16:30:47,366 INFO [Timer-1] lantern.DefaultXmppHandler.updatePresence (DefaultXmppHandler.java:459) - Sending presence available
825069 2012-01-30 16:30:47,367 INFO [Timer-1] lantern.DefaultXmppHandler.updatePresence (DefaultXmppHandler.java:488) - Reporting data: {"v":"lantern_version_tok","rp":305,"db":0,"bp":16193065,"cc":"US","dr":0}
825285 2012-01-30 16:30:47,583 INFO [Smack Listener Processor (1)] xmpp.ControlXmppP2PClient.processPacket (ControlXmppP2PClient.java:373) - Checking message ID: 16FBA663
825285 2012-01-30 16:30:47,583 INFO [Smack Listener Processor (1)] lantern.DefaultXmppHandler.accept (DefaultXmppHandler.java:308) - Filtered out packet:
825285 2012-01-30 16:30:47,583 INFO [pool-16-thread-9] xmpp.ControlXmppP2PClient.run (ControlXmppP2PClient.java:504) - Got message from lantern-controller@appspot.com/bot
825287 2012-01-30 16:30:47,585 INFO [pool-16-thread-9] xmpp.ControlXmppP2PClient.run (ControlXmppP2PClient.java:508) - No message type!! Notifying listeners
825287 2012-01-30 16:30:47,585 INFO [pool-16-thread-9] xmpp.ControlXmppP2PClient.notifyListeners (ControlXmppP2PClient.java:605) - Notifying global listeners
825287 2012-01-30 16:30:47,585 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processMessage (DefaultXmppHandler.java:115) - Got chat participant: [ REDACTED ]

[ REDACTED ]

825287 2012-01-30 16:30:47,585 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:351) - Lantern controlling agent response
825287 2012-01-30 16:30:47,585 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:353) - Body: [ REDACTED ]
825287 2012-01-30 16:30:47,585 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:375) - Scheduled next info request in 60000 milliseconds
825288 2012-01-30 16:30:47,586 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxy (DefaultXmppHandler.java:716) - Considering proxy: rlanternz.appspot.com
825288 2012-01-30 16:30:47,586 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addLaeProxy (DefaultXmppHandler.java:788) - Adding LAE proxy
825288 2012-01-30 16:30:47,586 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxyWithChecks (DefaultXmppHandler.java:806) - We already know about proxy ProxyHolder [ REDACTED ]
825288 2012-01-30 16:30:47,586 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxy (DefaultXmppHandler.java:716) - Considering proxy: laeproxyhr1.appspot.com
825289 2012-01-30 16:30:47,587 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addLaeProxy (DefaultXmppHandler.java:788) - Adding LAE proxy
825289 2012-01-30 16:30:47,587 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxyWithChecks (DefaultXmppHandler.java:806) - We already know about proxy ProxyHolder [ REDACTED ]
825289 2012-01-30 16:30:47,587 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxy (DefaultXmppHandler.java:716) - Considering proxy: [ REDACTED ]
825289 2012-01-30 16:30:47,587 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxy (DefaultXmppHandler.java:728) - We are: [ REDACTED ]
825289 2012-01-30 16:30:47,587 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxy (DefaultXmppHandler.java:729) - Service name: gmail.com
825289 2012-01-30 16:30:47,587 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.addProxyWithChecks (DefaultXmppHandler.java:806) - We already know about proxy ProxyHolder [ REDACTED ]
825290 2012-01-30 16:30:47,588 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:392) - Dispatching CONNECTED event
825290 2012-01-30 16:30:47,588 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:401) - Already displayed update? false
825290 2012-01-30 16:30:47,588 INFO [pool-3-thread-14] lantern.SystemTrayImpl.onConnectivityStateChanged (SystemTrayImpl.java:184) - Got connectivity state changed CONNECTED
825290 2012-01-30 16:30:47,588 INFO [Thread-1] lantern.SystemTrayImpl.run (SystemTrayImpl.java:213) - Customizing image on OSX...
825405 2012-01-30 16:30:47,703 INFO [Smack Listener Processor (1)] xmpp.ControlXmppP2PClient.processPacket (ControlXmppP2PClient.java:373) - Checking message ID: 2CC563EE
825406 2012-01-30 16:30:47,704 INFO [pool-16-thread-9] xmpp.ControlXmppP2PClient.run (ControlXmppP2PClient.java:504) - Got message from lantern-controller@appspot.com/bot
825406 2012-01-30 16:30:47,704 INFO [Smack Listener Processor (1)] lantern.DefaultXmppHandler.accept (DefaultXmppHandler.java:308) - Filtered out packet:
825406 2012-01-30 16:30:47,704 INFO [pool-16-thread-9] xmpp.ControlXmppP2PClient.run (ControlXmppP2PClient.java:508) - No message type!! Notifying listeners
825406 2012-01-30 16:30:47,704 INFO [pool-16-thread-9] xmpp.ControlXmppP2PClient.notifyListeners (ControlXmppP2PClient.java:605) - Notifying global listeners
825406 2012-01-30 16:30:47,704 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processMessage (DefaultXmppHandler.java:115) - Got chat participant: [ REDACTED ]

[ REDACTED ]

825406 2012-01-30 16:30:47,704 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:351) - Lantern controlling agent response
825406 2012-01-30 16:30:47,704 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:353) - Body: [ REDACTED ]
825407 2012-01-30 16:30:47,705 INFO [pool-16-thread-9] lantern.DefaultXmppHandler.processLanternHubMessage (DefaultXmppHandler.java:364) - Ignoring duplicate info request scheduling- scheduled request 120 milliseconds ago.
829392 2012-01-30 16:30:51,690 INFO [New I/O client worker #5-5] lantern.OutboundHandler.channelClosed (OutboundHandler.java:162) - Channel to external proxy closed
829392 2012-01-30 16:30:51,690 INFO [New I/O server worker #3-7] lantern.DispatchingProxyRelayHandler.channelClosed (DispatchingProxyRelayHandler.java:546) - Got inbound channel closed. Closing outbound.
```