maciekph / joscar

Automatically exported from code.google.com/p/joscar
0 stars 0 forks source link

Disconnection / reconnection cycle resulted in OscarConnection IllegalStateException #6

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago
joscar [487]

I was suddenly disconnected.  I haven't been able to reproduce this... but an 
attempt to 
reconnect was greeted by permanently attempting and not succeeding.  The debug 
log showed 
the below, then no more connection activity.... canceling the attempt and 
reattempting was 
successful.
==== Debug log

[11:51:30 AM EST] ClientFlapConn$2: NOT_CONNECTED
[11:51:30 AM EST] OscarConnection: Disconnected from 64.12.28.204
[11:51:30 AM EST] AbstractService: MainBosServiceImpl is finished
[11:51:30 AM EST] AbstractService: InfoServiceImpl is finished
[11:51:30 AM EST] AbstractService: BuddyServiceImpl is finished
[11:51:30 AM EST] AbstractService: IcbmServiceImpl is finished
[11:51:30 AM EST] AbstractService: SsiServiceImpl is finished
[11:51:30 AM EST] ConnectionManager: New state: DISCONNECTED - 
net.kano.joustsim.oscar.DisconnectedStateInfo@771727
[11:51:30 AM EST] ClientFlapConn$2: NOT_CONNECTED
[11:51:30 AM EST] OscarConnection: Disconnected from 64.12.201.42
[11:51:30 AM EST] AbstractService: ExternalBosServiceImpl is finished
[11:51:30 AM EST] AbstractService: RoomFinderService is finished
[11:51:30 AM EST] ExternalServiceManager$ExternalServiceConnListener: External 
service 
connection died for service 13 ( <13> 
net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@d41c75)
[11:51:30 AM EST] ExternalServiceManager: Someone requested a refresh of 0xd 
but the arbiter 
net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@d41c75 
keepalive = 
false
[11:51:30 AM EST] AbstractServiceArbiter$1: Conn state changed for 
net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@d41c75:

NOT_CONNECTED
[11:51:30 AM EST] KeepaliveSender: Stopping KeepaliveSender for 
net.kano.joustsim.oscar.oscar.ExternalConnection@e98d49
[11:51:30 AM EST] ClientFlapConn$2: NOT_CONNECTED
[11:51:30 AM EST] OscarConnection: Disconnected from 64.12.29.76
[11:51:30 AM EST] AbstractService: ExternalBosServiceImpl is finished
[11:51:30 AM EST] AbstractService: IconServiceImpl is finished
[11:51:30 AM EST] ExternalServiceManager$ExternalServiceConnListener: External 
service 
connection died for service 16 ( <16> 
net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@4da460)
[11:51:30 AM EST] ExternalServiceManager: Requesting external service 16 for 
net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@4da460
[11:51:30 AM EST] ClientSnacProcessor: Queueing Snac request #92: 
ServiceRequest for family 
0x10
[11:51:30 AM EST] RateQueue: Enqueuing ServiceRequest for family 0x10 within 
ratequeue (class 
1)...
[11:51:30 AM EST] RateQueue: Dequeueing ServiceRequest for family 0x10 from 
ratequeue (class 
1)...
[11:51:30 AM EST] ClientSnacProcessor: Sending SNAC request SnacRequest for 
ServiceRequest 
for family 0x10: listeners: 
[net.kano.joustsim.oscar.oscar.service.bos.MainBosServiceImpl
$ServiceRequestResponseListener@7c4ab7, 
net.kano.joscar.ratelim.RateQueue$1@d4fcf], 
responses: null
[11:51:30 AM EST] AbstractServiceArbiter$1: Conn state changed for 
net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@4da460: 
NOT_CONNECTED
[11:51:30 AM EST] KeepaliveSender: Stopping KeepaliveSender for 
net.kano.joustsim.oscar.oscar.ExternalConnection@b090be
[11:51:35 AM EST] KeepaliveSender: Stopping KeepaliveSender for 
net.kano.joustsim.oscar.oscar.BasicConnection@92c365
[11:51:35 AM EST] BuddyInfoTracker$TrackingThread: Shutting down buddy tracker 
thread for 
net.kano.joustsim.oscar.AimConnection@841a5c
[12:13:18 PM EST] AimConnection: Warning: this AIM connection's certificate and 
signer 
managers will not be set because the trust manager is null
[12:13:18 PM EST] TrustedCertificatesTracker: Warning: Trusted certificates 
tracker will not track 
explicitly trusted certificates since the certificate trust manager is null
[12:13:18 PM EST] TrustedCertificatesTracker: Warning: Trusted certificates 
tracker will not track 
signer-trusted certificates since the signer trust manager is null
[12:13:18 PM EST] SecurityEnabledHandler: Warning: Key manager for 
SecurityEnabledHandler 
will not be set because the AIM session's trust preferences are null
[12:13:18 PM EST] ExternalServiceManager: Creating arbiter for service 13
[12:13:18 PM EST] ExternalServiceManager: Created arbiter for service 13: 
net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@f92e01
[12:13:18 PM EST] AbstractService: Created new 
net.kano.joustsim.oscar.oscar.service.login.LoginService
[12:13:18 PM EST] AbstractService: LoginService is ready
[12:13:18 PM EST] LoginService: Using SecurID provider 
net.adium.joscarBridge.joscarBridge@e4bb3c
[12:13:18 PM EST] OscarConnection: OscarConnection to login.oscar.aol.com 
trying to connect...
[12:13:18 PM EST] ClientFlapConn$2: CONNECTED
[12:13:18 PM EST] OscarConnection: Connected to login.oscar.aol.com
[12:13:18 PM EST] LoginService: Sending key request on 
net.kano.joustsim.oscar.oscar.service.login.LoginService@2ef9bd
[12:13:18 PM EST] AbstractFlapProcessor: Sending Flap packet FlapPacket 
(channel=1, seq=1): 
10 total bytes
[12:13:18 PM EST] ClientSnacProcessor: Queueing Snac request #1: KeyRequest for 
screenname 
tekjew
[12:13:18 PM EST] ClientSnacProcessor: Sending SNAC request SnacRequest for 
KeyRequest for 
screenname tekjew: listeners: null, responses: null
[12:13:18 PM EST] AbstractFlapProcessor: Sending Flap packet FlapPacket 
(channel=2, seq=2): 
34 total bytes
[12:13:18 PM EST] ConnectionManager: New state: AUTHORIZING - 
net.kano.joustsim.oscar.AuthorizingStateInfo@dafccd
[12:13:18 PM EST] ConnectionManager: Tried converting state CONNECTINGAUTH to 
AUTHORIZING, but was in NOT_CONNECTED
[12:13:18 PM EST] KeepaliveSender: Starting KeepaliveSender for 
net.kano.joustsim.oscar.oscar.LoginConnection@56afa8
[12:13:18 PM EST] KeepaliveSender$2: Sending FLAP keepalive on 
net.kano.joustsim.oscar.oscar.LoginConnection@56afa8
[12:13:18 PM EST] AbstractFlapProcessor: Sending Flap packet FlapPacket 
(channel=5, seq=3): 6 
total bytes
[12:13:18 PM EST] ConnectionManager: New state: CONNECTINGAUTH - 
net.kano.joustsim.oscar.AuthorizingStateInfo@698adc
[12:13:18 PM EST] AbstractFlapProcessor: FlapProcessor received packet: 
FlapPacket (channel=1, 
seq=320)
[12:13:18 PM EST] AbstractFlapProcessor: Flap command for FlapPacket 
(channel=1, seq=320): 
LoginFlapCmd: version=1, cookie=null
[12:13:18 PM EST] AbstractFlapProcessor: FlapProcessor received packet: 
FlapPacket (channel=2, 
seq=321)
[12:13:18 PM EST] AbstractFlapProcessor: Flap command for FlapPacket 
(channel=2, seq=321): 
SnacFlapCmd: packet=SnacPacket type 0x17/0x7: 12 bytes (id=1)
[12:13:18 PM EST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 
0x17/0x7: 12 
bytes (id=1) to KeyResponse: key=3807911474
[12:13:18 PM EST] LoginService: Sending authorization request
[12:13:18 PM EST] ClientSnacProcessor: Queueing Snac request #2: AuthRequest: 
sn='tekjew', 
version='ClientVersionInfo: , versionString='Apple iChat', clientid=12570, 
major=1, minor=0, 
point=0, build=388, distCode=198', locale=en_US
[12:13:18 PM EST] ClientSnacProcessor: Sending SNAC request SnacRequest for 
AuthRequest: 
sn='tekjew', version='ClientVersionInfo: , versionString='Apple iChat', 
clientid=12570, major=1, 
minor=0, point=0, build=388, distCode=198', locale=en_US: listeners: null, 
responses: null
[12:13:18 PM EST] AbstractFlapProcessor: Sending Flap packet FlapPacket 
(channel=2, seq=4): 
120 total bytes
[12:13:19 PM EST] AbstractFlapProcessor: FlapProcessor received packet: 
FlapPacket (channel=2, 
seq=322)
[12:13:19 PM EST] AbstractFlapProcessor: Flap command for FlapPacket 
(channel=2, seq=322): 
SnacFlapCmd: packet=SnacPacket type 0x17/0x3: 413 bytes (id=2)
[12:13:19 PM EST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 
0x17/0x3: 
413 bytes (id=2) to AuthResponse: sn='TekJew', server='64.12.28.205', 
port=5190, 
regStatus=0x3 (REGSTATUS_FULL), email='evan@adiumx.com'
[12:13:19 PM EST] LoginService: Login process succeeded: 
net.kano.joustsim.oscar.oscar.loginstatus.LoginSuccessInfo@2d7c76
[12:13:19 PM EST] AbstractService: LoginService is finished
[12:13:19 PM EST] ClientFlapConn$2: NOT_CONNECTED
[12:13:19 PM EST] OscarConnection: Disconnected from login.oscar.aol.com
[12:13:19 PM EST] AbstractService: LoginService is finished
[12:13:19 PM EST] KeepaliveSender: Stopping KeepaliveSender for 
net.kano.joustsim.oscar.oscar.LoginConnection@56afa8
[12:13:19 PM EST] ConnProcessorImpl: Processing connection error 
(ERRTYPE_SNAC_RESPONSE_LISTENER): tried to connect to BOS server in state 
CONNECTINGAUTH: 
net.kano.joustsim.oscar.oscar.OscarConnection$3@d7244e
[12:13:19 PM EST] ConnProcessorImpl: CONNPROCESSOR HAS NO ERROR HANDLERS, 
DUMPING:
ERROR TYPE: ERRTYPE_SNAC_RESPONSE_LISTENER
ERROR INFO: net.kano.joustsim.oscar.oscar.OscarConnection
$3@d7244ejava.lang.IllegalStateException: tried to connect to BOS server in 
state 
CONNECTINGAUTH
    at net.kano.joustsim.oscar.ConnectionManager.prepareMainConn(ConnectionManager.java:
187)
    at net.kano.joustsim.oscar.ConnectionManager.connectBos(ConnectionManager.java:179)
    at net.kano.joustsim.oscar.ConnectionManager.access$1000(ConnectionManager.java:66)
    at net.kano.joustsim.oscar.ConnectionManager$LoginProcessListener.loginSucceeded
(ConnectionManager.java:274)
    at net.kano.joustsim.oscar.oscar.service.login.LoginService.fireLoginSucceeded
(LoginService.java:143)
    at net.kano.joustsim.oscar.oscar.service.login.LoginService.handleSnacPacket
(LoginService.java:219)
    at net.kano.joustsim.oscar.oscar.OscarConnection.handleSnacResponse
(OscarConnection.java:346)
    at net.kano.joustsim.oscar.oscar.OscarConnection$3.handleResponse
(OscarConnection.java:152)
    at net.kano.joscar.snac.ClientSnacProcessor.continueHandling(ClientSnacProcessor.java:
718)
    at net.kano.joscar.snac.AbstractSnacProcessor.processPacket(AbstractSnacProcessor.java:
447)
    at net.kano.joscar.snac.AbstractSnacProcessor.access$100(AbstractSnacProcessor.java:134)
    at net.kano.joscar.snac.AbstractSnacProcessor$1.handlePacket(AbstractSnacProcessor.java:
208)
    at net.kano.joscar.flap.AbstractFlapProcessor.processPacketSynchronously
(AbstractFlapProcessor.java:231)
    at net.kano.joscar.flap.AsynchronousFlapProcessor
$BackgroundPacketProcessor.tryProcessingPackets(AsynchronousFlapProcessor.java:7
5)
    at net.kano.joscar.flap.AsynchronousFlapProcessor$BackgroundPacketProcessor.run
(AsynchronousFlapProcessor.java:63)
    at java.lang.Thread.run(Thread.java:613)

Original issue reported on code.google.com by e...@adiumx.com on 30 Oct 2006 at 5:21