(0 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent1_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent1_debug.txt, sipunit.test.port=5071} ] (9 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (9 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (10 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (11 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (47 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (318 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5071 transport = udp] (319 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@f89785 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@a3bc8c] (320 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@a3bc8c] (334 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@9a99eb] (339 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent2_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent2, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent2_debug.txt, sipunit.test.port=5072} ] (340 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (340 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (341 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (341 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (341 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (342 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (343 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5072 transport = udp] (343 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@6f3619 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@48cd13] (348 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@48cd13] (350 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@8fc9ba] (352 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent3_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent3, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent3_debug.txt, sipunit.test.port=5073} ] (353 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (353 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (354 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (354 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (355 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (357 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (358 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5073 transport = udp] (358 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@4eabb listeningPoint = gov.nist.javax.sip.ListeningPointImpl@ce9f9d] (359 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@ce9f9d] (359 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@510dc2] (561 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 creating a new one ] (569 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:209) [NextHop based on Route:127.0.0.1:5060/udp] (569 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145:1656129052) : returning null] (572 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (595 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (602 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipSession.java:1116][SipSession.java:999][TestBase.java:977][AuthOfAppInitReqTest.java:88][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (603 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKeb41e720be85cd246a17275333d09a31] (605 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bkeb41e720be85cd246a17275333d09a31] (606 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKeb41e720be85cd246a17275333d09a31] (613 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (621 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendRequest(SIPClientTransaction.java:918) [sendRequest() MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uac Servlet-Name: AuthOfAppInitReq private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (634 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uac Servlet-Name: AuthOfAppInitReq private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (634 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (635 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKeb41e720be85cd246a17275333d09a31] (635 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32 branchID = z9hG4bKeb41e720be85cd246a17275333d09a31 isClient = true] (635 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:470][SIPClientTransaction.java:977][SipSession.java:1197][SipSession.java:1116][SipSession.java:999][TestBase.java:977][AuthOfAppInitReqTest.java:88][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (637 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32 tickCount 64 currentTickCount = -1] (638 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPClientTransaction.java:977][SipSession.java:1197][SipSession.java:1116][SipSession.java:999][TestBase.java:977][AuthOfAppInitReqTest.java:88][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (645 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.0.1/5060 MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uac Servlet-Name: AuthOfAppInitReq private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (645 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (651 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (651 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (652 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="127.0.0.1:5060" time="1223304273926" isSender="true" transactionId="z9hg4bkeb41e720be85cd246a17275333d09a31" callId="fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145" firstLine="MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uac Servlet-Name: AuthOfAppInitReq private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (652 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (655 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (656 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (656 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 313] (657 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (657 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 310] (657 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: sip:bob@192.168.0.145 Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 Max-Forwards: 70 ] (657 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: JSR289_TCK <sip:JSR289_TCK@127.0.0.1:5060>;tag=dxmgs4 Content-Length: 0 CSeq: 1 MESSAGE Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 From: Alice <sip:alice@192.168.0.145:5071>;tag=1656129052 ] (660 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (661 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (664 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304273946" isSender="false" transactionId="z9hg4bkeqzwi2" callId="dkkezg" firstLine="REGISTER sip:bob@192.168.0.145:5072 SIP/2.0" > <![CDATA[REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (664 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (664 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (664 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32] (665 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (667 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (667 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkeqzwi2] (667 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (670 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (670 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223304273956" isSender="false" transactionId="z9hg4bkeb41e720be85cd246a17275333d09a31" callId="fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=dxmgs4 CSeq: 1 MESSAGE Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (671 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (673 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (673 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bkeb41e720be85cd246a17275333d09a31] (674 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=dxmgs4 CSeq: 1 MESSAGE Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 Content-Length: 0 ] (677 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32 to gov.nist.javax.sip.DialogFilter@b0edb2] (677 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (673 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (678 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (678 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (681 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKeqzwi2] (681 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( REGISTER:z9hG4bKeqzwi2):gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (681 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 gov.nist.javax.sip.DialogFilter@376afa messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (681 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (682 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (680 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=dxmgs4 CSeq: 1 MESSAGE Call-ID: fcd9e807ff1f23d2acae5a0647c37783@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKeb41e720be85cd246a17275333d09a31 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1656129052 Content-Length: 0 ] (685 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (685 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32] (686 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@a7dd7b]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32this.sipListener = org.cafesip.sipunit.SipStack@9a99ebsipEvent.source = gov.nist.javax.sip.SipProviderImpl@a7dd7b] (686 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (686 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:638][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (687 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@456a0c] (687 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32 branchID = z9hG4bKeb41e720be85cd246a17275333d09a31 isClient = true] (687 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:644][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (688 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32 tickCount 10 currentTickCount = 64] (688 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32] (688 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (685 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (690 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (690 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (691 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKeqzwi2] (690 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@456a0cnevents 1] (693 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@a7dd7b]source = gov.nist.javax.sip.SipProviderImpl@a7dd7b] (693 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (693 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (693 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@713f1e32] (693 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][EventScanner.java:362][EventScanner.java:492][Thread.java:613]] (691 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1 branchID = z9hG4bKeqzwi2 isClient = false] (694 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (694 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (694 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1 listening point = 192.168.0.145:5072] (695 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (695 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(dkkezg:uu0nwg) : returning null] (695 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = dkkezg:uu0nwg] (697 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (698 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [REGISTER transaction.isMapped = false] (698 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@6e056e]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1this.sipListener = org.cafesip.sipunit.SipStack@8fc9basipEvent.source = gov.nist.javax.sip.SipProviderImpl@6e056e] (698 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] SIPUNIT TRACE: 1223304273987 SS.waitRequest() - about to block, waiting (699 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (699 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@fb7cbb] (699 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (699 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@fb7cbbnevents 1] (700 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@6e056e]source = gov.nist.javax.sip.SipProviderImpl@6e056e] (701 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1 sipEvent.serverTx = null] (702 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkeqzwi2 existing={}] (703 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkeqzwi2] (703 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (703 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (703 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] SIPUNIT TRACE: 1223304273993 SipStack: request received ! SIPUNIT TRACE: 1223304273993 SipStack: calling listener SIPUNIT TRACE: 1223304273993 SipSession: request received ! SIPUNIT TRACE: 1223304273993 me ('To' check) = sip:bob@192.168.0.145 SIPUNIT TRACE: 1223304273993 my local contact info ('Request URI' check) = sip:bob@192.168.0.145:5072;lr;transport=udp SIPUNIT TRACE: 1223304273993 REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304273993 SipSession: notifying block object (704 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (706 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (706 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (707 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][EventScanner.java:254][EventScanner.java:492][Thread.java:613]] (707 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkeqzwi2] SIPUNIT TRACE: 1223304273996 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304273996 SS.waitRequest() - either we got the request, or timed out (708 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : REGISTER returning false] (708 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkeqzwi2 existing={}] (708 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1] (709 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkeqzwi2] (709 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkeqzwi2] (709 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(dkkezg:uu0nwg) : returning null] SIPUNIT TRACE: 1223304274002 Response before sending out through stack.......... SIPUNIT TRACE: 1223304274002 SIP/2.0 401 UNAUTHORIZED To: <sip:bob@192.168.0.145>;tag=1329836972 CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 WWW-Authenticate: Digest realm ="bea.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" UserName: tckUser Password: beaSystem Content-Length: 0 (713 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1 branchID = z9hG4bKeqzwi2 isClient = false] (714 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSession.java:1509][AuthOfAppInitReqTest.java:120][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (714 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1 tickCount 64 currentTickCount = -1] (714 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1 getState = Completed Transaction] (715 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (716 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPServerTransaction.java:464][SIPServerTransaction.java:1099][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSession.java:1509][AuthOfAppInitReqTest.java:120][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (725 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 401 UNAUTHORIZED To: <sip:bob@192.168.0.145>;tag=1329836972 CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 WWW-Authenticate: Digest realm ="bea.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" UserName: tckUser Password: beaSystem Content-Length: 0 ] (726 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (732 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 401 UNAUTHORIZED To: <sip:bob@192.168.0.145>;tag=1329836972 CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 WWW-Authenticate: Digest realm ="bea.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" UserName: tckUser Password: beaSystem Content-Length: 0 ] (732 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (733 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (733 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5072" to="192.168.0.145:5060" time="1223304274005" isSender="true" transactionId="z9hg4bkeqzwi2" callId="dkkezg" firstLine="SIP/2.0 401 UNAUTHORIZED" > <![CDATA[SIP/2.0 401 UNAUTHORIZED To: <sip:bob@192.168.0.145>;tag=1329836972 CSeq: 1 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKeqzwi2 From: <sip:bob@192.168.0.145>;tag=uu0nwg Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 WWW-Authenticate: Digest realm ="bea.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" UserName: tckUser Password: beaSystem Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (734 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (734 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (736 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkeqzwi2] SIPUNIT TRACE: 1223304274025 SS.waitRequest() - about to block, waiting (744 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (744 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 642] (744 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: sip:bob@192.168.0.145 Authorization: Digest username="tckUser", realm="bea.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", uri="sip:bob@192.168.0.145:5072", response="4ed3cbf32ba4cfce6f846c7c7394c156", algorithm="MD5", qop="auth", nc=00000001, cnonce="b7191cb38fa9d03827e5594b67e30c54" Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKj8tcb4;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 ] (748 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (749 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (749 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304274033" isSender="false" transactionId="z9hg4bkj8tcb4" callId="dkkezg" firstLine="REGISTER sip:bob@192.168.0.145:5072 SIP/2.0" > <![CDATA[REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145> Authorization: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (749 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (750 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (751 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkj8tcb4] (752 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (752 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (752 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKj8tcb4] (752 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( REGISTER:z9hG4bKj8tcb4):gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (753 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 gov.nist.javax.sip.DialogFilter@6d4d81 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (755 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (755 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (755 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (755 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (756 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (756 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (756 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKj8tcb4] (756 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e branchID = z9hG4bKj8tcb4 isClient = false] (757 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (757 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (761 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145> Authorization: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e listening point = 192.168.0.145:5072] (762 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (762 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(dkkezg:19cf2i) : returning null] (762 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = dkkezg:19cf2i] (762 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (767 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [REGISTER transaction.isMapped = false] (767 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@6e056e]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0ethis.sipListener = org.cafesip.sipunit.SipStack@8fc9basipEvent.source = gov.nist.javax.sip.SipProviderImpl@6e056e] (768 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (768 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (768 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@fb53f6] (768 ms) [Thread-11] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (769 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@fb53f6nevents 1] (769 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@6e056e]source = gov.nist.javax.sip.SipProviderImpl@6e056e] (769 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e sipEvent.serverTx = null] (769 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkj8tcb4 existing={z9hg4bkeqzwi2=gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1}] (769 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkj8tcb4] (771 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (771 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (772 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] SIPUNIT TRACE: 1223304274061 SipStack: request received ! SIPUNIT TRACE: 1223304274061 SipStack: calling listener SIPUNIT TRACE: 1223304274061 SipSession: request received ! SIPUNIT TRACE: 1223304274061 me ('To' check) = sip:bob@192.168.0.145 SIPUNIT TRACE: 1223304274061 my local contact info ('Request URI' check) = sip:bob@192.168.0.145:5072;lr;transport=udp SIPUNIT TRACE: 1223304274062 REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145> Authorization: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304274062 SipSession: notifying block object (773 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (773 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (773 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (773 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][EventScanner.java:254][EventScanner.java:492][Thread.java:613]] SIPUNIT TRACE: 1223304274063 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304274063 SS.waitRequest() - either we got the request, or timed out (774 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkj8tcb4] #1: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" #2: Digest username="tckUser",realm="bea.com",cnonce="b7191cb38fa9d03827e5594b67e30c54",nc=00000001,qop="auth",uri="sip:bob@192.168.0.145:5072",nonce="dbffb13c8a4d30117c25c753d1fa7710",response="4ed3cbf32ba4cfce6f846c7c7394c156",algorithm="MD5" #3: true (775 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : REGISTER returning false] (776 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkj8tcb4 existing={z9hg4bkeqzwi2=gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1}] (776 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e] (776 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkj8tcb4] (780 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkj8tcb4] (781 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(dkkezg:19cf2i) : returning null] SIPUNIT TRACE: 1223304274070 Response before sending out through stack.......... SIPUNIT TRACE: 1223304274070 SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=322219841 CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 UserName: tckUser Password: beaSystem Content-Length: 0 (782 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e branchID = z9hG4bKj8tcb4 isClient = false] (782 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSession.java:1509][AuthOfAppInitReqTest.java:137][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (782 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e tickCount 64 currentTickCount = -1] (783 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e getState = Completed Transaction] (783 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (784 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPServerTransaction.java:464][SIPServerTransaction.java:1099][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSession.java:1509][AuthOfAppInitReqTest.java:137][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (786 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=322219841 CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 UserName: tckUser Password: beaSystem Content-Length: 0 ] (787 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (787 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=322219841 CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 UserName: tckUser Password: beaSystem Content-Length: 0 ] (790 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (791 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (792 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 658] (792 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145>;tag=322219841 Authorization: Digest username="tckUser", realm="bea.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", uri="sip:bob@192.168.0.145:5072", response="4ed3cbf32ba4cfce6f846c7c7394c156", algorithm="MD5", qop="auth", nc=00000001, cnonce="b7191cb38fa9d03827e5594b67e30c54" Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKps7zjv;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 ] (792 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (794 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5072" to="192.168.0.145:5060" time="1223304274075" isSender="true" transactionId="z9hg4bkj8tcb4" callId="dkkezg" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=322219841 CSeq: 2 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKj8tcb4 From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 private-uri: sip:bob@192.168.0.145:5072 UserName: tckUser Password: beaSystem Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (794 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (797 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (797 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkj8tcb4] SIPUNIT TRACE: 1223304274086 SS.waitRequest() - about to block, waiting (797 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (800 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (800 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304274082" isSender="false" transactionId="z9hg4bkps7zjv" callId="dkkezg" firstLine="REGISTER sip:bob@192.168.0.145:5072 SIP/2.0" > <![CDATA[REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145>;tag=322219841 Authorization: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (800 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (802 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (803 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkps7zjv] (804 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (804 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (804 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKps7zjv] (804 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( REGISTER:z9hG4bKps7zjv):gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (805 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 gov.nist.javax.sip.DialogFilter@ab7626 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (805 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (805 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (805 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (807 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (807 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (807 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (807 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKps7zjv] (808 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771 branchID = z9hG4bKps7zjv isClient = false] (808 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (811 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (811 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145>;tag=322219841 Authorization: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771 listening point = 192.168.0.145:5072] (811 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (812 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(dkkezg:322219841:19cf2i) : returning null] (813 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = dkkezg:322219841:19cf2i] (813 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (813 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [REGISTER transaction.isMapped = false] (813 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@6e056e]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771this.sipListener = org.cafesip.sipunit.SipStack@8fc9basipEvent.source = gov.nist.javax.sip.SipProviderImpl@6e056e] (813 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (814 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (814 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@d9c3e7] (814 ms) [Thread-12] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (814 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@d9c3e7nevents 1] (815 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@6e056e]source = gov.nist.javax.sip.SipProviderImpl@6e056e] (816 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771 sipEvent.serverTx = null] (816 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkps7zjv existing={z9hg4bkj8tcb4=gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e, z9hg4bkeqzwi2=gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1}] (816 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkps7zjv] (816 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (816 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (817 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] SIPUNIT TRACE: 1223304274106 SipStack: request received ! SIPUNIT TRACE: 1223304274106 SipStack: calling listener SIPUNIT TRACE: 1223304274106 SipSession: request received ! SIPUNIT TRACE: 1223304274106 me ('To' check) = sip:bob@192.168.0.145 SIPUNIT TRACE: 1223304274106 my local contact info ('Request URI' check) = sip:bob@192.168.0.145:5072;lr;transport=udp SIPUNIT TRACE: 1223304274106 REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:bob@192.168.0.145>;tag=322219841 Authorization: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304274106 SipSession: notifying block object (817 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (817 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message REGISTER sip:bob@192.168.0.145:5072 SIP/2.0 ] (818 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (818 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][EventScanner.java:254][EventScanner.java:492][Thread.java:613]] (821 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkps7zjv] SIPUNIT TRACE: 1223304274110 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304274110 SS.waitRequest() - either we got the request, or timed out #1: Digest cnonce="b7191cb38fa9d03827e5594b67e30c54",qop="auth",uri="sip:bob@192.168.0.145:5072",realm="bea.com",username="tckUser",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="4ed3cbf32ba4cfce6f846c7c7394c156" #2: Digest username="tckUser",realm="bea.com",cnonce="b7191cb38fa9d03827e5594b67e30c54",nc=00000001,qop="auth",uri="sip:bob@192.168.0.145:5072",nonce="dbffb13c8a4d30117c25c753d1fa7710",response="4ed3cbf32ba4cfce6f846c7c7394c156",algorithm="MD5" #3: true (824 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : REGISTER returning false] (824 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkps7zjv existing={z9hg4bkj8tcb4=gov.nist.javax.sip.stack.SIPServerTransaction@ddf59c0e, z9hg4bkeqzwi2=gov.nist.javax.sip.stack.SIPServerTransaction@d893a2d1}] (824 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771] (825 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkps7zjv] (828 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkps7zjv] (829 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(dkkezg:322219841:19cf2i) : returning null] SIPUNIT TRACE: 1223304274118 Response before sending out through stack.......... SIPUNIT TRACE: 1223304274118 SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=93443157 CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 Content-Length: 0 (829 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771 branchID = z9hG4bKps7zjv isClient = false] (830 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSession.java:1509][AuthOfAppInitReqTest.java:153][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (831 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771 tickCount 64 currentTickCount = -1] (831 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@eb56b771 getState = Completed Transaction] (832 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (832 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPServerTransaction.java:464][SIPServerTransaction.java:1099][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSession.java:1509][AuthOfAppInitReqTest.java:153][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (833 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=93443157 CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 Content-Length: 0 ] (836 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (836 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=93443157 CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 Content-Length: 0 ] (837 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (849 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (849 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5072" to="192.168.0.145:5060" time="1223304274122" isSender="true" transactionId="z9hg4bkps7zjv" callId="dkkezg" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:bob@192.168.0.145>;tag=93443157 CSeq: 3 REGISTER Call-ID: dkkezg Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uac;branch=z9hG4bKps7zjv From: <sip:bob@192.168.0.145>;tag=19cf2i Expires: 3600 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (857 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (953 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (954 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkps7zjv] (968 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (969 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (969 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (1970 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (1970 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (1971 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (2972 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (2972 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (2972 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]