rendered paste bodyOpened 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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: <CapabilityBlock: 09 46 13 43 4c 7f 11 d1 82 22 44 45 53 54 00 00 (BLOCK_FILE_SEND)>, 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)