Uploaded image for project: 'Kraken'
  1. Kraken
  2. KR-146

Empty "RootItem" causes exception upon logging in, preventing login altogether

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 1.1.2
    • Fix Version/s: 1.1.3
    • Component/s: AIM/ICQ Transport
    • Labels:
      None

      Description

      2009.11.27 15:40:50 JettyLog: EOF
      2009.11.27 15:40:53 000456 (01/05/00) - Connection #5 tested: OK
      2009.11.27 15:40:53 000457 (01/05/00) - Connection #5 tested: OK
      2009.11.27 15:40:53 000457 (01/05/00) - Connection #2 tested: OK
      2009.11.27 15:40:53 000458 (01/05/00) - Connection #2 tested: OK
      2009.11.27 15:40:53 AuthorizationManager: Trying Default Mapping.map(test)
      2009.11.27 15:40:53 DefaultAuthorizationMapping: No realm found
      2009.11.27 15:40:53 AuthorizationManager: Trying Default Policy.authorize(test , test)
      2009.11.27 15:40:53 DefaultAuthorizationPolicy: Checking authenID realm
      2009.11.27 15:40:53 000458 (01/05/00) - Connection #1 tested: OK
      2009.11.27 15:40:53 000459 (01/05/00) - Connection #1 tested: OK
      2009.11.27 15:40:53 000459 (01/05/00) - Connection #3 tested: OK
      2009.11.27 15:40:53 000460 (01/05/00) - Connection #3 tested: OK
      2009.11.27 15:40:53 Received presence packet: <presence from="test@worktrek.com/b3632889" to="icq.worktrek.com"/>
      2009.11.27 15:40:53 000460 (01/05/00) - Connection #4 tested: OK
      2009.11.27 15:40:53 000461 (01/05/00) - Connection #4 tested: OK
      2009.11.27 15:40:53 000461 (01/05/00) - Connection #5 tested: OK
      2009.11.27 15:40:53 000462 (01/05/00) - Connection #5 tested: OK
      2009.11.27 15:40:53 A new session has come online: test@worktrek.com/b3632889
      2009.11.27 15:40:53 000462 (01/05/00) - Connection #2 tested: OK
      2009.11.27 15:40:53 000463 (01/05/00) - Connection #2 tested: OK
      2009.11.27 15:40:53 Created icq session for test@worktrek.com/b3632889 as '576760097'
      2009.11.27 15:40:53 OSCAR login service state change from NOT_CONNECTED to INITING
      2009.11.27 15:40:53 OSCAR login service state change from INITING to RESOLVING
      2009.11.27 15:40:53 OSCAR login service state change from RESOLVING to CONNECTING
      2009.11.27 15:40:53 Received presence packet: <presence type="probe" from="test@worktrek.com/b3632889" to="icq.worktrek.com"/>
      2009.11.27 15:40:53 000463 (01/05/00) - Connection #1 tested: OK
      2009.11.27 15:40:53 000464 (01/05/00) - Connection #1 tested: OK
      2009.11.27 15:40:53 000464 (01/05/00) - Connection #3 tested: OK
      2009.11.27 15:40:53 000465 (01/05/00) - Connection #3 tested: OK
      2009.11.27 15:40:53 icq: Sending packet: <presence to="test@worktrek.com/b3632889" from="icq.worktrek.com" type="unavailable"><status></status></presence>
      2009.11.27 15:40:53 000465 (01/05/00) - Connection #4 tested: OK
      2009.11.27 15:40:53 000466 (01/05/00) - Connection #4 tested: OK
      2009.11.27 15:40:53 000466 (01/05/00) - Connection #5 tested: OK
      2009.11.27 15:40:53 000467 (01/05/00) - Connection #5 tested: OK
      2009.11.27 15:40:53 OSCAR login service state change from CONNECTING to CONNECTED
      2009.11.27 15:40:53 Sending SNAC command: KeyRequest for screenname 576760097
      2009.11.27 15:40:53 Setting up SNAC request and listener: KeyRequest for screenname 576760097,null
      2009.11.27 15:40:53 Handling AIM-style auth.
      2009.11.27 15:40:53 Sending SNAC command: AuthRequest: sn='576760097', version='ClientVersionInfo: , versionString='Apple iChat', clientid=12570, major=1, minor=0, point=0, build=388, distCode=198', locale=en_US
      2009.11.27 15:40:53 Setting up SNAC request and listener: AuthRequest: sn='576760097', version='ClientVersionInfo: , versionString='Apple iChat', clientid=12570, major=1, minor=0, point=0, build=388, distCode=198', locale=en_US,null
      2009.11.27 15:40:53 Got auth response!
      2009.11.27 15:40:53 Got something else?
      2009.11.27 15:40:53 000467 (01/05/00) - Connection #2 tested: OK
      2009.11.27 15:40:53 000468 (01/05/00) - Connection #2 tested: OK
      2009.11.27 15:40:53 Updating status [available,] for TransportSession[test@worktrek.com]
      2009.11.27 15:40:53 icq: Sending packet: <presence to="test@worktrek.com" from="icq.worktrek.com"/>
      2009.11.27 15:40:53 OSCAR bos service state change from NOT_CONNECTED to INITING Reason: null
      2009.11.27 15:40:53 OSCAR connection to 64.12.24.62:80
      2009.11.27 15:40:53 OSCAR bos service state change from INITING to RESOLVING Reason: null
      2009.11.27 15:40:53 OSCAR bos service state change from RESOLVING to CONNECTING Reason: null
      2009.11.27 15:40:53 OSCAR login service state change from CONNECTED to NOT_CONNECTED
      2009.11.27 15:40:54 OSCAR bos service state change from CONNECTING to CONNECTED Reason: null
      2009.11.27 15:40:54 OSCAR flap packet received: FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=2, flapCommand=LoginFlapCmd: version=1, cookie=null, flapPacket=FlapPacket (channel=1, seq=34048)
      2009.11.27 15:40:54 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=2, requests: 0, paused=false, snacPacket=SnacPacket type 0x1/0x3: 30 bytes (id=2583359001), snacCommand=ServerReadyCmd: snac families: 1, 2, 3, 4, 6, 8, 9, a, b, c, 13, 15, 22, 24, 25 - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=3, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x3: 30 bytes (id=2583359001), flapPacket=FlapPacket (channel=2, seq=34049)
      2009.11.27 15:40:54 Registrating snac handler ClientFlapConn: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=3
      2009.11.27 15:40:54 Sending SNAC command: ClientVersionsCmd: family versions: 1 (v=4), 2 (v=1), 3 (v=1), 4 (v=1), 6 (v=1), 8 (v=1), 13 (v=4),
      2009.11.27 15:40:54 Sending SNAC command: RateInfoRequest
      2009.11.27 15:40:54 Sending SNAC command: ParamInfoRequest
      2009.11.27 15:40:54 Sending SNAC command: LocRightsRequest
      2009.11.27 15:40:54 Sending SNAC command: SsiRightsRequest
      2009.11.27 15:40:54 Sending SNAC command: SsiDataRequest
      2009.11.27 15:40:54 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=8, requests: 6, paused=false, snacPacket=SnacPacket type 0x1/0x15: 438 bytes (id=2583359002), snacCommand=null - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=9, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x15: 438 bytes (id=2583359002), flapPacket=FlapPacket (channel=2, seq=34050)
      2009.11.27 15:40:54 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=8, requests: 6, paused=false, snacPacket=SnacPacket type 0x1/0x18: 60 bytes (id=2583359213), snacCommand=ServerVersionsCmd: family versions: 1 (v=4), 2 (v=1), 3 (v=1), 4 (v=1), 6 (v=1), 8 (v=1), 9 (v=1), a (v=1), b (v=1), c (v=1), 13 (v=5), 15 (v=2), 22 (v=1), 24 (v=1), 25 (v=1), - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=9, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x18: 60 bytes (id=2583359213), flapPacket=FlapPacket (channel=2, seq=34051)
      2009.11.27 15:40:54 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=8, requests: 6, paused=false, snacPacket=SnacPacket type 0x1/0x13: 14 bytes (id=2583359214), snacCommand=UpdateAdvisory: type=5, message=null - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=9, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x13: 14 bytes (id=2583359214), flapPacket=FlapPacket (channel=2, seq=34052)
      2009.11.27 15:40:54 OSCAR snac packet response: SnacResponseEvent: request=SnacRequest for RateInfoRequest: listeners: [net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5], responses: null - SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=8, requests: 6, paused=false, snacPacket=SnacPacket type 0x1/0x7: 1473 bytes (id=4), snacCommand=RateInfoCmd: RateClassInfo for class 1, currentAvg=5853, windowSize=80, clearAvg=2500, warnAvg=2000, limitedAvg=1500, disconnectAvg=800, max=6000, timeSinceLastCommand=0, currentState=0, families: 308 - RateClassInfo for class 2, currentAvg=6000, windowSize=80, clearAvg=3000, warnAvg=2000, limitedAvg=1500, disconnectAvg=1000, max=6000, timeSinceLastCommand=170, currentState=0, families: 6 - RateClassInfo for class 3, currentAvg=3500, windowSize=20, clearAvg=3100, warnAvg=2500, limitedAvg=2000, disconnectAvg=1500, max=4500, timeSinceLastCommand=170, currentState=0, families: 3 - RateClassInfo for class 4, currentAvg=6000, windowSize=20, clearAvg=5500, warnAvg=5300, limitedAvg=4200, disconnectAvg=3000, max=8000, timeSinceLastCommand=170, currentState=0, families: 2 - RateClassInfo for class 5, currentAvg=6000, windowSize=10, clearAvg=5500, warnAvg=5300, limitedAvg=4200, disconnectAvg=3000, max=8000, timeSinceLastCommand=170, currentState=0, families: 0 - - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=9, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x7: 1473 bytes (id=4), flapPacket=FlapPacket (channel=2, seq=34053)
      2009.11.27 15:40:54 Sending SNAC command: RateAck for classes: 1, 2, 3, 4, 5,
      2009.11.27 15:40:54 OSCAR snac packet response: SnacResponseEvent: request=SnacRequest for ParamInfoRequest: listeners: [net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5], responses: null - SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=9, requests: 7, paused=false, snacPacket=SnacPacket type 0x4/0x5: 16 bytes (id=5), snacCommand=ParamInfoCmd: paramInfo=<ParamInfo: maxChannel=4, flags=0x3 (FLAG_MISSEDCALLS_ALLOWED | FLAG_CHANMSGS_ALLOWED), maxMsgLen=512, maxSenderWarning=90.0%, maxReceiverWarning=100.9%, minMsgInterval=1000> - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=10, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x4/0x5: 16 bytes (id=5), flapPacket=FlapPacket (channel=2, seq=34054)
      2009.11.27 15:40:54 Sending SNAC command: SetParamInfoCmd: paramInfo=<ParamInfo: maxChannel=0, flags=0xb (FLAG_TYPING_NOTIFICATION | FLAG_MISSEDCALLS_ALLOWED | FLAG_CHANMSGS_ALLOWED), maxMsgLen=8000, maxSenderWarning=90.0%, maxReceiverWarning=100.9%, minMsgInterval=0>
      2009.11.27 15:40:54 OSCAR snac packet response: SnacResponseEvent: request=SnacRequest for LocRightsRequest: listeners: [net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5], responses: null - SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=10, requests: 8, paused=false, snacPacket=SnacPacket type 0x2/0x3: 30 bytes (id=6), snacCommand=LocRightsCmd: max info length=4096 - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=11, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x2/0x3: 30 bytes (id=6), flapPacket=FlapPacket (channel=2, seq=34055)
      2009.11.27 15:40:54 Sending SNAC command: SetInfoCmd: info=InfoData: info: oscargateway capabilities: 1
      2009.11.27 15:40:54 Sending SNAC command: MyInfoRequest
      2009.11.27 15:40:54 OSCAR snac packet response: SnacResponseEvent: request=SnacRequest for SsiRightsRequest: listeners: [net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5], responses: null - SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=12, requests: 10, paused=false, snacPacket=SnacPacket type 0x13/0x3: 164 bytes (id=7), snacCommand=SsiRightsCmd: maxima: 0x0: 3000, 0x1: 100, 0x2: 1000, 0x3: 1000, 0x4: 1, 0x5: 1, 0x6: 50, 0x7: 0, 0x8: 0, 0x9: 3, 0xa: 0, 0xb: 0, 0xc: 0, 0xd: 128, 0xe: 1000, 0xf: 20, 0x10: 200, 0x11: 1, 0x12: 0, 0x13: 1, 0x14: 15, 0x15: 1, 0x16: 40, 0x17: 0, 0x18: 0, 0x19: 200, 0x1a: 1, 0x1b: 20, 0x1c: 200, 0x1d: 1, 0x1e: 8, 0x1f: 20, 0x20: 1, 0x21: 0, 0x22: 0, 0x23: 0, 0x24: 50, 0x25: 0, 0x26: 5, 0x27: 500, 0x28: 1, 0x29: 8, - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=12, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x13/0x3: 164 bytes (id=7), flapPacket=FlapPacket (channel=2, seq=34056)
      2009.11.27 15:40:54 OSCAR snac packet response: SnacResponseEvent: request=SnacRequest for SsiDataRequest: listeners: [net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5], responses: null - SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=12, requests: 10, paused=false, snacPacket=SnacPacket type 0x13/0x6: 249 bytes (id=8), snacCommand=SsiDataCmd (ssi version=0): 6 items, modified Fri Nov 27 15:39:31 CET 2009 - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=13, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x13/0x6: 249 bytes (id=8), flapPacket=FlapPacket (channel=2, seq=34057)
      2009.11.27 15:40:54 ERRTYPE_SNAC_RESPONSE_LISTENER FLAP ERROR: null net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5
      java.lang.NullPointerException
      at net.kano.joscar.ssiitem.RootItem.toString(RootItem.java:203)
      at java.lang.String.valueOf(String.java:2827)
      at java.lang.StringBuilder.append(StringBuilder.java:115)
      at net.sf.kraken.protocols.oscar.BOSConnection.handleSnacResponse(BOSConnection.java:228)
      at net.sf.kraken.protocols.oscar.AbstractFlapConnection$5.handleResponse(AbstractFlapConnection.java:138)
      at net.kano.joscar.snac.SnacRequest.gotResponse(SnacRequest.java:344)
      at net.kano.joscar.snac.ClientSnacProcessor.continueHandling(ClientSnacProcessor.java:727)
      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:75)
      at net.kano.joscar.flap.AsynchronousFlapProcessor$BackgroundPacketProcessor.run(AsynchronousFlapProcessor.java:63)
      at java.lang.Thread.run(Thread.java:619)
      2009.11.27 15:40:54 OSCAR snac packet response: SnacResponseEvent: request=SnacRequest for MyInfoRequest: listeners: [net.sf.kraken.protocols.oscar.AbstractFlapConnection$5@1887dd5, net.kano.joscar.ratelim.RateQueue$1@19c123d], responses: null - SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=12, requests: 10, paused=false, snacPacket=SnacPacket type 0x1/0xf: 270 bytes (id=12), snacCommand=YourInfoCmd: UserInfo for 576760097: flags=0x51 (MASK_FREE | MASK_UNCONFIRMED | 0x40), memberSince=Fri Nov 20 16:37:31 CET 2009, sessLenAim=0min, onSince=Fri Nov 27 15:39:47 CET 2009, extraTlvs=[TLV: type=0xc, length=37, ascii value="": 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00, TLV: type=0xa, length=4, uint value=1578615084: 5e 17 c1 2c, TLV: type=0x15, length=4, ascii value="", uint value=2048: 00 00 08 00, TLV: type=0x22, length=2, ushort value=46056: b3 e8, TLV: type=0x1e, length=4, ascii value="", uint value=0: 00 00 00 00, TLV: type=0x28, length=1, ascii value="<": 3c, TLV: type=0x29, length=4, uint value=1259233714: 4b 0e 61 b2, TLV: type=0x2d, length=4, ascii value="", uint value=0: 00 00 00 00, TLV: type=0x2c, length=4, ascii value="", uint value=0: 00 00 00 00] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=13, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0xf: 270 bytes (id=12), flapPacket=FlapPacket (channel=2, seq=34058)
      2009.11.27 15:40:54 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=12, requests: 10, paused=false, snacPacket=SnacPacket type 0x1/0xf: 115 bytes (id=2583360005), snacCommand=YourInfoCmd: UserInfo for 576760097: flags=0x51 (MASK_FREE | MASK_UNCONFIRMED | 0x40), memberSince=Fri Nov 20 16:37:31 CET 2009, sessLenAim=0min, onSince=Fri Nov 27 15:39:47 CET 2009, extraTlvs=[TLV: type=0x15, length=4, ascii value="", uint value=2048: 00 00 08 00, TLV: type=0xa, length=4, uint value=1578615084: 5e 17 c1 2c, TLV: type=0x22, length=2, ushort value=46056: b3 e8, TLV: type=0x1e, length=4, ascii value="", uint value=0: 00 00 00 00, TLV: type=0x28, length=1, ascii value="<": 3c, TLV: type=0x29, length=4, uint value=1259233714: 4b 0e 61 b2, TLV: type=0x2d, length=4, ascii value="", uint value=0: 00 00 00 00, TLV: type=0x2c, length=4, ascii value="", uint value=0: 00 00 00 00, TLV: type=0x26, length=4, uint value=1259233714: 4b 0e 61 b2], longcaps: [] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=13, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0xf: 115 bytes (id=2583360005), flapPacket=FlapPacket (channel=2, seq=34059)
      2009.11.27 15:41:16 Received message packet: <message from="test@worktrek.com/b3632889" to="588846164@icq.worktrek.com" type="chat"><body>test</body></message>
      2009.11.27 15:41:16 Sending SNAC command: SendImIcbm to 588846164 (id=0, ackreq=true): IM: test
      2009.11.27 15:41:16 Setting up SNAC request and listener: SendImIcbm to 588846164 (id=0, ackreq=true): IM: test,null
      2009.11.27 15:41:16 Handling request SnacRequest for SendImIcbm to 588846164 (id=0, ackreq=true): IM: test: listeners: null, responses: null
      2009.11.27 15:42:24 OSCAR bos service state change from CONNECTED to NOT_CONNECTED Reason: java.net.SocketException: Connection reset

        Attachments

          Activity

            People

            • Assignee:
              jadestorm Daniel Henninger
              Reporter:
              jadestorm Daniel Henninger
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: