Opened debug log at 2006-07-11 18:48:48 +0200 [18.48 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller ChecksumController [18.48 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.ChecksumController: ComputedChecksumsInfo [18.48 Uhr CEST] RvConnectionImpl: Changing state controller from ChecksumController [18.48 Uhr CEST] RvConnectionImpl: Getting next controller for ChecksumController (ended with ComputedChecksumsInfo) [18.48 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller SendPassivelyController [18.48 Uhr CEST] AbstractConnectionController: SendPassivelyController opening socket [18.48 Uhr CEST] AbstractRvSessionConnectionInfo: Setting initiator for RvSession with 123029196 (sessionid=0xa976003e1d37c8a1) to ME [18.48 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendReqRvCmd: reqIndex=1, message='InvitationMessage: "null" (in de)', connInfo=ConnectionInfo: internalIP=localhost/192.168.0.100, externalIP=null, proxyIP=null, port=50985, fileSendBlock=FileSendBlock: type=1: 54.jpg: 225855 bytes total [18.48 Uhr CEST] ClientSnacProcessor: Queueing Snac request #299: SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.48 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.48 Uhr CEST] TimerTimeoutHandler: Started timeout for SendPassivelyController: 10000ms [18.48 Uhr CEST] RateClassMonitor: Class 3 should be waiting -57565ms (avg is 4500ms) [18.48 Uhr CEST] RateClassMonitor: Class 3 should be waiting -57566ms (avg is 4500ms) [18.48 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.48 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.48 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=300): 160 total bytes [18.48 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15368) [18.48 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15368): SnacFlapCmd: packet=SnacPacket type 0x4/0x1: 2 bytes (id=299) [18.48 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x4/0x1: 2 bytes (id=299) to SnacError: code=0x9 (name: CODE_NOT_SUPPORTED_BY_CLIENT) [18.48 Uhr CEST] BuddyIconTracker$3: Re-requesting buddy icon {ExtraInfoData=ExtraInfoData: flags=0x41 (FLAG_UPLOAD_ICON | FLAG_HASH_PRESENT), data=3c 73 58 c1 6e a8 84 64 47 62 49 09 59 88 2d d3, Screenname=284854803} [18.48 Uhr CEST] BuddyIconTracker: Requesting buddy icon for 284854803 [18.48 Uhr CEST] ExternalServiceManager: Someone requested 0x10 but there's already an external connection: net.kano.joustsim.oscar.oscar.ExternalConnection@44efa0 [18.48 Uhr CEST] ExternalServiceManager$ExternalServiceConnListener: External service connection died for service 16 ( <16> net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53) [18.48 Uhr CEST] ExternalServiceManager: Requesting external service 16 for net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53 [18.48 Uhr CEST] ClientSnacProcessor: Queueing Snac request #300: ServiceRequest for family 0x10 [18.48 Uhr CEST] RateQueue: Enqueuing ServiceRequest for family 0x10 within ratequeue (class 1)... [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53: FAILED [18.48 Uhr CEST] RateClassMonitor: Class 1 should be waiting -345982ms (avg is 6000ms) [18.48 Uhr CEST] RateClassMonitor: Class 1 should be waiting -345982ms (avg is 6000ms) [18.48 Uhr CEST] RateQueue: Dequeueing ServiceRequest for family 0x10 from ratequeue (class 1)... [18.48 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for ServiceRequest for family 0x10: listeners: [net.kano.joustsim.oscar.oscar.service.bos.MainBosServiceImpl$ServiceRequestResponseListener@6607fb], responses: null [18.48 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=301): 18 total bytes [18.48 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15369) [18.48 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15369): SnacFlapCmd: packet=SnacPacket type 0x1/0x5, flag1=0x80: 291 bytes (id=300) [18.48 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x1/0x5, flag1=0x80: 283 bytes (id=300) to ServiceRedirect: family=0x10, host=205.188.12.92, port=-1, cookie=256 bytes [18.48 Uhr CEST] ExternalServiceManager$ArbitratedExternalServiceListener: Connecting to 205.188.12.92:-1 for external service 16 [18.48 Uhr CEST] AbstractService: Created new net.kano.joustsim.oscar.oscar.service.bos.ExternalBosServiceImpl [18.48 Uhr CEST] AbstractService: Created new net.kano.joustsim.oscar.oscar.service.icon.IconServiceImpl [18.48 Uhr CEST] OscarConnection: OscarConnection to 205.188.12.92 trying to connect... [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53: INITING [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53: RESOLVING [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53: CONNECTING [18.48 Uhr CEST] ExternalServiceManager: Requesting external service 13 for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192 [18.48 Uhr CEST] ClientSnacProcessor: Queueing Snac request #301: ServiceRequest for family 0xd [18.48 Uhr CEST] RateQueue: Enqueuing ServiceRequest for family 0xd within ratequeue (class 1)... [18.48 Uhr CEST] RateClassMonitor: Class 1 should be waiting -339598ms (avg is 5944ms) [18.48 Uhr CEST] RateClassMonitor: Class 1 should be waiting -339598ms (avg is 5944ms) [18.48 Uhr CEST] RateQueue: Dequeueing ServiceRequest for family 0xd from ratequeue (class 1)... [18.48 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for ServiceRequest for family 0xd: listeners: [net.kano.joustsim.oscar.oscar.service.bos.MainBosServiceImpl$ServiceRequestResponseListener@1ebaf3], responses: null [18.48 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=302): 18 total bytes [18.48 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15370) [18.48 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15370): SnacFlapCmd: packet=SnacPacket type 0x1/0x5, flag1=0x80: 290 bytes (id=301) [18.48 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x1/0x5, flag1=0x80: 282 bytes (id=301) to ServiceRedirect: family=0xd, host=64.12.201.36, port=-1, cookie=256 bytes [18.48 Uhr CEST] ExternalServiceManager$ArbitratedExternalServiceListener: Connecting to 64.12.201.36:-1 for external service 13 [18.48 Uhr CEST] AbstractService: Created new net.kano.joustsim.oscar.oscar.service.bos.ExternalBosServiceImpl [18.48 Uhr CEST] AbstractService: Created new net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderService [18.48 Uhr CEST] OscarConnection: OscarConnection to 64.12.201.36 trying to connect... [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: INITING [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: RESOLVING [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: CONNECTING [18.48 Uhr CEST] BuddyIconTracker$3: Re-requesting buddy icon {ExtraInfoData=ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72, Screenname=61978879} [18.48 Uhr CEST] BuddyIconTracker: Requesting buddy icon for 61978879 [18.48 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=1, seq=1): 270 total bytes [18.48 Uhr CEST] OscarConnection: Connected to 64.12.201.36 [18.48 Uhr CEST] ClientSnacProcessor: Queueing Snac request #1: RoomRightsRequest [18.48 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for RoomRightsRequest: listeners: [net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderService$1@1aec43], responses: null [18.48 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=2): 16 total bytes [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: CONNECTED [18.48 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=1, seq=22085) [18.48 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=1, seq=22085): LoginFlapCmd: version=1, cookie=null [18.48 Uhr CEST] OscarConnection: Disconnected from 64.12.201.36 [18.48 Uhr CEST] AbstractService: ExternalBosServiceImpl is finished [18.48 Uhr CEST] AbstractService: RoomFinderService is finished [18.48 Uhr CEST] ExternalServiceManager$ExternalServiceConnListener: External service connection died for service 13 ( <13> net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192) [18.48 Uhr CEST] ExternalServiceManager: Someone requested a refresh of 0xd but the arbiter net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192 keepalive = false [18.48 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: NOT_CONNECTED [18.49 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.SendPassivelyController: FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] RvConnectionImpl: Changing state controller from SendPassivelyController [18.49 Uhr CEST] RvConnectionImpl: Getting next controller for SendPassivelyController (ended with FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds) [18.49 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller RedirectConnectionController [18.49 Uhr CEST] AbstractStateController: Error in SendPassivelyController:java.nio.channels.ClosedByInterruptException at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152) at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.PassiveConnectionController$MyConnector.createStream(PassiveConnectionController.java:101) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.createStream(AbstractConnectionController.java:163) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.openConnectionInThread(AbstractConnectionController.java:149) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController$2.run(AbstractConnectionController.java:118) at java.lang.Thread.run(Thread.java:613) [18.49 Uhr CEST] AbstractStateController: State controller SendPassivelyController tried to set new end state ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractStateController: State controller SendPassivelyController tried to set new end state LocallyCancelledInfo but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractConnectionController: RedirectConnectionController opening socket [18.49 Uhr CEST] AbstractRvSessionConnectionInfo: Setting initiator for RvSession with 123029196 (sessionid=0xa976003e1d37c8a1) to ME [18.49 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendReqRvCmd: reqIndex=2, message='InvitationMessage: "null" (in de)', connInfo=ConnectionInfo: internalIP=localhost/192.168.0.100, externalIP=null, proxyIP=null, port=50988, fileSendBlock=FileSendBlock: type=1: 54.jpg: 225855 bytes total [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #302: SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.49 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.49 Uhr CEST] TimerTimeoutHandler: Started timeout for RedirectConnectionController: 10000ms [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51539ms (avg is 4500ms) [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51540ms (avg is 4500ms) [18.49 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=303): 160 total bytes [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15371) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15371): SnacFlapCmd: packet=SnacPacket type 0x4/0x1: 2 bytes (id=302) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x4/0x1: 2 bytes (id=302) to SnacError: code=0x9 (name: CODE_NOT_SUPPORTED_BY_CLIENT) [18.49 Uhr CEST] ExternalServiceManager$4: External service for arbiter net.kano.joustsim.oscar.oscar.service.icon.IconServiceArbiter@a14c53(0x10) timed out after 11.599s; retrying [18.49 Uhr CEST] ExternalServiceManager: Someone requested 0x10 but there's already an external connection: net.kano.joustsim.oscar.oscar.ExternalConnection@9896c7 [18.49 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.RedirectConnectionController: FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] RvConnectionImpl: Changing state controller from RedirectConnectionController [18.49 Uhr CEST] RvConnectionImpl: Getting next controller for RedirectConnectionController (ended with FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds) [18.49 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller RedirectConnectionController [18.49 Uhr CEST] AbstractStateController: Error in RedirectConnectionController:java.nio.channels.ClosedByInterruptException at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152) at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.PassiveConnectionController$MyConnector.createStream(PassiveConnectionController.java:101) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.createStream(AbstractConnectionController.java:163) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.openConnectionInThread(AbstractConnectionController.java:149) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController$2.run(AbstractConnectionController.java:118) at java.lang.Thread.run(Thread.java:613) [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state LocallyCancelledInfo but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractConnectionController: RedirectConnectionController opening socket [18.49 Uhr CEST] AbstractRvSessionConnectionInfo: Setting initiator for RvSession with 123029196 (sessionid=0xa976003e1d37c8a1) to ME [18.49 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendReqRvCmd: reqIndex=3, message='InvitationMessage: "null" (in de)', connInfo=ConnectionInfo: internalIP=localhost/192.168.0.100, externalIP=null, proxyIP=null, port=50989, fileSendBlock=FileSendBlock: type=1: 54.jpg: 225855 bytes total [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #303: SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.49 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.49 Uhr CEST] TimerTimeoutHandler: Started timeout for RedirectConnectionController: 10000ms [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51526ms (avg is 4500ms) [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51527ms (avg is 4500ms) [18.49 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=304): 160 total bytes [18.49 Uhr CEST] ExternalServiceManager$4: External service for arbiter net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192(0xd) timed out after 14.999s; retrying [18.49 Uhr CEST] ExternalServiceManager: Requesting external service 13 for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192 [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #304: ServiceRequest for family 0xd [18.49 Uhr CEST] RateQueue: Enqueuing ServiceRequest for family 0xd within ratequeue (class 1)... [18.49 Uhr CEST] RateClassMonitor: Class 1 should be waiting -348641ms (avg is 6000ms) [18.49 Uhr CEST] RateClassMonitor: Class 1 should be waiting -348641ms (avg is 6000ms) [18.49 Uhr CEST] RateQueue: Dequeueing ServiceRequest for family 0xd from ratequeue (class 1)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for ServiceRequest for family 0xd: listeners: [net.kano.joustsim.oscar.oscar.service.bos.MainBosServiceImpl$ServiceRequestResponseListener@5ad0f0], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=305): 18 total bytes [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15372) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15372): SnacFlapCmd: packet=SnacPacket type 0x4/0x1: 2 bytes (id=303) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x4/0x1: 2 bytes (id=303) to SnacError: code=0x9 (name: CODE_NOT_SUPPORTED_BY_CLIENT) [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15373) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15373): SnacFlapCmd: packet=SnacPacket type 0x1/0x5, flag1=0x80: 290 bytes (id=304) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x1/0x5, flag1=0x80: 282 bytes (id=304) to ServiceRedirect: family=0xd, host=64.12.201.36, port=-1, cookie=256 bytes [18.49 Uhr CEST] ExternalServiceManager$ArbitratedExternalServiceListener: Connecting to 64.12.201.36:-1 for external service 13 [18.49 Uhr CEST] AbstractService: Created new net.kano.joustsim.oscar.oscar.service.bos.ExternalBosServiceImpl [18.49 Uhr CEST] AbstractService: Created new net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderService [18.49 Uhr CEST] OscarConnection: OscarConnection to 64.12.201.36 trying to connect... [18.49 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: INITING [18.49 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: RESOLVING [18.49 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: CONNECTING [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=1, seq=1): 270 total bytes [18.49 Uhr CEST] OscarConnection: Connected to 64.12.201.36 [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #1: RoomRightsRequest [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for RoomRightsRequest: listeners: [net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderService$1@827a5a], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=2): 16 total bytes [18.49 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: CONNECTED [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=1, seq=23006) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=1, seq=23006): LoginFlapCmd: version=1, cookie=null [18.49 Uhr CEST] OscarConnection: Disconnected from 64.12.201.36 [18.49 Uhr CEST] AbstractService: ExternalBosServiceImpl is finished [18.49 Uhr CEST] AbstractService: RoomFinderService is finished [18.49 Uhr CEST] ExternalServiceManager$ExternalServiceConnListener: External service connection died for service 13 ( <13> net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192) [18.49 Uhr CEST] ExternalServiceManager: Someone requested a refresh of 0xd but the arbiter net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192 keepalive = false [18.49 Uhr CEST] AbstractServiceArbiter$1: Conn state changed for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192: NOT_CONNECTED [18.49 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.RedirectConnectionController: FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] RvConnectionImpl: Changing state controller from RedirectConnectionController [18.49 Uhr CEST] RvConnectionImpl: Getting next controller for RedirectConnectionController (ended with FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds) [18.49 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller RedirectConnectionController [18.49 Uhr CEST] AbstractStateController: Error in RedirectConnectionController:java.nio.channels.ClosedByInterruptException at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152) at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.PassiveConnectionController$MyConnector.createStream(PassiveConnectionController.java:101) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.createStream(AbstractConnectionController.java:163) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.openConnectionInThread(AbstractConnectionController.java:149) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController$2.run(AbstractConnectionController.java:118) at java.lang.Thread.run(Thread.java:613) [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state LocallyCancelledInfo but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractConnectionController: RedirectConnectionController opening socket [18.49 Uhr CEST] AbstractRvSessionConnectionInfo: Setting initiator for RvSession with 123029196 (sessionid=0xa976003e1d37c8a1) to ME [18.49 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendReqRvCmd: reqIndex=4, message='InvitationMessage: "null" (in de)', connInfo=ConnectionInfo: internalIP=localhost/192.168.0.100, externalIP=null, proxyIP=null, port=50992, fileSendBlock=FileSendBlock: type=1: 54.jpg: 225855 bytes total [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #305: SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.49 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.49 Uhr CEST] TimerTimeoutHandler: Started timeout for RedirectConnectionController: 10000ms [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51527ms (avg is 4500ms) [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51527ms (avg is 4500ms) [18.49 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=306): 160 total bytes [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15374) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15374): SnacFlapCmd: packet=SnacPacket type 0x4/0x1: 2 bytes (id=305) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x4/0x1: 2 bytes (id=305) to SnacError: code=0x9 (name: CODE_NOT_SUPPORTED_BY_CLIENT) [18.49 Uhr CEST] ExternalServiceManager$4: External service for arbiter net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192(0xd) timed out after 14.998s; retrying [18.49 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.RedirectConnectionController: FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] RvConnectionImpl: Changing state controller from RedirectConnectionController [18.49 Uhr CEST] RvConnectionImpl: Getting next controller for RedirectConnectionController (ended with FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds) [18.49 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller RedirectConnectionController [18.49 Uhr CEST] AbstractStateController: Error in RedirectConnectionController:java.nio.channels.ClosedByInterruptException at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152) at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.PassiveConnectionController$MyConnector.createStream(PassiveConnectionController.java:101) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.createStream(AbstractConnectionController.java:163) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.openConnectionInThread(AbstractConnectionController.java:149) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController$2.run(AbstractConnectionController.java:118) at java.lang.Thread.run(Thread.java:613) [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state LocallyCancelledInfo but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractConnectionController: RedirectConnectionController opening socket [18.49 Uhr CEST] AbstractRvSessionConnectionInfo: Setting initiator for RvSession with 123029196 (sessionid=0xa976003e1d37c8a1) to ME [18.49 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendReqRvCmd: reqIndex=5, message='InvitationMessage: "null" (in de)', connInfo=ConnectionInfo: internalIP=localhost/192.168.0.100, externalIP=null, proxyIP=null, port=50993, fileSendBlock=FileSendBlock: type=1: 54.jpg: 225855 bytes total [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #306: SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.49 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.49 Uhr CEST] TimerTimeoutHandler: Started timeout for RedirectConnectionController: 10000ms [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51540ms (avg is 4500ms) [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51540ms (avg is 4500ms) [18.49 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=307): 160 total bytes [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15375) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15375): SnacFlapCmd: packet=SnacPacket type 0x4/0x1: 2 bytes (id=306) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x4/0x1: 2 bytes (id=306) to SnacError: code=0x9 (name: CODE_NOT_SUPPORTED_BY_CLIENT) [18.49 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.RedirectConnectionController: FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] RvConnectionImpl: Changing state controller from RedirectConnectionController [18.49 Uhr CEST] RvConnectionImpl: Getting next controller for RedirectConnectionController (ended with FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds) [18.49 Uhr CEST] RvConnectionImpl: Transfer OutgoingFileTransferImpl with 123029196 changing to state controller RedirectConnectionController [18.49 Uhr CEST] AbstractStateController: Error in RedirectConnectionController:java.nio.channels.ClosedByInterruptException at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152) at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.PassiveConnectionController$MyConnector.createStream(PassiveConnectionController.java:101) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.createStream(AbstractConnectionController.java:163) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.openConnectionInThread(AbstractConnectionController.java:149) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController$2.run(AbstractConnectionController.java:118) at java.lang.Thread.run(Thread.java:613) [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state LocallyCancelledInfo but it was already FailureEventInfo: event=ConnectionTimedOutEvent: timeout=10.0 seconds [18.49 Uhr CEST] AbstractConnectionController: RedirectConnectionController opening socket [18.49 Uhr CEST] AbstractRvSessionConnectionInfo: Setting initiator for RvSession with 123029196 (sessionid=0xa976003e1d37c8a1) to ME [18.49 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendReqRvCmd: reqIndex=6, message='InvitationMessage: "null" (in de)', connInfo=ConnectionInfo: internalIP=localhost/192.168.0.100, externalIP=null, proxyIP=null, port=50995, fileSendBlock=FileSendBlock: type=1: 54.jpg: 225855 bytes total [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #307: SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.49 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.49 Uhr CEST] TimerTimeoutHandler: Started timeout for RedirectConnectionController: 10000ms [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51567ms (avg is 4500ms) [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -51568ms (avg is 4500ms) [18.49 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=0, sessid=-6235796367269705567 -- AbstractRvIcbm: status=0, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=308): 160 total bytes [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15376) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15376): SnacFlapCmd: packet=SnacPacket type 0x4/0x1: 2 bytes (id=307) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x4/0x1: 2 bytes (id=307) to SnacError: code=0x9 (name: CODE_NOT_SUPPORTED_BY_CLIENT) [18.49 Uhr CEST] RvConnectionImpl: New state for OutgoingFileTransferImpl with 123029196 is FAILED, so we're done (from event net.kano.joustsim.oscar.oscar.service.icbm.ft.events.LocallyCancelledEvent@afaa85) [18.49 Uhr CEST] RvConnectionImpl: Changing state of OutgoingFileTransferImpl with 123029196 to FAILED because of net.kano.joustsim.oscar.oscar.service.icbm.ft.events.LocallyCancelledEvent@afaa85 [18.49 Uhr CEST] RvProcessor$RvSessionImpl: Sending RV to 123029196: FileSendRejectRvCmd: rejectCode=1 [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #308: SendRvIcbm to 123029196: , status=1, sessid=-6235796367269705567 -- AbstractRvIcbm: status=1, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 [18.49 Uhr CEST] RateQueue: Enqueuing SendRvIcbm to 123029196: , status=1, sessid=-6235796367269705567 -- AbstractRvIcbm: status=1, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 within ratequeue (class 3)... [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -44087ms (avg is 4404ms) [18.49 Uhr CEST] RateClassMonitor: Class 3 should be waiting -44087ms (avg is 4404ms) [18.49 Uhr CEST] RateQueue: Dequeueing SendRvIcbm to 123029196: , status=1, sessid=-6235796367269705567 -- AbstractRvIcbm: status=1, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567 from ratequeue (class 3)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for SendRvIcbm to 123029196: , status=1, sessid=-6235796367269705567 -- AbstractRvIcbm: status=1, rvSessionId=-6235796367269705567, on top of SendRvIcbm: channel=2, messageId=-6235796367269705567: listeners: [net.kano.joscar.rv.RvProcessor$RvSessionImpl$1@180809], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=309): 76 total bytes [18.49 Uhr CEST] AbstractStateController: Error in RedirectConnectionController:java.nio.channels.ClosedByInterruptException at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152) at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.PassiveConnectionController$MyConnector.createStream(PassiveConnectionController.java:101) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.createStream(AbstractConnectionController.java:163) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController.openConnectionInThread(AbstractConnectionController.java:149) at net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.AbstractConnectionController$2.run(AbstractConnectionController.java:118) at java.lang.Thread.run(Thread.java:613) [18.49 Uhr CEST] AbstractStateController: New state for net.kano.joustsim.oscar.oscar.service.icbm.ft.controllers.RedirectConnectionController: ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null [18.49 Uhr CEST] RvConnectionImpl: Changing state controller from RedirectConnectionController [18.49 Uhr CEST] RvConnectionImpl: Getting next controller for RedirectConnectionController (ended with ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null) [18.49 Uhr CEST] RvConnectionImpl: Someone tried changing controller for OutgoingFileTransferImpl with 123029196 to RedirectToProxyController, but we are done so it is being ignored [18.49 Uhr CEST] AbstractStateController: State controller RedirectConnectionController tried to set new end state LocallyCancelledInfo but it was already ExceptionStateInfo: java.nio.channels.ClosedByInterruptException: null [18.49 Uhr CEST] ExternalServiceManager: Requesting external service 13 for net.kano.joustsim.oscar.oscar.service.chatrooms.RoomFinderServiceArbiter@9c2192 [18.49 Uhr CEST] ClientSnacProcessor: Queueing Snac request #309: ServiceRequest for family 0xd [18.49 Uhr CEST] RateQueue: Enqueuing ServiceRequest for family 0xd within ratequeue (class 1)... [18.49 Uhr CEST] RateClassMonitor: Class 1 should be waiting -373005ms (avg is 6000ms) [18.49 Uhr CEST] RateClassMonitor: Class 1 should be waiting -373006ms (avg is 6000ms) [18.49 Uhr CEST] RateQueue: Dequeueing ServiceRequest for family 0xd from ratequeue (class 1)... [18.49 Uhr CEST] ClientSnacProcessor: Sending SNAC request SnacRequest for ServiceRequest for family 0xd: listeners: [net.kano.joustsim.oscar.oscar.service.bos.MainBosServiceImpl$ServiceRequestResponseListener@fa2e2e], responses: null [18.49 Uhr CEST] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=310): 18 total bytes [18.49 Uhr CEST] FlapProcessor: FlapProcessor received packet: FlapPacket (channel=2, seq=15377) [18.49 Uhr CEST] FlapProcessor: Flap command for FlapPacket (channel=2, seq=15377): SnacFlapCmd: packet=SnacPacket type 0x1/0x1, flag1=0x80: 10 bytes (id=309) [18.49 Uhr CEST] AbstractSnacProcessor: Converted Snac packet SnacPacket type 0x1/0x1, flag1=0x80: 2 bytes (id=309) to SnacError: code=0xd (name: CODE_REQUEST_DENIED) [18.49 Uhr CEST] MainBosServiceImpl$ServiceRequestResponseListener: unexpected response to service request: SnacError: code=0xd (name: CODE_REQUEST_DENIED)