(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} ] (10 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (10 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (12 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (73 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (263 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] (264 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@5da37c listeningPoint = gov.nist.javax.sip.ListeningPointImpl@9845fb] (268 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@9845fb] (287 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@c54654] (288 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} ] (288 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (288 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (289 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (289 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (290 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (290 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (293 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] (293 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@8c6982 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@62e703] (295 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@62e703] (296 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@2c7ac5] (298 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} ] (299 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (299 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (299 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (301 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (342 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (345 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (347 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] (347 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@303a60 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@487ae0] (348 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@487ae0] (348 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@7b21ea] (607 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (625 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 ] (631 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 314] (634 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 408 Request Timeout To: Bob <sip:bob@192.168.0.145:5072>;tag=nzxx8j Content-Length: 0 CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: Alice <sip:alice@192.168.0.145:5071>;tag=416193590 ] (635 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] (640 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(5abd665f22e2905ef621be117bbf5fe5@192.168.0.145:931810555) : returning null] (641 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (644 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (645 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (650 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (650 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:62253" to="192.168.0.145:5071" time="1223302265038" isSender="false" transactionId="z9hg4bkb4ccddf613d9dec89c56d19337255aea" callId="4afc1673a59e809df6b1384d990a34a4@192.168.0.145" firstLine="SIP/2.0 408 Request Timeout" > <![CDATA[SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=nzxx8j CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: "Alice" <sip:alice@192.168.0.145:5071>;tag=416193590 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (676 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (651 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:664][TestBase.java:627][ServletTimerTest.java:40][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]] (684 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (686 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK67372621bf770a4480994105275c62b4] (688 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bkb4ccddf613d9dec89c56d19337255aea] (690 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction null for SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=nzxx8j CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: "Alice" <sip:alice@192.168.0.145:5071>;tag=416193590 Content-Length: 0 ] (693 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(4afc1673a59e809df6b1384d990a34a4@192.168.0.145:416193590:nzxx8j) : returning null] (689 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk67372621bf770a4480994105275c62b4] (695 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK67372621bf770a4480994105275c62b4] (695 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (694 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1098) [PROCESSING INCOMING RESPONSE: SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=nzxx8j CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: "Alice" <sip:alice@192.168.0.145:5071>;tag=416193590 Content-Length: 0 ] (698 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1142) [Transaction = null sipDialog = null] (698 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (697 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: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 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: ServletTimer Method-Name: testCancel001 Content-Length: 0 ] (707 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@4a1ab7 lastResponse = SIP/2.0 408 Request Timeout ] (763 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPDialog.java:345][DialogFilter.java:1173][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (763 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (762 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: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 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: ServletTimer Method-Name: testCancel001 Content-Length: 0 ] (785 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (787 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK67372621bf770a4480994105275c62b4] (787 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@9d060c77 branchID = z9hG4bK67372621bf770a4480994105275c62b4 isClient = true] (788 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:664][TestBase.java:627][ServletTimerTest.java:40][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]] (788 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77 tickCount 64 currentTickCount = -1] (789 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:664][TestBase.java:627][ServletTimerTest.java:40][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]] (785 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (817 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = null] (817 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 408] (818 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = null] (818 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (818 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:359) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@4a1ab7] (818 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:360][DialogFilter.java:1173][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (819 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1224) [sending response to TU for processing ] (819 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@4a1ab7 lastResponse = SIP/2.0 408 Request Timeout ] (819 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1229][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (819 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (819 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (816 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: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 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: ServletTimer Method-Name: testCancel001 Content-Length: 0 ] (821 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (829 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 408] (829 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = null] (830 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (830 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@4a1ab7newState = 3] (830 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][DialogFilter.java:1229][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (830 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@4a1ab7 old dialog state is Early Dialog] (831 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@4a1ab7 New dialog state is Terminated Dialog] (829 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (833 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@ce08c7]currentTransaction = nullthis.sipListener = org.cafesip.sipunit.SipStack@c54654sipEvent.source = gov.nist.javax.sip.SipProviderImpl@ce08c7] (835 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@4a1ab7] (835 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1235][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (839 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (843 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (844 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 312] (844 ms) [Thread-10] 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=71ahnf Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 From: Alice <sip:alice@192.168.0.145:5071>;tag=931810555 ] (843 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (846 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="1223302265183" isSender="true" transactionId="z9hg4bk67372621bf770a4480994105275c62b4" callId="5abd665f22e2905ef621be117bbf5fe5@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: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 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: ServletTimer Method-Name: testCancel001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (846 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (846 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (853 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77] (853 ms) [Thread-10] 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]] (868 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@3bbcfd] (869 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (869 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (870 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (869 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@3bbcfdnevents 1] (917 ms) [Thread-10] 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="1223302265264" isSender="false" transactionId="z9hg4bk67372621bf770a4480994105275c62b4" callId="5abd665f22e2905ef621be117bbf5fe5@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=71ahnf CSeq: 1 MESSAGE Call-ID: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (918 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (919 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (919 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk67372621bf770a4480994105275c62b4] (919 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=71ahnf CSeq: 1 MESSAGE Call-ID: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 Content-Length: 0 ] (920 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77 to gov.nist.javax.sip.DialogFilter@ba1894] (920 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (918 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@ce08c7]source = gov.nist.javax.sip.SipProviderImpl@ce08c7] (922 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (923 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 408 Request Timeout ] (923 ms) [Thread-10] 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=71ahnf CSeq: 1 MESSAGE Call-ID: 5abd665f22e2905ef621be117bbf5fe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK67372621bf770a4480994105275c62b4 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=931810555 Content-Length: 0 ] (924 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77] (924 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@ce08c7]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77this.sipListener = org.cafesip.sipunit.SipStack@c54654sipEvent.source = gov.nist.javax.sip.SipProviderImpl@ce08c7] (924 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (924 ms) [Thread-10] 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]] (1051 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@b7c63f] (1051 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77 branchID = z9hG4bK67372621bf770a4480994105275c62b4 isClient = true] (1051 ms) [Thread-10] 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]] (1052 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77 tickCount 10 currentTickCount = 64] (1052 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77] (1052 ms) [Thread-10] 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]] (1054 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@b7c63fnevents 1] (1055 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@ce08c7]source = gov.nist.javax.sip.SipProviderImpl@ce08c7] (1055 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (1055 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (1056 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@9d060c77] (1056 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]] (1057 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (1057 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (1058 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (2094 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (2095 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (2095 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (3096 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (3097 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (3097 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (4133 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (4173 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (4174 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] (4240 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@ab58d listeningPoint = gov.nist.javax.sip.ListeningPointImpl@156508] (4241 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@156508] (4242 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@9c2931] (4243 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (4243 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (4244 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] (4246 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@548414 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@ab7626] (4307 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@ab7626] (4308 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@d9c3e7] (4308 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (4309 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (4310 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] (4310 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@cc892e listeningPoint = gov.nist.javax.sip.ListeningPointImpl@425f38] (4311 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@425f38] (4311 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@798249] (4315 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 ] (4315 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] (4315 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(a2b9e12b576f956941ef4490f17eb68c@192.168.0.145:1892619930) : returning null] (4316 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (4316 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (4317 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:664][TestBase.java:627][ServletTimerTest.java:46][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]] (4373 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK03c55a1eeb8889c438d7824c253bc922] (4375 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk03c55a1eeb8889c438d7824c253bc922] (4375 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK03c55a1eeb8889c438d7824c253bc922] (4376 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (4377 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: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 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: ServletTimer Method-Name: testGetApplicationSession001 Content-Length: 0 ] (4377 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: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 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: ServletTimer Method-Name: testGetApplicationSession001 Content-Length: 0 ] (4428 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (4429 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK03c55a1eeb8889c438d7824c253bc922] (4431 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@f6c8070c branchID = z9hG4bK03c55a1eeb8889c438d7824c253bc922 isClient = true] (4432 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:664][TestBase.java:627][ServletTimerTest.java:46][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]] (4550 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c tickCount 64 currentTickCount = -1] (4552 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:664][TestBase.java:627][ServletTimerTest.java:46][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]] (4553 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: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 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: ServletTimer Method-Name: testGetApplicationSession001 Content-Length: 0 ] (4554 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (4559 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (4559 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 313] (4560 ms) [Thread-20] 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=ri6tyu Content-Length: 0 CSeq: 1 MESSAGE Call-ID: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 From: Alice <sip:alice@192.168.0.145:5071>;tag=1892619930 ] (4561 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} ] (4605 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (4641 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c] (4641 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (4641 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 314] (4642 ms) [Thread-20] 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]] (4642 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (4643 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 408 Request Timeout To: Bob <sip:bob@192.168.0.145:5072>;tag=nzxx8j Content-Length: 0 CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: Alice <sip:alice@192.168.0.145:5071>;tag=416193590 ] (4643 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (4644 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (4644 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4645 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4645 ms) [Thread-20] 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="1223302269039" isSender="false" transactionId="z9hg4bk03c55a1eeb8889c438d7824c253bc922" callId="a2b9e12b576f956941ef4490f17eb68c@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=ri6tyu CSeq: 1 MESSAGE Call-ID: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4645 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4645 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (4646 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (4646 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4645 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4647 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4647 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk03c55a1eeb8889c438d7824c253bc922] (4648 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4648 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4648 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=ri6tyu CSeq: 1 MESSAGE Call-ID: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 Content-Length: 0 ] (4649 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="1223302268946" isSender="true" transactionId="z9hg4bk03c55a1eeb8889c438d7824c253bc922" callId="a2b9e12b576f956941ef4490f17eb68c@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: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 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: ServletTimer Method-Name: testGetApplicationSession001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4648 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:62253" to="192.168.0.145:5071" time="1223302269040" isSender="false" transactionId="z9hg4bkb4ccddf613d9dec89c56d19337255aea" callId="4afc1673a59e809df6b1384d990a34a4@192.168.0.145" firstLine="SIP/2.0 408 Request Timeout" > <![CDATA[SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=nzxx8j CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: "Alice" <sip:alice@192.168.0.145:5071>;tag=416193590 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4649 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c to gov.nist.javax.sip.DialogFilter@5b44d6] (4649 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4650 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4650 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (4651 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4651 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4652 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bkb4ccddf613d9dec89c56d19337255aea] (4651 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (4652 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction null for SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=nzxx8j CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: "Alice" <sip:alice@192.168.0.145:5071>;tag=416193590 Content-Length: 0 ] (4652 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(4afc1673a59e809df6b1384d990a34a4@192.168.0.145:416193590:nzxx8j) : returning null] (4652 ms) [Thread-20] 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=ri6tyu CSeq: 1 MESSAGE Call-ID: a2b9e12b576f956941ef4490f17eb68c@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK03c55a1eeb8889c438d7824c253bc922 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1892619930 Content-Length: 0 ] (4652 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1098) [PROCESSING INCOMING RESPONSE: SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=nzxx8j CSeq: 1 INVITE Call-ID: 4afc1673a59e809df6b1384d990a34a4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKb4ccddf613d9dec89c56d19337255aea From: "Alice" <sip:alice@192.168.0.145:5071>;tag=416193590 Content-Length: 0 ] (4653 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c] (4653 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1142) [Transaction = null sipDialog = null] (4654 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@33549b]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070cthis.sipListener = org.cafesip.sipunit.SipStack@9c2931sipEvent.source = gov.nist.javax.sip.SipProviderImpl@33549b] (4654 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (4654 ms) [Thread-20] 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]] (4654 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (4655 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@44daf] (4655 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@882d18 lastResponse = SIP/2.0 408 Request Timeout ] (4655 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPDialog.java:345][DialogFilter.java:1173][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (4655 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c branchID = z9hG4bK03c55a1eeb8889c438d7824c253bc922 isClient = true] (4655 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@44dafnevents 1] (4656 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (4656 ms) [Thread-20] 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]] (4656 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@33549b]source = gov.nist.javax.sip.SipProviderImpl@33549b] (4656 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (4656 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (4656 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c tickCount 10 currentTickCount = 64] (4658 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = null] (4658 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (4658 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c] (4658 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 408] (4659 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@f6c8070c] (4659 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (4740 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]] (4659 ms) [Thread-20] 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]] (4659 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (4659 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = null] (4741 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (4742 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (4743 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:359) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@882d18] (4744 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:360][DialogFilter.java:1173][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (4745 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1224) [sending response to TU for processing ] (4745 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@882d18 lastResponse = SIP/2.0 408 Request Timeout ] (4746 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1229][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (4746 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (4746 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (4747 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (4747 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 408] (4747 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = null] (4748 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (4748 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@882d18newState = 3] (4748 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][DialogFilter.java:1229][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (4748 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@882d18 old dialog state is Early Dialog] (4748 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@882d18 New dialog state is Terminated Dialog] (4749 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@33549b]currentTransaction = nullthis.sipListener = nullsipEvent.source = gov.nist.javax.sip.SipProviderImpl@33549b] (4749 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@882d18] (4749 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1235][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (4749 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@389922] (5741 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (5742 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (5743 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (6743 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (6744 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (6744 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (7746 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (7747 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (7750 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] (7750 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@8d12e4 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@d35bf2] (7751 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@d35bf2] (7751 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@398044] (7753 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (7753 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (7754 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] (7754 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@141d19 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@825459] (7755 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@825459] (7755 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@6fb3d6] (7756 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (7756 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (7759 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] (7759 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@87a8e0 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@602bbc] (7760 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@602bbc] (7768 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@d75cf7] (7771 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 ] (7771 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] (7771 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3dcbe235957b34f9d84048f991c7ff67@192.168.0.145:1020504687) : returning null] (7772 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (7772 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (7773 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:664][TestBase.java:627][ServletTimerTest.java:54][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]] (7774 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK0829446749c7d7ed37743367a5ae3c05] (7775 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk0829446749c7d7ed37743367a5ae3c05] (7775 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK0829446749c7d7ed37743367a5ae3c05] (7775 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (7776 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: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 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: ServletTimer Method-Name: testGetId001 Content-Length: 0 ] (7777 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: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 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: ServletTimer Method-Name: testGetId001 Content-Length: 0 ] (7777 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (7778 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK0829446749c7d7ed37743367a5ae3c05] (7778 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@d5e60449 branchID = z9hG4bK0829446749c7d7ed37743367a5ae3c05 isClient = true] (7779 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:664][TestBase.java:627][ServletTimerTest.java:54][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]] (7779 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449 tickCount 64 currentTickCount = -1] (7780 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:664][TestBase.java:627][ServletTimerTest.java:54][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]] (7780 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: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 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: ServletTimer Method-Name: testGetId001 Content-Length: 0 ] (7781 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (7782 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} ] (7782 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (7782 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (7783 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (7785 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (7785 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (7786 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (7786 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (7786 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="1223302272174" isSender="true" transactionId="z9hg4bk0829446749c7d7ed37743367a5ae3c05" callId="3dcbe235957b34f9d84048f991c7ff67@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: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 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: ServletTimer Method-Name: testGetId001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (7787 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (7786 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (7788 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 313] (7788 ms) [Thread-31] 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=m5cwtt Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 From: Alice <sip:alice@192.168.0.145:5071>;tag=1020504687 ] (7788 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (7789 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449] (7790 ms) [Thread-31] 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]] (7790 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (7791 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (7791 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (7791 ms) [Thread-31] 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="1223302272185" isSender="false" transactionId="z9hg4bk0829446749c7d7ed37743367a5ae3c05" callId="3dcbe235957b34f9d84048f991c7ff67@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=m5cwtt CSeq: 1 MESSAGE Call-ID: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (7792 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (7792 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (7792 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk0829446749c7d7ed37743367a5ae3c05] (7793 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=m5cwtt CSeq: 1 MESSAGE Call-ID: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 Content-Length: 0 ] (7793 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449 to gov.nist.javax.sip.DialogFilter@656758] (7794 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (7794 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (7794 ms) [Thread-31] 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=m5cwtt CSeq: 1 MESSAGE Call-ID: 3dcbe235957b34f9d84048f991c7ff67@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK0829446749c7d7ed37743367a5ae3c05 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1020504687 Content-Length: 0 ] (7794 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449] (7794 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@186cf9]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449this.sipListener = org.cafesip.sipunit.SipStack@398044sipEvent.source = gov.nist.javax.sip.SipProviderImpl@186cf9] (7795 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (7795 ms) [Thread-31] 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]] (7795 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@63de4e] (7795 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449 branchID = z9hG4bK0829446749c7d7ed37743367a5ae3c05 isClient = true] (7795 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@63de4enevents 1] (7796 ms) [Thread-31] 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]] (7796 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@186cf9]source = gov.nist.javax.sip.SipProviderImpl@186cf9] (7797 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449 tickCount 10 currentTickCount = 64] (7797 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (7797 ms) [Thread-31] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449] (7797 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (7797 ms) [Thread-31] 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]] (7798 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@d5e60449] (7798 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (7798 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (7798 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]] (7799 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (8862 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (8862 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (8863 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (9864 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (9864 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (9866 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (10868 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (10869 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (10873 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] (10873 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@556f4c listeningPoint = gov.nist.javax.sip.ListeningPointImpl@fe0816] (10874 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@fe0816] (10877 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@c50561] (10878 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (10878 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (10883 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] (10884 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@509bfc listeningPoint = gov.nist.javax.sip.ListeningPointImpl@30cefd] (10885 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@30cefd] (10886 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@65724d] (10886 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (10886 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (10887 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] (10887 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@333b2e listeningPoint = gov.nist.javax.sip.ListeningPointImpl@727745] (10888 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@727745] (10888 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@f480e3] (10890 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 ] (10892 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] (10892 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145:815019796) : returning null] (10893 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (10893 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (10893 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:664][TestBase.java:627][ServletTimerTest.java:60][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]] (10894 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK021a48e7106a4d27074541005c8f7d12] (10894 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk021a48e7106a4d27074541005c8f7d12] (10895 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK021a48e7106a4d27074541005c8f7d12] (10896 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (10896 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: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 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: ServletTimer Method-Name: testGetInfo001 Content-Length: 0 ] (10897 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: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 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: ServletTimer Method-Name: testGetInfo001 Content-Length: 0 ] (10897 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (10898 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK021a48e7106a4d27074541005c8f7d12] (10898 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@6135fff5 branchID = z9hG4bK021a48e7106a4d27074541005c8f7d12 isClient = true] (10899 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:664][TestBase.java:627][ServletTimerTest.java:60][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]] (10899 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5 tickCount 64 currentTickCount = -1] (10906 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:664][TestBase.java:627][ServletTimerTest.java:60][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]] (10906 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: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 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: ServletTimer Method-Name: testGetInfo001 Content-Length: 0 ] (10906 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (10907 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} ] (10908 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (10908 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (10909 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (10909 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (10909 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (10910 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (10910 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (10911 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="1223302275294" isSender="true" transactionId="z9hg4bk021a48e7106a4d27074541005c8f7d12" callId="3cd4cfda1bead92dd648f45c9eb1fe6b@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: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 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: ServletTimer Method-Name: testGetInfo001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (10911 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (10911 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (10916 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (10916 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 312] (10917 ms) [Thread-41] 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=hjkbd6 Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 From: Alice <sip:alice@192.168.0.145:5071>;tag=815019796 ] (10919 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5] (10919 ms) [Thread-41] 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]] (10920 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (10920 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (10921 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (10921 ms) [Thread-41] 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="1223302275315" isSender="false" transactionId="z9hg4bk021a48e7106a4d27074541005c8f7d12" callId="3cd4cfda1bead92dd648f45c9eb1fe6b@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=hjkbd6 CSeq: 1 MESSAGE Call-ID: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (10921 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (10921 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (10922 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk021a48e7106a4d27074541005c8f7d12] (10922 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=hjkbd6 CSeq: 1 MESSAGE Call-ID: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 Content-Length: 0 ] (10922 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5 to gov.nist.javax.sip.DialogFilter@3f7175] (10922 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (10922 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (10923 ms) [Thread-41] 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=hjkbd6 CSeq: 1 MESSAGE Call-ID: 3cd4cfda1bead92dd648f45c9eb1fe6b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK021a48e7106a4d27074541005c8f7d12 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=815019796 Content-Length: 0 ] (10923 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5] (10923 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@39ed6d]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5this.sipListener = org.cafesip.sipunit.SipStack@c50561sipEvent.source = gov.nist.javax.sip.SipProviderImpl@39ed6d] (10923 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (10924 ms) [Thread-41] 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]] (10925 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@31c43f] (10925 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5 branchID = z9hG4bK021a48e7106a4d27074541005c8f7d12 isClient = true] (10925 ms) [Thread-41] 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]] (10926 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5 tickCount 10 currentTickCount = 64] (10926 ms) [Thread-41] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5] (10926 ms) [Thread-41] 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]] (10926 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@31c43fnevents 1] (10926 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@39ed6d]source = gov.nist.javax.sip.SipProviderImpl@39ed6d] (10927 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (10927 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (10927 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@6135fff5] (10927 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]] (10928 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (10928 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (10929 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (11973 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (11974 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (11974 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (12974 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (12974 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (12976 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (13977 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (13978 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (13979 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] (13980 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@48f7e0 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@89b9bd] (13981 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@89b9bd] (13981 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@13985] (13984 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (13985 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (13986 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] (13987 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@675ec4 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@7eb767] (13987 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@7eb767] (13988 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@3b014c] (13988 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (13989 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (13990 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] (13990 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@d26552 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@fa157c] (13990 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@fa157c] (13991 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@988d36] (13993 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 ] (13993 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] (13993 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(799a9a2628160c8ababe04d020e10b2b@192.168.0.145:526499082) : returning null] (13994 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (13994 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (13994 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][ServletTimerTest.java:93][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]] (13995 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK00e9adc17bd1894820f62706e32b6ec7] (13996 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk00e9adc17bd1894820f62706e32b6ec7] (13996 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK00e9adc17bd1894820f62706e32b6ec7] (13996 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (13997 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: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 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: ServletTimer Method-Name: testGetTimeRemaining001 Content-Length: 0 ] (13997 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: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 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: ServletTimer Method-Name: testGetTimeRemaining001 Content-Length: 0 ] (13997 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (13998 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK00e9adc17bd1894820f62706e32b6ec7] (13999 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@dfc0d57b branchID = z9hG4bK00e9adc17bd1894820f62706e32b6ec7 isClient = true] (13999 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][ServletTimerTest.java:93][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]] (13999 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b tickCount 64 currentTickCount = -1] (14000 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][ServletTimerTest.java:93][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]] (14000 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: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 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: ServletTimer Method-Name: testGetTimeRemaining001 Content-Length: 0 ] (14001 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (14001 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} ] (14002 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (14002 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (14002 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (14003 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (14004 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (14004 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (14004 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 312] (14006 ms) [Thread-51] 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=s7upgz Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 From: Alice <sip:alice@192.168.0.145:5071>;tag=526499082 ] (14006 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (14006 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (14007 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="1223302278394" isSender="true" transactionId="z9hg4bk00e9adc17bd1894820f62706e32b6ec7" callId="799a9a2628160c8ababe04d020e10b2b@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: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 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: ServletTimer Method-Name: testGetTimeRemaining001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (14007 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b] (14007 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (14007 ms) [Thread-51] 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]] (14007 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (14008 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (14009 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (14009 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (14009 ms) [Thread-51] 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="1223302278403" isSender="false" transactionId="z9hg4bk00e9adc17bd1894820f62706e32b6ec7" callId="799a9a2628160c8ababe04d020e10b2b@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=s7upgz CSeq: 1 MESSAGE Call-ID: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (14011 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (14011 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (14011 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk00e9adc17bd1894820f62706e32b6ec7] (14012 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=s7upgz CSeq: 1 MESSAGE Call-ID: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 Content-Length: 0 ] (14012 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b to gov.nist.javax.sip.DialogFilter@bec43f] (14012 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (14012 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (14013 ms) [Thread-51] 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=s7upgz CSeq: 1 MESSAGE Call-ID: 799a9a2628160c8ababe04d020e10b2b@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK00e9adc17bd1894820f62706e32b6ec7 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=526499082 Content-Length: 0 ] (14013 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b] (14014 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@5f0e7d]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57bthis.sipListener = org.cafesip.sipunit.SipStack@13985sipEvent.source = gov.nist.javax.sip.SipProviderImpl@5f0e7d] (14014 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (14014 ms) [Thread-51] 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]] (14014 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@462f90] (14014 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b branchID = z9hG4bK00e9adc17bd1894820f62706e32b6ec7 isClient = true] (14014 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@462f90nevents 1] (14015 ms) [Thread-51] 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]] (14015 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@5f0e7d]source = gov.nist.javax.sip.SipProviderImpl@5f0e7d] (14015 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b tickCount 10 currentTickCount = 64] (14015 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (14015 ms) [Thread-51] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b] (14015 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] SIPUNIT TRACE: 1223302278411 SS.waitRequest() - about to block, waiting (14015 ms) [Thread-51] 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]] (14015 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@dfc0d57b] (14016 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]] (15208 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (15208 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 280] (15209 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 To: Alice <sip:alice@192.168.0.145:5071> Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: JSR289_TCK <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Max-Forwards: 70 ] (15211 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (15211 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (15212 ms) [Thread-52] 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="1223302279604" isSender="false" transactionId="z9hg4bkk93f2d" callId="4zxup8" firstLine="MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0" > <![CDATA[MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 To: "Alice" <sip:alice@192.168.0.145:5071> CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (15212 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (15212 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (15213 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkk93f2d] (15219 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (15219 ms) [Thread-52] 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]] (15219 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKk93f2d] (15221 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( MESSAGE:z9hG4bKk93f2d):gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15221 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 gov.nist.javax.sip.DialogFilter@c5c32e messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15222 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15222 ms) [Thread-52] 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]] (15222 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (15222 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15223 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 ] (15224 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (15224 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKk93f2d] (15224 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2 branchID = z9hG4bKk93f2d isClient = false] (15225 ms) [Thread-52] 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]] (15225 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (15225 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 To: "Alice" <sip:alice@192.168.0.145:5071> CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2 listening point = 192.168.0.145:5071] (15226 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (15226 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(4zxup8:rn59yu) : returning null] (15226 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 4zxup8:rn59yu] (15228 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (15229 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [MESSAGE transaction.isMapped = false] (15229 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@5f0e7d]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2this.sipListener = org.cafesip.sipunit.SipStack@13985sipEvent.source = gov.nist.javax.sip.SipProviderImpl@5f0e7d] (15230 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (15230 ms) [Thread-52] 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]] (15230 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@91275b] (15231 ms) [Thread-52] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15231 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@91275bnevents 1] (15231 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@5f0e7d]source = gov.nist.javax.sip.SipProviderImpl@5f0e7d] (15232 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2 sipEvent.serverTx = null] (15233 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkk93f2d existing={}] (15233 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkk93f2d] (15233 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15234 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 ] (15236 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] SIPUNIT TRACE: 1223302279631 SipStack: request received ! SIPUNIT TRACE: 1223302279631 SipStack: calling listener SIPUNIT TRACE: 1223302279631 SipSession: request received ! SIPUNIT TRACE: 1223302279631 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223302279631 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223302279631 MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 To: "Alice" <sip:alice@192.168.0.145:5071> CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223302279632 SipSession: notifying block object SIPUNIT TRACE: 1223302279632 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223302279632 SS.waitRequest() - either we got the request, or timed out (15237 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 ] (15237 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message MESSAGE sip:alice@192.168.0.145:5071 SIP/2.0 ] (15237 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (15237 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15238 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkk93f2d existing={}] (15238 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]] (15239 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2] (15240 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkk93f2d] (15240 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkk93f2d] (15240 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkk93f2d] (15240 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(4zxup8:rn59yu) : returning null] (15241 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@df9b05b2 branchID = z9hG4bKk93f2d isClient = false] (15241 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][ServletTimerTest.java:122][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]] (15242 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2 tickCount 64 currentTickCount = -1] (15242 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@df9b05b2 getState = Completed Transaction] (15243 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (15243 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][ServletTimerTest.java:122][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]] (15244 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: "Alice" <sip:alice@192.168.0.145:5071>;tag=940673157 CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 ] (15244 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (15244 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: "Alice" <sip:alice@192.168.0.145:5071>;tag=940673157 CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 ] (15246 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (15246 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (15247 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="1223302279639" isSender="true" transactionId="z9hg4bkk93f2d" callId="4zxup8" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: "Alice" <sip:alice@192.168.0.145:5071>;tag=940673157 CSeq: 1 MESSAGE Call-ID: 4zxup8 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKk93f2d From: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=rn59yu Contact: <sip:alice@192.168.0.145:5071> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (15247 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (15248 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (15248 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkk93f2d] (15249 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (15249 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (15249 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (16250 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (16251 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (16251 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (17252 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (17252 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (17253 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (18255 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (18256 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (18257 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] (18258 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@1dfe1a listeningPoint = gov.nist.javax.sip.ListeningPointImpl@15632d] (18258 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@15632d] (18259 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@2221f6] (18259 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (18260 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (18260 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] (18261 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@e3bddb listeningPoint = gov.nist.javax.sip.ListeningPointImpl@c5a2f7] (18262 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@c5a2f7] (18262 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@4e430c] (18263 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (18263 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (18264 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] (18264 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@13de03 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@54c08a] (18265 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@54c08a] (18265 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@2cdd20] (18272 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 ] (18273 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] (18273 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(53525ed1b9d72129433ae12ee8187c13@192.168.0.145:1651462470) : returning null] (18274 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (18274 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (18274 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:664][TestBase.java:627][ServletTimerTest.java:130][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]] (18275 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKae750547c3a0520a78e8ba51d347e272] (18275 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bkae750547c3a0520a78e8ba51d347e272] (18276 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKae750547c3a0520a78e8ba51d347e272] (18276 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (18277 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: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 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: ServletTimer Method-Name: testGetTimeRemaining002 Content-Length: 0 ] (18277 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: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 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: ServletTimer Method-Name: testGetTimeRemaining002 Content-Length: 0 ] (18277 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (18278 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKae750547c3a0520a78e8ba51d347e272] (18278 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@c2a6bc3f branchID = z9hG4bKae750547c3a0520a78e8ba51d347e272 isClient = true] (18279 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:664][TestBase.java:627][ServletTimerTest.java:130][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]] (18279 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f tickCount 64 currentTickCount = -1] (18280 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:664][TestBase.java:627][ServletTimerTest.java:130][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]] (18280 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: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 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: ServletTimer Method-Name: testGetTimeRemaining002 Content-Length: 0 ] (18281 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (18281 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} ] (18282 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (18282 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (18282 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (18283 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (18283 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (18284 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (18284 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (18285 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="1223302282674" isSender="true" transactionId="z9hg4bkae750547c3a0520a78e8ba51d347e272" callId="53525ed1b9d72129433ae12ee8187c13@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: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 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: ServletTimer Method-Name: testGetTimeRemaining002 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (18285 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (18285 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (18384 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (18385 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 313] (18385 ms) [Thread-62] 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=kk5j3r Content-Length: 0 CSeq: 1 MESSAGE Call-ID: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 From: Alice <sip:alice@192.168.0.145:5071>;tag=1651462470 ] (18386 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f] (18386 ms) [Thread-62] 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]] (18386 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (18387 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (18388 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (18388 ms) [Thread-62] 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="1223302282781" isSender="false" transactionId="z9hg4bkae750547c3a0520a78e8ba51d347e272" callId="53525ed1b9d72129433ae12ee8187c13@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=kk5j3r CSeq: 1 MESSAGE Call-ID: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (18388 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (18388 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (18389 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bkae750547c3a0520a78e8ba51d347e272] (18389 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=kk5j3r CSeq: 1 MESSAGE Call-ID: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 Content-Length: 0 ] (18389 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f to gov.nist.javax.sip.DialogFilter@373a9c] (18390 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (18390 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (18391 ms) [Thread-62] 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=kk5j3r CSeq: 1 MESSAGE Call-ID: 53525ed1b9d72129433ae12ee8187c13@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKae750547c3a0520a78e8ba51d347e272 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1651462470 Content-Length: 0 ] (18391 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f] (18391 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@59e6df]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3fthis.sipListener = org.cafesip.sipunit.SipStack@2221f6sipEvent.source = gov.nist.javax.sip.SipProviderImpl@59e6df] (18392 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (18392 ms) [Thread-62] 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]] (18393 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@e91259] (18393 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f branchID = z9hG4bKae750547c3a0520a78e8ba51d347e272 isClient = true] (18393 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@e91259nevents 1] (18393 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@59e6df]source = gov.nist.javax.sip.SipProviderImpl@59e6df] (18393 ms) [Thread-62] 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]] (18393 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (18394 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f tickCount 10 currentTickCount = 64] (18394 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (18394 ms) [Thread-62] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f] (18394 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@c2a6bc3f] (18394 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (18394 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (18394 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]] (18394 ms) [Thread-62] 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]] (18395 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (19396 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (19396 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (19397 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (20397 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (20397 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (20399 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (21400 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (21400 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (21402 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] (21402 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@e1153a listeningPoint = gov.nist.javax.sip.ListeningPointImpl@38c403] (21402 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@38c403] (21404 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@ccbab7] (21404 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (21405 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (21405 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] (21406 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@f65b5b listeningPoint = gov.nist.javax.sip.ListeningPointImpl@e7ce87] (21406 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@e7ce87] (21407 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@a80e5a] (21408 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (21408 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (21409 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] (21409 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@54cbb9 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@ae3fb] (21411 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@ae3fb] (21411 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@fd9726] (21414 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 ] (21415 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] (21415 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(e85099f8834ada77ee249e64ccf009a9@192.168.0.145:16381813) : returning null] (21416 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (21416 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (21418 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:664][TestBase.java:627][ServletTimerTest.java:137][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (21418 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK4ec65bea35bba0a522a981925ca8a651] (21419 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk4ec65bea35bba0a522a981925ca8a651] (21419 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK4ec65bea35bba0a522a981925ca8a651] (21420 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (21420 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: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 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: ServletTimer Method-Name: testScheduledExecutionTime001 Content-Length: 0 ] (21421 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: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 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: ServletTimer Method-Name: testScheduledExecutionTime001 Content-Length: 0 ] (21422 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (21422 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK4ec65bea35bba0a522a981925ca8a651] (21423 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@73d3b5b1 branchID = z9hG4bK4ec65bea35bba0a522a981925ca8a651 isClient = true] (21423 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:664][TestBase.java:627][ServletTimerTest.java:137][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (21424 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 tickCount 64 currentTickCount = -1] (21424 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:664][TestBase.java:627][ServletTimerTest.java:137][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (21425 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: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 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: ServletTimer Method-Name: testScheduledExecutionTime001 Content-Length: 0 ] (21425 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (21426 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} ] (21426 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (21427 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (21429 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (21429 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (21430 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (21430 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (21431 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (21431 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="1223302285819" isSender="true" transactionId="z9hg4bk4ec65bea35bba0a522a981925ca8a651" callId="e85099f8834ada77ee249e64ccf009a9@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: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 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: ServletTimer Method-Name: testScheduledExecutionTime001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (21431 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (21431 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (21934 ms) [Timer-18] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:1015][SIPTransaction.java:644][SIPClientTransaction.java:268][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (21935 ms) [Timer-18] 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: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 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: ServletTimer Method-Name: testScheduledExecutionTime001 Content-Length: 0 ] (21935 ms) [Timer-18] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (21936 ms) [Timer-18] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (21936 ms) [Timer-18] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (21937 ms) [Timer-18] 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="1223302286327" isSender="true" transactionId="z9hg4bk4ec65bea35bba0a522a981925ca8a651" callId="e85099f8834ada77ee249e64ccf009a9@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: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 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: ServletTimer Method-Name: testScheduledExecutionTime001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (21937 ms) [Timer-18] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (21938 ms) [Timer-18] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (22130 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (22130 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 311] (22130 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (22130 ms) [Thread-72] 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=2huchr Content-Length: 0 CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: Alice <sip:alice@192.168.0.145:5071>;tag=16381813 ] (22131 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 311] (22131 ms) [Thread-73] 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=2huchr Content-Length: 0 CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: Alice <sip:alice@192.168.0.145:5071>;tag=16381813 ] (22132 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22132 ms) [Thread-72] 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]] (22133 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (22133 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (22133 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22133 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (22134 ms) [Thread-73] 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]] (22134 ms) [Thread-72] 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="1223302286528" isSender="false" transactionId="z9hg4bk4ec65bea35bba0a522a981925ca8a651" callId="e85099f8834ada77ee249e64ccf009a9@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=2huchr CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (22134 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (22134 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (22135 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk4ec65bea35bba0a522a981925ca8a651] (22136 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=2huchr CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 Content-Length: 0 ] (22136 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 to gov.nist.javax.sip.DialogFilter@57457b] (22136 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (22136 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (22136 ms) [Thread-72] 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=2huchr CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 Content-Length: 0 ] (22136 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22137 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@c519e2]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1this.sipListener = org.cafesip.sipunit.SipStack@ccbab7sipEvent.source = gov.nist.javax.sip.SipProviderImpl@c519e2] (22137 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (22137 ms) [Thread-72] 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]] (22137 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@92a78b] (22137 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 branchID = z9hG4bK4ec65bea35bba0a522a981925ca8a651 isClient = true] (22137 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@92a78bnevents 1] (22138 ms) [Thread-72] 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]] (22138 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@c519e2]source = gov.nist.javax.sip.SipProviderImpl@c519e2] (22138 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 tickCount 10 currentTickCount = 63] (22138 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (22139 ms) [Thread-72] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22139 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (22139 ms) [Thread-72] 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]] (22139 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22139 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (22139 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (22140 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]] (22140 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (22140 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (22140 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (22140 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (22141 ms) [Thread-73] 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="1223302286535" isSender="false" transactionId="z9hg4bk4ec65bea35bba0a522a981925ca8a651" callId="e85099f8834ada77ee249e64ccf009a9@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=2huchr CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (22141 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (22141 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (22142 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk4ec65bea35bba0a522a981925ca8a651] (22142 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=2huchr CSeq: 1 MESSAGE Call-ID: e85099f8834ada77ee249e64ccf009a9@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4ec65bea35bba0a522a981925ca8a651 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=16381813 Content-Length: 0 ] (22143 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1 to gov.nist.javax.sip.DialogFilter@d0bc85] (22143 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Completed Transaction] (22143 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (22143 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.nonInviteClientTransaction(SIPClientTransaction.java:676) [ Not sending response to TU! Completed Transaction] (22143 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22144 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPClientTransaction.java:679][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (22144 ms) [Thread-73] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@73d3b5b1] (22144 ms) [Thread-73] 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]] (23141 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (23141 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (23143 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (24143 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (24143 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (24145 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]