(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} ] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (14 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (15 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (17 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (52 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (221 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] (221 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@9dcbb listeningPoint = gov.nist.javax.sip.ListeningPointImpl@7aa187] (222 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@7aa187] (228 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@3508c0] (231 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} ] (231 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (231 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (232 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (232 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (233 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (233 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (234 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] (235 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@8f729c listeningPoint = gov.nist.javax.sip.ListeningPointImpl@ad97f5] (235 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@ad97f5] (236 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@d38976] (237 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} ] (238 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (238 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (239 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (239 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (240 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (241 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (241 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] (242 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@e5c339 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@7414c8] (242 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@7414c8] (243 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@7a17] (385 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 ] (386 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] (387 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(88e84eed87ccb61ff35a835181bc32c8@192.168.0.145:48188553) : returning null] (389 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (395 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (397 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][TestBase.java:941][AuthInfoTest.java:76][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]] (398 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKbd9f1a4e76daf15f19893a9931576c7e] (399 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bkbd9f1a4e76daf15f19893a9931576c7e] (400 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKbd9f1a4e76daf15f19893a9931576c7e] (401 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (403 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: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e 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.apitestapp Servlet-Name: AuthInfo Method-Name: testAddAuthInfo001 Content-Length: 0 ] (405 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: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e 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.apitestapp Servlet-Name: AuthInfo Method-Name: testAddAuthInfo001 Content-Length: 0 ] (406 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (407 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKbd9f1a4e76daf15f19893a9931576c7e] (407 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@32ffab59 branchID = z9hG4bKbd9f1a4e76daf15f19893a9931576c7e isClient = true] (407 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][TestBase.java:941][AuthInfoTest.java:76][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]] (408 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59 tickCount 64 currentTickCount = -1] (409 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][TestBase.java:941][AuthInfoTest.java:76][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]] (410 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: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e 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.apitestapp Servlet-Name: AuthInfo Method-Name: testAddAuthInfo001 Content-Length: 0 ] (411 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (413 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (414 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (414 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="1223301933936" isSender="true" transactionId="z9hg4bkbd9f1a4e76daf15f19893a9931576c7e" callId="88e84eed87ccb61ff35a835181bc32c8@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: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e 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.apitestapp Servlet-Name: AuthInfo Method-Name: testAddAuthInfo001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (415 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (416 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (416 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (418 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 311] (418 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=25rd6l Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e From: Alice <sip:alice@192.168.0.145:5071>;tag=48188553 ] (421 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59] (422 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]] (422 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (423 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (423 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 308] (423 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: sip:alice@192.168.0.145:5071 Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 ] (427 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (427 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (427 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="1223301933950" isSender="false" transactionId="z9hg4bkbd9f1a4e76daf15f19893a9931576c7e" callId="88e84eed87ccb61ff35a835181bc32c8@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=25rd6l CSeq: 1 MESSAGE Call-ID: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (427 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (428 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (428 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (428 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bkbd9f1a4e76daf15f19893a9931576c7e] (428 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (428 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223301933951" isSender="false" transactionId="z9hg4bkvttmb5" callId="3038ui" firstLine="INVITE sip:alice@192.168.0.145:5071 SIP/2.0" > <![CDATA[INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (428 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=25rd6l CSeq: 1 MESSAGE Call-ID: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 Content-Length: 0 ] (429 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (429 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (431 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkvttmb5] (434 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@32ffab59 to gov.nist.javax.sip.DialogFilter@618565] (434 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] (434 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (434 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=25rd6l CSeq: 1 MESSAGE Call-ID: 88e84eed87ccb61ff35a835181bc32c8@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKbd9f1a4e76daf15f19893a9931576c7e From: "Alice" <sip:alice@192.168.0.145:5071>;tag=48188553 Content-Length: 0 ] (435 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59] (435 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@794494]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59this.sipListener = org.cafesip.sipunit.SipStack@3508c0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@794494] (435 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (435 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (436 ms) [Thread-10] DEBUG: testAgent#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]] (436 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]] (441 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKvttmb5] (442 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( INVITE:z9hG4bKvttmb5):gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (442 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@7a3e72] (442 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for INVITE sip:alice@192.168.0.145:5071 SIP/2.0 gov.nist.javax.sip.DialogFilter@99ae9c messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (443 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@32ffab59 branchID = z9hG4bKbd9f1a4e76daf15f19893a9931576c7e isClient = true] (443 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (443 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@7a3e72nevents 1] (443 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]] (444 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (444 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]source = gov.nist.javax.sip.SipProviderImpl@794494] (444 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59 tickCount 10 currentTickCount = 64] (445 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (445 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (445 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59] (445 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process INVITE sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (446 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (446 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]] SIPUNIT TRACE: 1223301933976 SS.waitRequest() - about to block, waiting (448 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (448 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@32ffab59] (449 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (449 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]] (449 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKvttmb5] (449 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 branchID = z9hG4bKvttmb5 isClient = false] (450 ms) [Thread-10] DEBUG: testAgent#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]] (450 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (450 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 listening point = 192.168.0.145:5071] (451 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Proceeding Transaction] (451 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3038ui:id6u41) : returning null] (451 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 3038ui:id6u41] (451 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (452 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [INVITE transaction.isMapped = false] (454 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49this.sipListener = org.cafesip.sipunit.SipStack@3508c0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@794494] (454 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (454 ms) [Thread-10] DEBUG: testAgent#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]] (455 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@c8f3cd] (455 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing INVITE sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (455 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@c8f3cdnevents 1] (455 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]source = gov.nist.javax.sip.SipProviderImpl@794494] (456 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : INVITE sip:alice@192.168.0.145:5071 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 sipEvent.serverTx = null] (456 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkvttmb5 existing={}] (457 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkvttmb5] (457 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (457 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (457 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] SIPUNIT TRACE: 1223301933986 SipStack: request received ! SIPUNIT TRACE: 1223301933986 SipStack: calling listener SIPUNIT TRACE: 1223301933986 SipSession: request received ! SIPUNIT TRACE: 1223301933986 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223301933986 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223301933986 INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223301933986 SipSession: notifying block object SIPUNIT TRACE: 1223301933986 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223301933986 SS.waitRequest() - either we got the request, or timed out (458 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (458 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (460 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] SIPUNIT TRACE: 1223301933988 INVITE after received by stack.......... (460 ms) [EventScannerThread] DEBUG: testAgent#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: 1223301933988 INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 (460 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkvttmb5] (460 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (460 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkvttmb5 existing={}] (461 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (461 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$SendTrying.<init>(SIPServerTransaction.java:299) [scheduled timer for gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (462 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkvttmb5] (462 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkvttmb5] (462 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3038ui:id6u41) : returning null] (471 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (472 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@f9e6e5/1] (472 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@f9e6e5null/id6u41] (472 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkvttmb5/true] (473 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:497][AuthInfoTest.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]] (473 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@f9e6e5] (474 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (475 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:497][AuthInfoTest.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]] (475 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 dialog = gov.nist.javax.sip.stack.SIPDialog@f9e6e5] (475 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (476 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@f9e6e5state = null] SIPUNIT TRACE: 1223301934004 Response before sending out through stack.......... SIPUNIT TRACE: 1223301934005 SIP/2.0 401 Unauthorized To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 1 WWW-Authenticate: Digest realm ="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" Content-Length: 0 (477 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@f9e6e5 lastResponse = SIP/2.0 401 Unauthorized ] (478 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][AuthInfoTest.java:99][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]] (479 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (480 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (480 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (480 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 401] (481 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (481 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (481 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalTag(SIPDialog.java:1317) [set Local tag 943172877 null] (482 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1319][SIPDialog.java:2280][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][AuthInfoTest.java:99][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]] (484 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@f9e6e5newState = 3] (484 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2295][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][AuthInfoTest.java:99][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]] (484 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@f9e6e5 old dialog state is null] (485 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@f9e6e5 New dialog state is Terminated Dialog] (485 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49this.sipListener = org.cafesip.sipunit.SipStack@3508c0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@794494] (486 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPServerTransaction.java:1415][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][AuthInfoTest.java:99][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]] (486 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@696cdb] (487 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@696cdbnevents 1] (490 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 branchID = z9hG4bKvttmb5 isClient = false] (491 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]source = gov.nist.javax.sip.SipProviderImpl@794494] (491 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:999][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][AuthInfoTest.java:99][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]] (492 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 tickCount 64 currentTickCount = -1] (493 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 getState = Completed Transaction] (493 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (494 ms) [main] DEBUG: testAgent#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:1864][SipCall.java:1095][SipCall.java:1253][AuthInfoTest.java:99][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]] (496 ms) [main] DEBUG: testAgent#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:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 1 WWW-Authenticate: Digest realm ="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" Content-Length: 0 ] (498 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (503 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 401 Unauthorized To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 1 WWW-Authenticate: Digest realm ="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" Content-Length: 0 ] (504 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (504 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (505 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223301934023" isSender="true" transactionId="z9hg4bkvttmb5" callId="3038ui" firstLine="SIP/2.0 401 Unauthorized" > <![CDATA[SIP/2.0 401 Unauthorized To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 1 WWW-Authenticate: Digest realm ="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (506 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (507 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 269] (507 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (509 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (509 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkvttmb5] SIPUNIT TRACE: 1223301934038 SS.waitRequest() - about to block, waiting (508 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=943172877 Content-Length: 0 CSeq: 1 ACK Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 ] (510 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.fireRetransmissionTimer(SIPServerTransaction.java:1131) [fireRetransmissionTimer() -- ] (511 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPServerTransaction.java:1140][SIPTransaction.java:644][SIPServerTransaction.java:367][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (511 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 401 Unauthorized To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 1 WWW-Authenticate: Digest realm ="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" Content-Length: 0 ] (512 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (513 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (514 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (518 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223301934038" isSender="false" transactionId="z9hg4bkvttmb5" callId="3038ui" firstLine="ACK sip:alice@192.168.0.145:5071 SIP/2.0" > <![CDATA[ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 ACK Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (518 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (518 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (519 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( ACK:z9hG4bKvttmb5):gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (519 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for ACK sip:alice@192.168.0.145:5071 SIP/2.0 gov.nist.javax.sip.DialogFilter@357784 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (519 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (519 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (519 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (520 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process ACK sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (520 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] (520 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = Completed Transaction] (520 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Confirmed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 branchID = z9hG4bKvttmb5 isClient = false] (517 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (520 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:747][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (521 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (522 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (522 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (522 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 tickCount 10 currentTickCount = 63] (522 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 653] (522 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 269] (522 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223301934039" isSender="true" transactionId="z9hg4bkvttmb5" callId="3038ui" firstLine="SIP/2.0 401 Unauthorized" > <![CDATA[SIP/2.0 401 Unauthorized To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 1 WWW-Authenticate: Digest realm ="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", opaque="", stale=FALSE, algorithm=MD5, qop="auth" Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (523 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:768) [ACK received for server Tx z9hg4bkvttmb5 not delivering to application!] (523 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: sip:alice@192.168.0.145:5071 Authorization: Digest username="user1", realm="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", uri="sip:alice@192.168.0.145:5071", response="2d6fb83656f68dc78d74fa211cc1c6b8", algorithm="MD5", qop="auth", nc=00000001, cnonce="cc946bc08728da736440b12a7c0c53ab" Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 INVITE Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKksa9n3;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.apitestapp From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 ] (523 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=943172877 Content-Length: 0 CSeq: 1 ACK Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 ] (523 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (523 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (524 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPServerTransaction.java:775][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (526 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (526 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (524 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (526 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223301934052" isSender="false" transactionId="z9hg4bkvttmb5" callId="3038ui" firstLine="ACK sip:alice@192.168.0.145:5071 SIP/2.0" > <![CDATA[ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 ACK Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (526 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (526 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (527 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (527 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][UDPMessageChannel.java:461][UDPMessageChannel.java:255][Thread.java:613]] (527 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (527 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (528 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing ACK sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (528 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223301934052" isSender="false" transactionId="z9hg4bkksa9n3" callId="3038ui" firstLine="INVITE sip:alice@192.168.0.145:5071 SIP/2.0" > <![CDATA[INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (528 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( ACK:z9hG4bKvttmb5):gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (529 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (529 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for ACK sip:alice@192.168.0.145:5071 SIP/2.0 gov.nist.javax.sip.DialogFilter@6e056e messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (529 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (529 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (530 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkksa9n3] (530 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (530 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (530 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (530 ms) [Thread-12] DEBUG: testAgent#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]] (530 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process ACK sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (531 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKksa9n3] (531 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] (531 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( INVITE:z9hG4bKksa9n3):gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (531 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = Confirmed Transaction] (532 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for INVITE sip:alice@192.168.0.145:5071 SIP/2.0 gov.nist.javax.sip.DialogFilter@26b165 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (533 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=943172877 CSeq: 1 ACK Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvttmb5 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=id6u41 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 listening point = 192.168.0.145:5071] (533 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (533 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Confirmed Transaction] (533 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (534 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3038ui:943172877:id6u41) : returning null] (534 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (534 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 3038ui:943172877:id6u41] (534 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process INVITE sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (534 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (535 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (535 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:257) [Processing ACK for INVITE Tx ] (535 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (535 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [ACK transaction.isMapped = true] (535 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKksa9n3] (536 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49this.sipListener = org.cafesip.sipunit.SipStack@3508c0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@794494] (536 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024 branchID = z9hG4bKksa9n3 isClient = false] (536 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (537 ms) [Thread-12] DEBUG: testAgent#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]] (537 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:827][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (537 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (538 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@489c06] (538 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024 listening point = 192.168.0.145:5071] (538 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (538 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@489c06nevents 1] (538 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Proceeding Transaction] (538 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][UDPMessageChannel.java:461][UDPMessageChannel.java:255][Thread.java:613]] (539 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]source = gov.nist.javax.sip.SipProviderImpl@794494] (540 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3038ui:6eymec) : returning null] (540 ms) [Thread-13] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing ACK sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (541 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : ACK sip:alice@192.168.0.145:5071 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49 sipEvent.serverTx = gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (541 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 3038ui:6eymec] (541 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkvttmb5 existing={z9hg4bkvttmb5=gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49}] (541 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (541 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:191) [transaction already exists! gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49] (542 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [INVITE transaction.isMapped = false] (542 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] (542 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024this.sipListener = org.cafesip.sipunit.SipStack@3508c0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@794494] (542 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkvttmb5] (542 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (543 ms) [Thread-12] DEBUG: testAgent#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]] (543 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@fb7cbb] (543 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing INVITE sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (543 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@fb7cbbnevents 1] (544 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]source = gov.nist.javax.sip.SipProviderImpl@794494] (545 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : INVITE sip:alice@192.168.0.145:5071 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024 sipEvent.serverTx = null] (545 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkksa9n3 existing={z9hg4bkvttmb5=gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49}] (545 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkksa9n3] (546 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (547 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (547 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] SIPUNIT TRACE: 1223301934075 SipStack: request received ! SIPUNIT TRACE: 1223301934075 SipStack: calling listener SIPUNIT TRACE: 1223301934075 SipSession: request received ! SIPUNIT TRACE: 1223301934075 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223301934075 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223301934075 INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223301934075 SipSession: notifying block object SIPUNIT TRACE: 1223301934075 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223301934075 SS.waitRequest() - either we got the request, or timed out SIPUNIT TRACE: 1223301934075 INVITE after received by stack.......... SIPUNIT TRACE: 1223301934075 INVITE sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071> Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 (548 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (548 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message INVITE sip:alice@192.168.0.145:5071 SIP/2.0 ] (548 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (548 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (549 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkksa9n3 existing={z9hg4bkvttmb5=gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49}] (549 ms) [EventScannerThread] DEBUG: testAgent#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]] (549 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (550 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkksa9n3] (551 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$SendTrying.<init>(SIPServerTransaction.java:299) [scheduled timer for gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (551 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkksa9n3] (552 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkksa9n3] (552 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3038ui:6eymec) : returning null] (552 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (552 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@ba1894/2] (553 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@ba1894null/6eymec] (553 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkksa9n3/true] (554 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:1409][AuthInfoTest.java:114][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]] (554 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@ba1894] (554 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (555 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:1409][AuthInfoTest.java:114][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]] (555 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024 dialog = gov.nist.javax.sip.stack.SIPDialog@ba1894] (555 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (556 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@ba1894state = null] SIPUNIT TRACE: 1223301934084 Response before sending out through stack.......... SIPUNIT TRACE: 1223301934084 SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071> CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Expires: 2 Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 (556 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (557 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@ba1894 lastResponse = SIP/2.0 200 OK ] (558 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1600][SipCall.java:1525][SipCall.java:1476][AuthInfoTest.java:123][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]] (558 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (558 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (559 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (559 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (560 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024] (560 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (561 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalTag(SIPDialog.java:1317) [set Local tag b2ec87d7 null] (561 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1319][SIPDialog.java:2280][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1600][SipCall.java:1525][SipCall.java:1476][AuthInfoTest.java:123][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]] (561 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@ba1894newState = 1] (562 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2299][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1600][SipCall.java:1525][SipCall.java:1476][AuthInfoTest.java:123][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]] (562 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@ba1894 old dialog state is null] (562 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@ba1894 New dialog state is Confirmed Dialog] (563 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=3038ui:b2ec87d7:6eymec dialog = gov.nist.javax.sip.stack.SIPDialog@ba1894] (564 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2301][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1600][SipCall.java:1525][SipCall.java:1476][AuthInfoTest.java:123][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]] (564 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.startTimer(SIPDialog.java:1902) [Starting dialog timer for 3038ui:b2ec87d7:6eymec] (565 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024 branchID = z9hG4bKksa9n3 isClient = false] (565 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:994][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipCall.java:1600][SipCall.java:1525][SipCall.java:1476][AuthInfoTest.java:123][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]] (565 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024 getState = Terminated Transaction] (566 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (566 ms) [main] DEBUG: testAgent#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:1864][SipCall.java:1600][SipCall.java:1525][SipCall.java:1476][AuthInfoTest.java:123][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]] (567 ms) [main] DEBUG: testAgent#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:alice@192.168.0.145:5071>;tag=b2ec87d7 CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Expires: 2 Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 ] (568 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (569 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071>;tag=b2ec87d7 CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Expires: 2 Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 ] (570 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (572 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (572 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223301934095" isSender="true" transactionId="z9hg4bkksa9n3" callId="3038ui" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071>;tag=b2ec87d7 CSeq: 2 INVITE Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKksa9n3 From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Expires: 2 Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (572 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (574 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (575 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkksa9n3] SIPUNIT TRACE: 1223301934103 SS.waitRequest() - about to block, waiting (576 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction$LingerTimer.<init>(SIPTransaction.java:261) [LingerTimer : z9hg4bkksa9n3] (577 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (577 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 613] (577 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=b2ec87d7 Authorization: Digest username="user1", realm="beasys.com", nonce="dbffb13c8a4d30117c25c753d1fa7710", uri="sip:alice@192.168.0.145:5071", response="2d6fb83656f68dc78d74fa211cc1c6b8", algorithm="MD5", qop="auth", nc=00000001, cnonce="cc946bc08728da736440b12a7c0c53ab" Content-Length: 0 CSeq: 2 ACK Call-ID: 3038ui Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKx5msrs;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.apitestapp From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 ] (580 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (580 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (580 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223301934106" isSender="false" transactionId="z9hg4bkx5msrs" callId="3038ui" firstLine="ACK sip:alice@192.168.0.145:5071 SIP/2.0" > <![CDATA[ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=b2ec87d7 Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" CSeq: 2 ACK Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKx5msrs From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (581 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (581 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (582 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkx5msrs] (582 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (583 ms) [Thread-14] DEBUG: testAgent#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]] (583 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKx5msrs] (584 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( ACK:z9hG4bKx5msrs):gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (584 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for ACK sip:alice@192.168.0.145:5071 SIP/2.0 gov.nist.javax.sip.DialogFilter@385715 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (587 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (587 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (588 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (588 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process ACK sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (588 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] (588 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (588 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKx5msrs] (588 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3 branchID = z9hG4bKx5msrs isClient = false] (589 ms) [Thread-14] DEBUG: testAgent#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]] (589 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (590 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=b2ec87d7 Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" CSeq: 2 ACK Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKx5msrs From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3 listening point = 192.168.0.145:5071] (590 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (590 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3038ui:b2ec87d7:6eymec) : returning gov.nist.javax.sip.stack.SIPDialog@ba1894] (590 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 3038ui:b2ec87d7:6eymec] (590 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = gov.nist.javax.sip.stack.SIPDialog@ba1894] (591 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:262) [Processing ACK for dialog gov.nist.javax.sip.stack.SIPDialog@ba1894] (591 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3 dialog = gov.nist.javax.sip.stack.SIPDialog@ba1894] (591 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.ackReceived(SIPDialog.java:754) [ackReceived for INVITE] (591 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:884) [isServer = true] (591 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:885) [localTag = b2ec87d7] (592 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:886) [remoteTag = 6eymec] (592 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:887) [localSequenceNumer = 0] (592 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:889) [remoteSequenceNumer = 2] (593 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:891) [ackLine:6eymec 466] (593 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@ba1894newState = 1] (593 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:759][SIPDialog.java:2663][DialogFilter.java:286][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (594 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.handleAck(SIPDialog.java:2664) [ACK for 2XX response --- sending to TU ] (594 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@ba1894/2] (594 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@ba1894b2ec87d7/6eymec] (594 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkx5msrs/true] (594 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][DialogFilter.java:290][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (595 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@ba1894state = Confirmed Dialog] (595 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3 dialog = gov.nist.javax.sip.stack.SIPDialog@ba1894] (595 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : ACK returning false] (595 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [ACK transaction.isMapped = true] (595 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3this.sipListener = org.cafesip.sipunit.SipStack@3508c0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@794494] (596 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = gov.nist.javax.sip.stack.SIPDialog@ba1894] (596 ms) [Thread-14] DEBUG: testAgent#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]] (596 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@bc7c0] (597 ms) [Thread-14] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing ACK sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (597 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@bc7c0nevents 1] (597 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@794494]source = gov.nist.javax.sip.SipProviderImpl@794494] (597 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : ACK sip:alice@192.168.0.145:5071 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3 sipEvent.serverTx = gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (597 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkx5msrs existing={z9hg4bkksa9n3=gov.nist.javax.sip.stack.SIPServerTransaction@e2e0a024, z9hg4bkvttmb5=gov.nist.javax.sip.stack.SIPServerTransaction@f5bd6b49}] (597 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkx5msrs] (598 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (598 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] (598 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] SIPUNIT TRACE: 1223301934126 SipStack: request received ! SIPUNIT TRACE: 1223301934126 SipStack: calling listener SIPUNIT TRACE: 1223301934126 SipSession: request received ! SIPUNIT TRACE: 1223301934126 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223301934126 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071 SIPUNIT TRACE: 1223301934126 ACK sip:alice@192.168.0.145:5071 SIP/2.0 To: <sip:alice@192.168.0.145:5071>;tag=b2ec87d7 Authorization: Digest cnonce="cc946bc08728da736440b12a7c0c53ab",qop="auth",uri="sip:alice@192.168.0.145:5071",realm="beasys.com",username="user1",nonce="dbffb13c8a4d30117c25c753d1fa7710",algorithm="MD5",nc=00000001,response="2d6fb83656f68dc78d74fa211cc1c6b8" CSeq: 2 ACK Call-ID: 3038ui 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.apitestapp;branch=z9hG4bKx5msrs From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=6eymec Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223301934126 SipSession: notifying block object (598 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] SIPUNIT TRACE: 1223301934127 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223301934127 SS.waitRequest() - either we got the request, or timed out (599 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:803) [Request Consumed -- next consumable Request Seqno = 3] (599 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@f9e6e5newState = 3] (599 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message ACK sip:alice@192.168.0.145:5071 SIP/2.0 ] (599 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:1334][SipCall.java:158][SipPhone.java:1231][TestBase.java:249][TestCase.java:130][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]] (599 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3] (600 ms) [EventScannerThread] DEBUG: testAgent#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]] (600 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkx5msrs] (601 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f5ac3de3 branchID = z9hG4bKx5msrs isClient = false] (601 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (601 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][EventScanner.java:267][EventScanner.java:492][Thread.java:613]] (601 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (601 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (1602 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (1602 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (1603 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (2604 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (2604 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (2605 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]