Created
June 27, 2019 11:11
-
-
Save phildunks/8eba657aec5ff8dea97b3459980e1bdc to your computer and use it in GitHub Desktop.
Inconsistency with INFO event handler.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| ############################################################################################### | |
| This is call from sipp custom script, emulating a MSML conference entry procedure from our application server.. | |
| Followed by an actual conference entry procedure from our real application server. | |
| The first call completes successfully. | |
| The second call does not. | |
| Strangely, in this call the INFO event handler in our javascript is not called when an INFO is received. | |
| ############################################################################################### | |
| 2019-06-27 10:15:02.512136 Starting drachtio version v0.8.2-1-ga65722fcb | |
| 2019-06-27 10:15:02.512236 Logging threshold: 5 | |
| 2019-06-27 10:15:02.512295 DrachtioController::run: Main thread id: 140631196501824 | |
| 2019-06-27 10:15:02.512336 DrachtioController::run listening for applications on tcp port 9022 and tls port 0 | |
| 2019-06-27 10:15:02.515260 ClientController::ClientController done setting tls options: | |
| 2019-06-27 10:15:02.515398 Client controller thread id: 140631196501824 | |
| 2019-06-27 10:15:02.515658 ClientController::start_accept_tcp | |
| 2019-06-27 10:15:02.515958 Prometheus support disabled | |
| 2019-06-27 10:15:02.516200 DrachtioController::run: starting sip stack on local address sip:*;transport=udp,tcp (external address: 192.168.47.161) | |
| 2019-06-27 10:15:02.516704 SipTransport::getBindableContactUri: sip:192.168.47.161;transport=udp,tcp;maddr=* | |
| 2019-06-27 10:15:02.517082 nta.c:968 nta_agent_create() nta_agent_create: initialized hash tables | |
| 2019-06-27 10:15:02.517324 tport.c:516 tport_tcreate() tport_create(): 0x55d8ce0e5aa0 | |
| 2019-06-27 10:15:02.517562 nta.c:2382 agent_create_master_transport() nta: master transport created | |
| 2019-06-27 10:15:02.517788 tport.c:1643 tport_bind_server() tport_bind_server(0x55d8ce0e5aa0) to */*:5060 | |
| 2019-06-27 10:15:02.518116 tport.c:1713 tport_bind_server() tport_bind_server(0x55d8ce0e5aa0): calling tport_listen for udp | |
| 2019-06-27 10:15:02.518358 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x55d8ce0e5aa0): new primary tport 0x55d8ce0e55a0 | |
| 2019-06-27 10:15:02.521678 tport.c:769 tport_listen() tport_listen(0x55d8ce0e55a0): listening at udp/172.17.0.2:5060 | |
| 2019-06-27 10:15:02.521738 tport.c:1713 tport_bind_server() tport_bind_server(0x55d8ce0e5aa0): calling tport_listen for tcp | |
| 2019-06-27 10:15:02.521782 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x55d8ce0e5aa0): new primary tport 0x55d8ce0e5d80 | |
| 2019-06-27 10:15:02.521852 tport.c:769 tport_listen() tport_listen(0x55d8ce0e5d80): listening at tcp/172.17.0.2:5060 | |
| 2019-06-27 10:15:02.521896 tport.c:1713 tport_bind_server() tport_bind_server(0x55d8ce0e5aa0): calling tport_listen for udp | |
| 2019-06-27 10:15:02.521940 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x55d8ce0e5aa0): new primary tport 0x55d8ce0e5ff0 | |
| 2019-06-27 10:15:02.522041 tport.c:769 tport_listen() tport_listen(0x55d8ce0e5ff0): listening at udp/127.0.0.1:5060 | |
| 2019-06-27 10:15:02.522086 tport.c:1713 tport_bind_server() tport_bind_server(0x55d8ce0e5aa0): calling tport_listen for tcp | |
| 2019-06-27 10:15:02.522129 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x55d8ce0e5aa0): new primary tport 0x55d8ce0e6b40 | |
| 2019-06-27 10:15:02.522191 tport.c:769 tport_listen() tport_listen(0x55d8ce0e6b40): listening at tcp/127.0.0.1:5060 | |
| 2019-06-27 10:15:02.522236 nta.c:2341 nta_agent_add_tport() nta: bound to (192.168.47.161:5060;transport=*;maddr=*) | |
| 2019-06-27 10:15:02.522283 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 192.168.47.161 (*) | |
| 2019-06-27 10:15:02.522354 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 192.168.47.161 (*) | |
| 2019-06-27 10:15:02.522403 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 192.168.47.161 (*) | |
| 2019-06-27 10:15:02.522448 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 192.168.47.161 (*) | |
| 2019-06-27 10:15:02.522507 nta.c:2350 nta_agent_add_tport() nta: Via fields initialized | |
| 2019-06-27 10:15:02.522616 nta.c:2358 nta_agent_add_tport() nta: Contact header created | |
| 2019-06-27 10:15:02.522660 nta.c:975 nta_agent_create() nta_agent_create: initialized transports | |
| 2019-06-27 10:15:02.522711 nta.c:981 nta_agent_create() nta_agent_create: initialized random identifiers | |
| 2019-06-27 10:15:02.522753 nta.c:987 nta_agent_create() nta_agent_create: initialized timer | |
| 2019-06-27 10:15:02.522948 nta.c:997 nta_agent_create() nta_agent_create: initialized resolver | |
| 2019-06-27 10:15:02.525315 Client controller thread id: 140631092737792 | |
| 2019-06-27 10:15:02.525376 ClientController::threadFunc - ClientController: io_context run loop started (or restarted) | |
| 2019-06-27 10:15:02.526533 SipTransport::addTransports - creating transport: 0x55d8ce0e55a0: udp/172.17.0.2:5060 | |
| 2019-06-27 10:15:02.528501 SipTransport::addTransports - creating transport: 0x55d8ce0e5d80: tcp/172.17.0.2:5060 | |
| 2019-06-27 10:15:02.530413 SipTransport::addTransports - creating transport: 0x55d8ce0e5ff0: udp/127.0.0.1:5060 | |
| 2019-06-27 10:15:02.532289 SipTransport::addTransports - creating transport: 0x55d8ce0e6b40: tcp/127.0.0.1:5060 | |
| 2019-06-27 10:15:02.536705 SipTransport::logTransports - there are : 4 transports | |
| 2019-06-27 10:15:02.537056 SipTransport::logTransports - tcp/127.0.0.1:5060 (sip:*;transport=udp,tcp, external-ip: 192.168.47.161, local-net: ) | |
| 2019-06-27 10:15:02.537310 SipTransport::logTransports - tcp/172.17.0.2:5060 (sip:*;transport=udp,tcp, external-ip: 192.168.47.161, local-net: ) | |
| 2019-06-27 10:15:02.537412 SipTransport::logTransports - udp/127.0.0.1:5060 (sip:*;transport=udp,tcp, external-ip: 192.168.47.161, local-net: ), mtu size: 1300 | |
| 2019-06-27 10:15:02.537468 SipTransport::logTransports - udp/172.17.0.2:5060 (sip:*;transport=udp,tcp, external-ip: 192.168.47.161, local-net: ), mtu size: 1300 | |
| 2019-06-27 10:15:02.537786 DrachtioController::run - sip timers: T1: 500ms, T2: 4000ms, T4: 5000ms, T1X64: 32000ms | |
| 2019-06-27 10:15:02.537901 Starting sofia event loop in main thread: 140631196501824 | |
| 2019-06-27 10:15:18.541475 ClientController::accept_handler_tcp - got connection | |
| 2019-06-27 10:15:18.541732 Client::start - Received connection from client at 172.17.0.1:43218 | |
| 2019-06-27 10:15:18.541980 ClientController::join - Added client, count of connected clients is now: 1 | |
| 2019-06-27 10:15:18.542204 ClientController::start_accept_tcp | |
| 2019-06-27 10:15:18.545833 Client::read_handler read: 8d2d63ca-6421-4cf5-a261-f636a8cdeb0e|authenticate|cymru| | |
| 2019-06-27 10:15:18.545967 Client::processAuthentication - added tags | |
| 2019-06-27 10:15:18.546014 Client::processAuthentication - validating secret cymru | |
| 2019-06-27 10:15:18.546143 Client::processAuthentication - secret validated successfully: cymru | |
| 2019-06-27 10:15:18.546184 Sending response: 201#1ab3f5fb-61a1-4046-8ffe-cae0f8324378|response|8d2d63ca-6421-4cf5-a261-f636a8cdeb0e|OK|tcp/192.168.47.161:5060,tcp/192.168.47.161:5060,udp/192.168.47.161:5060,udp/192.168.47.161:5060|v0.8.2-1-ga65722fcb | |
| 2019-06-27 10:15:18.546335 Client::write_handler - wrote 205 bytes: system:0 | |
| 2019-06-27 10:15:18.550963 Client::read_handler read: 875a52fa-9163-49f9-8676-a4b4471c64ae|route|invite | |
| 2019-06-27 10:15:18.551087 Added client for invite requests | |
| 2019-06-27 10:15:18.551158 Sending response: 85#b329bf08-3bea-4a7a-aa51-00c8ef6e5551|response|875a52fa-9163-49f9-8676-a4b4471c64ae|OK | |
| 2019-06-27 10:15:18.551312 Client::write_handler - wrote 88 bytes: system:0 | |
| 2019-06-27 10:15:32.094630 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:32.094804 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:32.094892 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0eb9d0 from (udp/172.17.0.2:5060) has 479 bytes, veclen = 1 | |
| 2019-06-27 10:15:32.095217 recv 479 bytes from udp/[172.17.0.1]:60980 at 10:15:32.094967: | |
| INVITE sip:12345678@127.0.0.1:5060 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-0 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060> | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 1 INVITE | |
| Contact: sip:sipp@192.168.47.161:5061 | |
| Max-Forwards: 70 | |
| Subject: Drachtio Test | |
| Content-Type: application/sdp | |
| Content-Length: 98 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=MM2 Conferencing Media Leg | |
| t=0 0 | |
| 2019-06-27 10:15:32.095330 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0eb9d0 (479 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:32.095396 nta.c:3028 agent_recv_request() nta: received INVITE sip:12345678@127.0.0.1:5060 SIP/2.0 (CSeq 1) | |
| 2019-06-27 10:15:32.095515 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:15:32.095595 nta.c:3243 agent_recv_request() nta: INVITE (1) to message callback | |
| 2019-06-27 10:15:32.095705 processMessageStatelessly - incoming message with call-id 1-45583@192.168.47.161 does not match an existing call leg, processed in thread 140631196501824 | |
| 2019-06-27 10:15:32.095820 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:60980 | |
| 2019-06-27 10:15:32.095918 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:32.096138 tport.c:3531 tport_send_msg() tport_vsend returned 273 | |
| 2019-06-27 10:15:32.096322 send 273 bytes to udp/[172.17.0.1]:60980 at 10:15:32.096000: | |
| SIP/2.0 100 Trying | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-0;received=172.17.0.1;rport=60980 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060> | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 1 INVITE | |
| Content-Length: 0 | |
| 2019-06-27 10:15:32.096411 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 | |
| 2019-06-27 10:15:32.096525 ClientController::route_request_outside_dialog - Selected client at offset 0 | |
| 2019-06-27 10:15:32.096693 PendingRequestController::add - tport: 0x55d8ce0e55a0, Call-ID: 1-45583@192.168.47.161, transactionId ee4c2002-3055-48e7-a2ce-0bf3007c71d2 | |
| 2019-06-27 10:15:32.096779 pending-request: Adding entry to go off in 64000ms | |
| 2019-06-27 10:15:32.096854 pending-request: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:15:32.096969 ClientController::addNetTransaction: transactionId ee4c2002-3055-48e7-a2ce-0bf3007c71d2; size: 1 | |
| 2019-06-27 10:15:32.097382 Client::write_handler - wrote 644 bytes: system:0 | |
| 2019-06-27 10:15:32.097493 No connected clients found to handle incoming cdr:attempt request | |
| 2019-06-27 10:15:32.109025 Client::read_handler read: 682602f9-d864-487d-bc24-8de68da942e3|sip|| | |
| INVITE sip:1234@192.168.47.161:5063 SIP/2.0 | |
| Content-Length: 98 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=MM2 Conferencing Media Leg | |
| t=0 0 | |
| 2019-06-27 10:15:32.109246 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:32.109320 Client::processMessage - request id 682602f9-d864-487d-bc24-8de68da942e3, request type: sip transaction id: , dialog id: | |
| 2019-06-27 10:15:32.109513 Client::processMessage - sending a request outside of a dialog | |
| 2019-06-27 10:15:32.109608 ClientController::addAppTransaction: transactionId 5d70795f-c920-4906-9983-1374ad1974d3; size: 1 | |
| 2019-06-27 10:15:32.109679 ClientController::addApiRequest: clientMsgId 682602f9-d864-487d-bc24-8de68da942e3; size: 1 | |
| 2019-06-27 10:15:32.109945 DrachtioController::findTportForSubscription: no transport found for 1234@192.168.47.161 | |
| 2019-06-27 10:15:32.118246 SipTransport::findAppropriateTransport: searching for a transport to reach udp/sip:1234@192.168.47.161:5063 | |
| 2019-06-27 10:15:32.118329 SipTransport::findAppropriateTransport - after filtering for transport we have 4 candidates | |
| 2019-06-27 10:15:32.118433 SipTransport::findAppropriateTransport - after filtering for protocol we have 2 candidates | |
| 2019-06-27 10:15:32.120351 SipTransport::findAppropriateTransport: - returning the best match 0x55d8ce0e55a0: udp/172.17.0.2:5060 | |
| 2019-06-27 10:15:32.120410 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:15:32.120499 SipDialogController::doSendRequestOutsideDialog selected transport 0x55d8ce0e55a0udp/172.17.0.2:5060 | |
| 2019-06-27 10:15:32.120866 makeTags - using external IP as replacement for 'localhost': 192.168.47.161 | |
| 2019-06-27 10:15:32.120982 SipDialogController::doSendRequestOutsideDialog - from: <sip:192.168.47.161:5060> | |
| 2019-06-27 10:15:32.121025 SipDialogController::doSendRequestOutsideDialog - to: sip:1234@192.168.47.161:5063 | |
| 2019-06-27 10:15:32.121094 SipDialogController::doSendRequestOutsideDialog - contact: <sip:192.168.47.161:5060> | |
| 2019-06-27 10:15:32.121136 SipDialogController::doSendRequestOutsideDialog - automatically detecting content-type as application/sdp | |
| 2019-06-27 10:15:32.121177 isLocalSipUri: checking to see if this is one of mine: sip:1234@192.168.47.161:5063 | |
| 2019-06-27 10:15:32.121390 nta.c:4566 nta_leg_tcreate() nta_leg_tcreate(0x55d8ce0e9b00) | |
| 2019-06-27 10:15:32.121505 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:15:32.121569 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = */192.168.47.161:5063 | |
| 2019-06-27 10:15:32.124219 tport.c:4085 tport_resolve() tport_resolve addrinfo = 192.168.47.161:5063 | |
| 2019-06-27 10:15:32.124763 tport.c:3531 tport_send_msg() tport_vsend returned 473 | |
| ############################################################################################### | |
| First we set up B2B with sipp UAS (emulating a Freeswitch where we will process media). | |
| ############################################################################################### | |
| 2019-06-27 10:15:32.125054 send 473 bytes to udp/[192.168.47.161]:5063 at 10:15:32.124516: | |
| INVITE sip:1234@192.168.47.161:5063 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKUNe3H48y2pK0S | |
| Max-Forwards: 70 | |
| From: <sip:192.168.47.161:5060>;tag=U5m5NZev12QBp | |
| To: <sip:1234@192.168.47.161:5063> | |
| Call-ID: 563f7afb-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261474 INVITE | |
| Contact: <sip:192.168.47.161:5060> | |
| Content-Type: application/sdp | |
| Content-Length: 98 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=MM2 Conferencing Media Leg | |
| t=0 0 | |
| 2019-06-27 10:15:32.125152 nta.c:8470 outgoing_send() nta: sent INVITE (6261474) to */192.168.47.161:5063 | |
| 2019-06-27 10:15:32.125240 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce0ee810 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:15:32.125302 nta.c:1411 set_timeout() nta: timer set to 32000 ms | |
| 2019-06-27 10:15:32.125364 nta.c:1409 set_timeout() nta: timer shortened to 1000 ms | |
| 2019-06-27 10:15:32.125484 SipDialog::SipDialog - creating dialog for outbound INVITE sent from udp/172.17.0.2:5060 to 192.168.47.161:5063 | |
| 2019-06-27 10:15:32.125535 SipDialogController::addOutgoingInviteTransaction: adding leg 0x55d8ce0e9b00 | |
| 2019-06-27 10:15:32.125611 No connected clients found to handle incoming cdr:attempt request | |
| 2019-06-27 10:15:32.125698 ClientController::removeApiRequest: clientMsgId 682602f9-d864-487d-bc24-8de68da942e3; size: 0 | |
| 2019-06-27 10:15:32.127919 Client::write_handler - wrote 664 bytes: system:0 | |
| 2019-06-27 10:15:32.128253 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:32.129018 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:32.129792 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0f0d70 from (udp/172.17.0.2:5060) has 336 bytes, veclen = 1 | |
| 2019-06-27 10:15:32.130086 recv 336 bytes from udp/[192.168.47.161]:5063 at 10:15:32.129938: | |
| SIP/2.0 180 Ringing | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKUNe3H48y2pK0S | |
| From: <sip:192.168.47.161:5060>;tag=U5m5NZev12QBp | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0115 | |
| Call-ID: 563f7afb-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261474 INVITE | |
| Contact: <sip:192.168.47.161:5063;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:15:32.130160 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0f0d70 (336 bytes) from udp/192.168.47.161:5060 next=(nil) | |
| 2019-06-27 10:15:32.130217 nta.c:3448 agent_recv_response() nta: received 180 Ringing for INVITE (6261474) | |
| 2019-06-27 10:15:32.130259 nta.c:3515 agent_recv_response() nta: 180 Ringing is going to a transaction | |
| 2019-06-27 10:15:32.130313 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 8.739 ms | |
| 2019-06-27 10:15:32.130396 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0ee810 by 0x55d8ce0ef220 with 0x55d8ce0f0d70 (preliminary) | |
| 2019-06-27 10:15:32.130455 SipDialogController::processResponseOutsideDialog | |
| 2019-06-27 10:15:32.130678 Client::write_handler - wrote 532 bytes: system:0 | |
| 2019-06-27 10:15:32.130818 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:32.132293 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:32.132899 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0ed060 from (udp/172.17.0.2:5060) has 505 bytes, veclen = 1 | |
| 2019-06-27 10:15:32.133821 recv 505 bytes from udp/[192.168.47.161]:5063 at 10:15:32.133016: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKUNe3H48y2pK0S | |
| From: <sip:192.168.47.161:5060>;tag=U5m5NZev12QBp | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0115 | |
| Call-ID: 563f7afb-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261474 INVITE | |
| Contact: <sip:192.168.47.161:5063;transport=UDP> | |
| Content-Type: application/sdp | |
| Content-Length: 139 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6001 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:15:32.133921 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0ed060 (505 bytes) from udp/192.168.47.161:5060 next=(nil) | |
| 2019-06-27 10:15:32.133966 nta.c:3448 agent_recv_response() nta: received 200 OK for INVITE (6261474) | |
| 2019-06-27 10:15:32.134001 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:15:32.134043 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0ee810 by 0x55d8ce0ef220 with 0x55d8ce0ed060 | |
| 2019-06-27 10:15:32.134162 SipDialogController::processResponseOutsideDialog | |
| 2019-06-27 10:15:32.134242 SipDialogController::processResponse - adding dialog id: 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:32.134991 ClientController::addDialogForTransaction - added dialog (uac), now tracking: 1 dialogs and 1 app transactions | |
| 2019-06-27 10:15:32.135047 ClientController::addDialogForTransaction - transaction id 5d70795f-c920-4906-9983-1374ad1974d3 has associated dialog 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:32.135121 timerD: Adding entry to go off in 32500ms | |
| 2019-06-27 10:15:32.135169 timerD: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:15:32.135229 TimerDHandler::addInvite 0x55d8ce0ef220, 563f7afb-1367-1238-98a7-0242ac1100026261474 | |
| 2019-06-27 10:15:32.135382 Client::write_handler - wrote 701 bytes: system:0 | |
| 2019-06-27 10:15:32.135534 ClientController::removeAppTransaction: transactionId 5d70795f-c920-4906-9983-1374ad1974d3; size: 0 | |
| 2019-06-27 10:15:32.135654 No connected clients found to handle incoming cdr:start request | |
| 2019-06-27 10:15:32.176163 Client::read_handler read: 59163dab-7303-4d26-b085-f34d2e12cc50|sip||563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| ACK sip:1234@192.168.47.161:5063 SIP/2.0 | |
| Content-Length: 0 | |
| 2019-06-27 10:15:32.176349 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:32.176535 Client::processMessage - request id 59163dab-7303-4d26-b085-f34d2e12cc50, request type: sip transaction id: , dialog id: 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:32.176662 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:15:32.176764 ClientController::addApiRequest: clientMsgId 59163dab-7303-4d26-b085-f34d2e12cc50; size: 1 | |
| 2019-06-27 10:15:32.176957 SipDialogController::doSendRequestInsideDialog dialog id: 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:32.177667 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:192.168.47.161:5063;transport=UDP | |
| 2019-06-27 10:15:32.178244 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:15:32.178406 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/192.168.47.161:5063 | |
| 2019-06-27 10:15:32.178497 tport.c:4085 tport_resolve() tport_resolve addrinfo = 192.168.47.161:5063 | |
| 2019-06-27 10:15:32.178699 tport.c:3531 tport_send_msg() tport_vsend returned 331 | |
| 2019-06-27 10:15:32.179690 send 331 bytes to udp/[192.168.47.161]:5063 at 10:15:32.178586: | |
| ACK sip:192.168.47.161:5063;transport=UDP SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKvy7UKZS2ZZ9jN | |
| Max-Forwards: 70 | |
| From: <sip:192.168.47.161:5060>;tag=U5m5NZev12QBp | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0115 | |
| Call-ID: 563f7afb-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261474 ACK | |
| Content-Length: 0 | |
| 2019-06-27 10:15:32.179890 nta.c:8470 outgoing_send() nta: sent ACK (6261474) to UDP/192.168.47.161:5063 | |
| 2019-06-27 10:15:32.180495 TimerDHandler::addAck 0x55d8ce0ecc40, 563f7afb-1367-1238-98a7-0242ac1100026261474 | |
| 2019-06-27 10:15:32.180733 SipDialogController::doSendRequestInsideDialog - clearing IIP that we generated as uac | |
| 2019-06-27 10:15:32.181018 SipDialogController::clearIIP: clearing leg 0x55d8ce0e9b00, irq: 0, orq: 0x55d8ce0ef220, rel: 0 | |
| 2019-06-27 10:15:32.181234 SipDialogController::clearIIP: clearing m_mapOrq2IIP for leg 0x55d8ce0e9b00 | |
| 2019-06-27 10:15:32.181735 ClientController::removeApiRequest: clientMsgId 59163dab-7303-4d26-b085-f34d2e12cc50; size: 0 | |
| 2019-06-27 10:15:32.182772 Client::write_handler - wrote 522 bytes: system:0 | |
| 2019-06-27 10:15:32.188614 Client::read_handler read: b59fcd3e-6424-4b55-8310-495a57e61761|sip|ee4c2002-3055-48e7-a2ce-0bf3007c71d2| | |
| SIP/2.0 200 OK | |
| Call-ID: 1-45583@192.168.47.161 | |
| cseq: 1 INVITE | |
| from: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| to: sut <sip:12345678@127.0.0.1:5060> | |
| Content-Length: 139 | |
| user-agent: drachtio/iechyd-da | |
| X-Linked-UUID: 1e2587c | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6001 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:15:32.189011 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:32.189081 Client::processMessage - request id b59fcd3e-6424-4b55-8310-495a57e61761, request type: sip transaction id: ee4c2002-3055-48e7-a2ce-0bf3007c71d2, dialog id: | |
| 2019-06-27 10:15:32.189189 ClientController::addApiRequest: clientMsgId b59fcd3e-6424-4b55-8310-495a57e61761; size: 1 | |
| 2019-06-27 10:15:32.189319 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:15:32.189536 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId ee4c2002-3055-48e7-a2ce-0bf3007c71d2 | |
| 2019-06-27 10:15:32.189881 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - failed to find transactionId ee4c2002-3055-48e7-a2ce-0bf3007c71d2, most likely this is a response to an invite we sent | |
| 2019-06-27 10:15:32.190413 pending-request: removing entry, prior to removal length: 1 | |
| 2019-06-27 10:15:32.190636 pending-request: removed entry, timer not set (queue is empty after removal), length: 0 | |
| 2019-06-27 10:15:32.190754 nta.c:1409 set_timeout() nta: timer shortened to 200 ms | |
| 2019-06-27 10:15:32.190840 nta.c:4566 nta_leg_tcreate() nta_leg_tcreate(0x55d8ce0f3200) | |
| 2019-06-27 10:15:32.190900 DrachtioController::setupLegForIncomingRequest - created leg: 0x55d8ce0f3200, irq: 0x55d8ce0f2cc0, for transactionId: ee4c2002-3055-48e7-a2ce-0bf3007c71d2 | |
| 2019-06-27 10:15:32.191009 SipDialog::SipDialog - (UAS) detected client behind nat, using 172.17.0.1:60980 as route for requests within this dialog | |
| 2019-06-27 10:15:32.191076 SipDialog::SipDialog - creating dialog for inbound INVITE sent from UDP/172.17.0.2:5060 | |
| 2019-06-27 10:15:32.191164 SipDialogController::addIncomingInviteTransaction: added iip: 0x55d8ce0f1550 with leg 0x55d8ce0f3200, irq: 0x55d8ce0f2cc0, transactionId ee4c2002-3055-48e7-a2ce-0bf3007c71d2, iip size: 1 | |
| 2019-06-27 10:15:32.191238 SipDialogController::doRespondToSipRequest found invite or subscribe in progress 0x55d8ce0f1550 | |
| 2019-06-27 10:15:32.191304 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:15:32.191810 makeTags - Adding well-known header 'Call-ID' with value '1-45583@192.168.47.161' | |
| 2019-06-27 10:15:32.191894 makeTags - Adding well-known header 'cseq' with value '1 INVITE' | |
| 2019-06-27 10:15:32.191969 makeTags - Adding well-known header 'from' with value 'sipp <sip:sipp@192.168.47.161:5061>;tag=1' | |
| 2019-06-27 10:15:32.192041 makeTags - Adding well-known header 'to' with value 'sut <sip:12345678@127.0.0.1:5060>' | |
| 2019-06-27 10:15:32.192126 makeTags - Adding well-known header 'user-agent' with value 'drachtio/iechyd-da' | |
| 2019-06-27 10:15:32.192203 makeTags - custom header: 'X-Linked-UUID', value: 1e2587c | |
| 2019-06-27 10:15:32.192270 Sending 200 response (not reliably) on irq 0x55d8ce0f2cc0 | |
| 2019-06-27 10:15:32.192442 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:60980 | |
| 2019-06-27 10:15:32.192622 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:32.193041 tport.c:3531 tport_send_msg() tport_vsend returned 551 | |
| 2019-06-27 10:15:32.193407 send 551 bytes to udp/[172.17.0.1]:60980 at 10:15:32.192821: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-0;received=172.17.0.1;rport=60980 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 1 INVITE | |
| Contact: <sip:192.168.47.161:5060> | |
| User-Agent: drachtio/iechyd-da | |
| Content-Type: application/sdp | |
| Content-Length: 139 | |
| X-Linked-UUID: 1e2587c | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6001 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:15:32.193556 nta.c:6939 incoming_reply() nta: sent 200 OK for INVITE (1) | |
| 2019-06-27 10:15:32.193802 ClientController::addDialogForTransaction - added dialog (uas), now tracking: 2 dialogs and 1 net transactions | |
| 2019-06-27 10:15:32.193938 ClientController::addDialogForTransaction - transaction id ee4c2002-3055-48e7-a2ce-0bf3007c71d2 has associated dialog 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:32.194565 timerG: Adding entry to go off in 500ms | |
| 2019-06-27 10:15:32.194634 timerG: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:15:32.194713 timerH: Adding entry to go off in 32000ms | |
| 2019-06-27 10:15:32.194882 timerH: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:15:32.195198 ClientController::removeApiRequest: clientMsgId b59fcd3e-6424-4b55-8310-495a57e61761; size: 0 | |
| 2019-06-27 10:15:32.195966 Client::write_handler - wrote 778 bytes: system:0 | |
| 2019-06-27 10:15:32.196086 No connected clients found to handle incoming cdr:start request | |
| 2019-06-27 10:15:32.200371 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:32.201992 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:32.202069 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0f5fb0 from (udp/172.17.0.2:5060) has 358 bytes, veclen = 1 | |
| 2019-06-27 10:15:32.203129 recv 358 bytes from udp/[172.17.0.1]:60980 at 10:15:32.202547: | |
| ACK sip:12345678@127.0.0.1:5060 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-4 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 1 ACK | |
| Contact: sip:sipp@192.168.47.161:5061 | |
| Max-Forwards: 70 | |
| Subject: Drachtio Test | |
| Content-Length: 0 | |
| 2019-06-27 10:15:32.204079 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0f5fb0 (358 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:32.204415 nta.c:3028 agent_recv_request() nta: received ACK sip:12345678@127.0.0.1:5060 SIP/2.0 (CSeq 1) | |
| 2019-06-27 10:15:32.205138 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:15:32.205238 nta.c:3209 agent_recv_request() nta: ACK (1) going to existing leg | |
| 2019-06-27 10:15:32.205314 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:15:32.205398 SipDialogController::processRequestInsideDialog: ACK irq 0x55d8ce0f6930 | |
| 2019-06-27 10:15:32.205472 SipDialogController::clearIIP: clearing leg 0x55d8ce0f3200, irq: 0x55d8ce0f2cc0, orq: 0, rel: 0 | |
| 2019-06-27 10:15:32.205559 SipDialogController::clearIIP: clearing m_mapIrq2IIP for leg 0x55d8ce0f3200 | |
| 2019-06-27 10:15:32.205614 SipDialogController::clearSipTimers for 1-45583@192.168.47.161 | |
| 2019-06-27 10:15:32.205694 timerG: removing entry, prior to removal length: 1 | |
| 2019-06-27 10:15:32.205774 timerG: removed entry, timer not set (queue is empty after removal), length: 0 | |
| 2019-06-27 10:15:32.205821 timerH: removing entry, prior to removal length: 1 | |
| 2019-06-27 10:15:32.205902 timerH: removed entry, timer not set (queue is empty after removal), length: 0 | |
| 2019-06-27 10:15:32.206081 Client::write_handler - wrote 554 bytes: system:0 | |
| 2019-06-27 10:15:32.206177 ClientController::removeNetTransaction: transactionId ee4c2002-3055-48e7-a2ce-0bf3007c71d2; size: 0 | |
| 2019-06-27 10:15:32.206259 ClientController::route_ack_request_inside_dialog - removed incoming invite transaction, map size is now: 0 request | |
| 2019-06-27 10:15:32.206321 nta.c:5892 incoming_free() nta: incoming_free(0x55d8ce0f6930) | |
| ############################################################################################### | |
| B2B set up ok - sipp UAC (our emulated application server) sends an INFO containing MSML | |
| ############################################################################################### | |
| 2019-06-27 10:15:32.206450 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:32.206539 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:32.206696 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0f1de0 from (udp/172.17.0.2:5060) has 1089 bytes, veclen = 1 | |
| 2019-06-27 10:15:32.207069 recv 1089 bytes from udp/[172.17.0.1]:60980 at 10:15:32.206791: | |
| INFO sip:12345678@127.0.0.1:5060 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-5 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060> | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 2 INFO | |
| Contact: sip:sipp@192.168.47.161:5061 | |
| Max-Forwards: 70 | |
| Content-Type: application/msml+xml | |
| Content-Length: 731 | |
| <?xml version='1.0' encoding='US-ASCII'?> | |
| <msml version="1.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="http://convedia.com/msml" xmlns:cvd="http://convedia.com/ext"> | |
| <dialogstart target='conn:BX5XUmm1X8mcK' type='application/moml+xml' > | |
| <play cvd:barge='true' cvd:cleardb='false' > | |
| <audio uri='file://provisioned/bt/MM2/eng/pin_prompt.wav' /> | |
| </play> | |
| <dtmf fdt='20s' idt='10s' edt='10s' cleardb='false' > | |
| <pattern digits='min=1;max=28;rtk=#' format='moml+digits'> | |
| <exit namelist='dtmf.digits dtmf.end'/> | |
| </pattern> | |
| <noinput><exit namelist='dtmf.digits dtmf.end'/></noinput> | |
| <nomatch><exit namelist='dtmf.digits dtmf.end'/></nomatch> | |
| </dtmf> | |
| </dialogstart> | |
| </msml> | |
| 2019-06-27 10:15:32.207174 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0f1de0 (1089 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:32.207264 nta.c:3028 agent_recv_request() nta: received INFO sip:12345678@127.0.0.1:5060 SIP/2.0 (CSeq 2) | |
| 2019-06-27 10:15:32.207325 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:15:32.207416 nta.c:3209 agent_recv_request() nta: INFO (2) going to existing leg | |
| 2019-06-27 10:15:32.207619 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:15:32.207707 SipDialogController::processRequestInsideDialog: INFO irq 0x55d8ce0f53a0 | |
| 2019-06-27 10:15:32.207809 ClientController::addNetTransaction: transactionId a5eb319b-f8db-408b-8ef2-8403a56e922d; size: 1 | |
| 2019-06-27 10:15:32.208118 Client::write_handler - wrote 1290 bytes: system:0 | |
| 2019-06-27 10:15:32.208282 SipDialogController::addIncomingRequestTransaction - adding transactionId a5eb319b-f8db-408b-8ef2-8403a56e922d for irq:0x55d8ce0f53a0 | |
| 2019-06-27 10:15:32.223765 Client::read_handler read: 38dcbe91-c9f2-4cf4-8616-6de8ef567a45|sip|a5eb319b-f8db-408b-8ef2-8403a56e922d| | |
| SIP/2.0 200 OK | |
| Call-ID: 1-45583@192.168.47.161 | |
| cseq: 2 INFO | |
| from: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| to: sut <sip:12345678@127.0.0.1:5060> | |
| Content-Length: 28 | |
| content-type: application/msml+xml | |
| <MSML value='response=200'/> | |
| ############################################################################################### | |
| INFO event handler in our javascript fires, puts content into 200 OK and sets content-type. | |
| ############################################################################################### | |
| 2019-06-27 10:15:32.224028 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:32.224146 Client::processMessage - request id 38dcbe91-c9f2-4cf4-8616-6de8ef567a45, request type: sip transaction id: a5eb319b-f8db-408b-8ef2-8403a56e922d, dialog id: | |
| 2019-06-27 10:15:32.224289 ClientController::addApiRequest: clientMsgId 38dcbe91-c9f2-4cf4-8616-6de8ef567a45; size: 1 | |
| 2019-06-27 10:15:32.224535 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:15:32.224633 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId a5eb319b-f8db-408b-8ef2-8403a56e922d | |
| 2019-06-27 10:15:32.224748 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d8ce0f53a0 | |
| 2019-06-27 10:15:32.224927 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:15:32.225679 makeTags - Adding well-known header 'Call-ID' with value '1-45583@192.168.47.161' | |
| 2019-06-27 10:15:32.225805 makeTags - Adding well-known header 'cseq' with value '2 INFO' | |
| 2019-06-27 10:15:32.225876 makeTags - Adding well-known header 'from' with value 'sipp <sip:sipp@192.168.47.161:5061>;tag=1' | |
| 2019-06-27 10:15:32.225977 makeTags - Adding well-known header 'to' with value 'sut <sip:12345678@127.0.0.1:5060>' | |
| 2019-06-27 10:15:32.226096 makeTags - Adding well-known header 'content-type' with value 'application/msml+xml' | |
| 2019-06-27 10:15:32.226242 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:60980 | |
| 2019-06-27 10:15:32.226406 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:32.226551 tport.c:3531 tport_send_msg() tport_vsend returned 350 | |
| 2019-06-27 10:15:32.226723 send 350 bytes to udp/[172.17.0.1]:60980 at 10:15:32.226472: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-5;received=172.17.0.1;rport=60980 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 2 INFO | |
| Content-Type: application/msml+xml | |
| Content-Length: 28 | |
| <MSML value='response=200'/ | |
| ############################################################################################### | |
| Our javascript pretends it has collected a PIN, and sends MSML back in an INFO. | |
| ############################################################################################### | |
| 2019-06-27 10:15:32.226811 nta.c:6939 incoming_reply() nta: sent 200 OK for INFO (2) | |
| 2019-06-27 10:15:32.226890 SipDialogController::doRespondToSipRequest destroying irq 0x55d8ce0f53a0 | |
| 2019-06-27 10:15:32.226981 ClientController::removeApiRequest: clientMsgId 38dcbe91-c9f2-4cf4-8616-6de8ef567a45; size: 0 | |
| 2019-06-27 10:15:32.227226 Client::write_handler - wrote 541 bytes: system:0 | |
| 2019-06-27 10:15:32.227310 ClientController::removeNetTransaction: transactionId a5eb319b-f8db-408b-8ef2-8403a56e922d; size: 0 | |
| 2019-06-27 10:15:32.237268 Client::read_handler read: 17b25209-9920-4427-99bd-5a7baae6ed36|sip||1-45583@192.168.47.161;from-tag=1 | |
| INFO sip:placeholder SIP/2.0 | |
| Content-Type: application/msml+xml | |
| Content-Length: 230 | |
| <?xml version="1.0"?><msml version="1.1"><event name="msml.dialog.exit" id="conn:NoTagMappingFound/dialog:1561630532215"><name>dtmf.end</name><value>dtmf.match</value><name>dtmf.digits</name><value>11111111#</value></event></msml> | |
| 2019-06-27 10:15:32.237414 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:32.237456 Client::processMessage - request id 17b25209-9920-4427-99bd-5a7baae6ed36, request type: sip transaction id: , dialog id: 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:32.237489 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:15:32.237545 ClientController::addAppTransaction: transactionId 0931004b-b133-49ab-8cfb-41bc381ab8b7; size: 1 | |
| 2019-06-27 10:15:32.237621 ClientController::addApiRequest: clientMsgId 17b25209-9920-4427-99bd-5a7baae6ed36; size: 1 | |
| 2019-06-27 10:15:32.237722 SipDialogController::doSendRequestInsideDialog dialog id: 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:32.238762 makeTags - Adding well-known header 'Content-Type' with value 'application/msml+xml' | |
| 2019-06-27 10:15:32.239045 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:sipp@192.168.47.161:5061 | |
| 2019-06-27 10:15:32.239093 DrachtioController::findTportForSubscription: no transport found for sipp@192.168.47.161 | |
| 2019-06-27 10:15:32.239137 SipDialogController::doSendRequestInsideDialog - sending request to nat'ed address using route sip:172.17.0.1:60980 | |
| 2019-06-27 10:15:32.239209 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:15:32.239292 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = udp/172.17.0.1:60980 | |
| 2019-06-27 10:15:32.239344 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:32.239514 tport.c:3531 tport_send_msg() tport_vsend returned 570 | |
| 2019-06-27 10:15:32.239749 send 570 bytes to udp/[172.17.0.1]:60980 at 10:15:32.239398: | |
| INFO sip:sipp@192.168.47.161:5061 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKX70mNta6v8Z5g | |
| Max-Forwards: 70 | |
| From: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| To: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 2 INFO | |
| Content-Type: application/msml+xml | |
| Content-Length: 230 | |
| <?xml version="1.0"?><msml version="1.1"><event name="msml.dialog.exit" id="conn:NoTagMappingFound/dialog:1561630532215"><name>dtmf.end</name><value>dtmf.match</value><name>dtmf.digits</name><value>11111111#</value></event></msml | |
| 2019-06-27 10:15:32.239848 nta.c:8470 outgoing_send() nta: sent INFO (2) to udp/172.17.0.1:60980 | |
| 2019-06-27 10:15:32.239912 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce0f5b50 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:15:32.239987 SipDialogController::doSendRequestInsideDialog - created orq 0x55d8ce0f5540 sending INFO to sip:sipp@192.168.47.161:5061 | |
| 2019-06-27 10:15:32.240196 SipDialogController::addRIP adding orq 0x55d8ce0f5540 | |
| 2019-06-27 10:15:32.240302 ClientController::removeApiRequest: clientMsgId 17b25209-9920-4427-99bd-5a7baae6ed36; size: 0 | |
| 2019-06-27 10:15:32.240558 Client::write_handler - wrote 761 bytes: system:0 | |
| 2019-06-27 10:15:32.246686 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:32.247055 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:32.247195 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0fb130 from (udp/172.17.0.2:5060) has 307 bytes, veclen = 1 | |
| 2019-06-27 10:15:32.247470 recv 307 bytes from udp/[172.17.0.1]:60980 at 10:15:32.247291: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKX70mNta6v8Z5g | |
| From: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| To: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 2 INFO | |
| Contact: <sip:192.168.47.161:5061;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:15:32.248950 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0fb130 (307 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:32.249249 nta.c:3448 agent_recv_response() nta: received 200 OK for INFO (2) | |
| 2019-06-27 10:15:32.249335 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:15:32.249466 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 10.165 ms | |
| 2019-06-27 10:15:32.249578 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0f5b50 by 0x55d8ce0f5540 with 0x55d8ce0fb130 | |
| 2019-06-27 10:15:32.250593 SipDialogController::processResponseInsideDialog: | |
| 2019-06-27 10:15:32.250832 SipDialogController::findRIPByOrq orq 0x55d8ce0f5540 | |
| 2019-06-27 10:15:32.250945 SipDialogController::processResponseInsideDialog: found request for response | |
| 2019-06-27 10:15:32.251589 Client::write_handler - wrote 474 bytes: system:0 | |
| 2019-06-27 10:15:32.251903 ClientController::removeAppTransaction: transactionId 0931004b-b133-49ab-8cfb-41bc381ab8b7; size: 0 | |
| 2019-06-27 10:15:32.251963 SipDialogController::clearRIP clearing orq 0x55d8ce0f5540 | |
| 2019-06-27 10:15:32.393185 nta.c:1357 agent_timer() nta: timer set next to 4801 ms | |
| 2019-06-27 10:15:32.541219 DrachtioController::processWatchdogTimer | |
| 2019-06-27 10:15:32.541357 size of hash table for server-side transactions 31 | |
| 2019-06-27 10:15:32.541402 size of hash table for client-side transactions 31 | |
| 2019-06-27 10:15:32.541449 size of hash table for dialogs 31 | |
| 2019-06-27 10:15:32.541523 number of server-side transactions in the hash table 2 | |
| 2019-06-27 10:15:32.541610 number of client-side transactions in the hash table 3 | |
| 2019-06-27 10:15:32.541656 number of dialogs in the hash table 2 | |
| 2019-06-27 10:15:32.541757 number of sip messages received 6 | |
| 2019-06-27 10:15:32.541832 number of sip messages sent 6 | |
| 2019-06-27 10:15:32.541878 number of sip requests received 3 | |
| 2019-06-27 10:15:32.541962 number of sip requests sent 3 | |
| 2019-06-27 10:15:32.542005 number of bad sip messages received 0 | |
| 2019-06-27 10:15:32.542071 number of bad sip requests received 0 | |
| 2019-06-27 10:15:32.542116 number of bad sip requests dropped 0 | |
| 2019-06-27 10:15:32.542204 number of bad sip reponses dropped 0 | |
| 2019-06-27 10:15:32.542253 number of client transactions created 3 | |
| 2019-06-27 10:15:32.542311 number of server transactions created 3 | |
| 2019-06-27 10:15:32.542387 number of in-dialog server transactions created 2 | |
| 2019-06-27 10:15:32.542462 number of server transactions that have received ack 0 | |
| 2019-06-27 10:15:32.542511 number of server transactions that have received cancel 0 | |
| 2019-06-27 10:15:32.542598 number of requests that were processed stateless 1 | |
| 2019-06-27 10:15:32.542644 number of requests converted to transactions by message callback 0 | |
| 2019-06-27 10:15:32.542717 number of responses without matching request 0 | |
| 2019-06-27 10:15:32.542794 number of successful responses missing INVITE client transaction 0 | |
| 2019-06-27 10:15:32.542835 number of requests merged by UAS 0 | |
| 2019-06-27 10:15:32.542863 number of SIP responses sent by stack 3 | |
| 2019-06-27 10:15:32.542896 number of SIP requests retransmitted by stack 0 | |
| 2019-06-27 10:15:32.542942 number of SIP responses retransmitted by stack 0 | |
| 2019-06-27 10:15:32.543015 number of retransmitted SIP requests received by stack 0 | |
| 2019-06-27 10:15:32.543061 number of SIP client transactions that has timeout 0 | |
| 2019-06-27 10:15:32.543099 number of SIP server transactions that has timeout 0 | |
| 2019-06-27 10:15:32.543126 SipDialogController storage counts | |
| 2019-06-27 10:15:32.543154 ---------------------------------- | |
| 2019-06-27 10:15:32.543181 m_mapIrq2IIP size: 0 | |
| 2019-06-27 10:15:32.543207 m_mapOrq2IIP size: 0 | |
| 2019-06-27 10:15:32.543234 m_mapTransactionId2IIP size: 0 | |
| 2019-06-27 10:15:32.543261 m_mapLeg2Dialog size: 2 | |
| 2019-06-27 10:15:32.543290 m_mapId2Dialog size: 2 | |
| 2019-06-27 10:15:32.543357 m_mapOrq2RIP size: 0 | |
| 2019-06-27 10:15:32.543416 number of outgoing transactions held for timerD: 1 | |
| 2019-06-27 10:15:32.543492 number of outgoing transactions waiting for ACK from app: 0 | |
| 2019-06-27 10:15:32.543549 general queue size: 0 | |
| 2019-06-27 10:15:32.543588 timer A queue size: 0 | |
| 2019-06-27 10:15:32.543653 timer B queue size: 0 | |
| 2019-06-27 10:15:32.543728 timer C queue size: 0 | |
| 2019-06-27 10:15:32.543774 timer D queue size: 1 | |
| 2019-06-27 10:15:32.543860 timer E queue size: 0 | |
| 2019-06-27 10:15:32.543905 timer F queue size: 0 | |
| 2019-06-27 10:15:32.543979 timer G queue size: 0 | |
| 2019-06-27 10:15:32.544062 timer K queue size: 0 | |
| 2019-06-27 10:15:32.544108 ClientController storage counts | |
| 2019-06-27 10:15:32.544183 ---------------------------------- | |
| 2019-06-27 10:15:32.544228 m_clients size: 1 | |
| 2019-06-27 10:15:32.544303 m_services size: 0 | |
| 2019-06-27 10:15:32.544376 m_request_types size: 1 | |
| 2019-06-27 10:15:32.544411 m_map_of_request_type_offsets size: 1 | |
| 2019-06-27 10:15:32.544444 m_mapDialogs size: 2 | |
| 2019-06-27 10:15:32.544517 m_mapNetTransactions size: 0 | |
| 2019-06-27 10:15:32.544604 m_mapAppTransactions size: 0 | |
| 2019-06-27 10:15:32.544660 m_mapApiRequests size: 0 | |
| 2019-06-27 10:15:32.544737 m_mapDialogId2Appname size: 0 | |
| 2019-06-27 10:15:32.544813 PendingRequestController storage counts | |
| 2019-06-27 10:15:32.544858 ---------------------------------- | |
| 2019-06-27 10:15:32.544953 m_mapCallId2Invite size: 0 | |
| 2019-06-27 10:15:32.544994 m_mapTxnId2Invite size: 0 | |
| 2019-06-27 10:15:32.545046 SipProxyController storage counts | |
| 2019-06-27 10:15:32.545109 ---------------------------------- | |
| 2019-06-27 10:15:32.545155 m_mapCallId2Proxy size: 0 | |
| 2019-06-27 10:15:32.545241 m_mapNonce2Challenge size: 0 | |
| 2019-06-27 10:15:32.545287 general queue size: 0 | |
| 2019-06-27 10:15:32.545360 timer A queue size: 0 | |
| 2019-06-27 10:15:32.545443 timer B queue size: 0 | |
| 2019-06-27 10:15:32.545482 timer C queue size: 0 | |
| 2019-06-27 10:15:32.545515 timer D queue size: 0 | |
| 2019-06-27 10:15:32.545590 timer E queue size: 0 | |
| 2019-06-27 10:15:32.545635 timer F queue size: 0 | |
| 2019-06-27 10:15:32.545712 timer G queue size: 0 | |
| 2019-06-27 10:15:32.545772 timer K queue size: 0 | |
| 2019-06-27 10:15:32.545819 m_mapUri2InvalidData size: 0 | |
| 2019-06-27 10:15:33.247944 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:33.248064 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:33.248119 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0f6fc0 from (udp/172.17.0.2:5060) has 1061 bytes, veclen = 1 | |
| ############################################################################################### | |
| Emulated application requests caller to record name. | |
| ############################################################################################### | |
| 2019-06-27 10:15:33.248475 recv 1061 bytes from udp/[172.17.0.1]:60980 at 10:15:33.248172: | |
| INFO sip:12345678@127.0.0.1:5060 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-10 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060> | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 3 INFO | |
| Contact: sip:sipp@192.168.47.161:5061 | |
| Max-Forwards: 70 | |
| Content-Type: application/msml+xml | |
| Content-Length: 702 | |
| <?xml version='1.0' encoding='US-ASCII'?> | |
| <msml version="1.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="http://convedia.com/msml" xmlns:cvd="http://convedia.com/ext"> | |
| <dialogstart target="conn:4m6SD4me13tUr" type="application/moml+xml" name="recordname"> | |
| <play cvd:barge="false" cvd:cleardb="true"> | |
| <audio uri="file://provisioned/bt/MM2/eng/name_record.wav"/> | |
| <audio uri="file://provisioned/bt/MM2/eng/mute_on_beep.wav"/> | |
| </play> | |
| <record dest="file://transient/5923373421817_2.wav" format="audio/wav" maxtime="3s" cvd:pre-speech="5s" termkey="#"> | |
| <recordexit> | |
| <exit namelist="record.len"/> | |
| </recordexit> | |
| </record> | |
| </dialogstart> | |
| </msml> | |
| 2019-06-27 10:15:33.248565 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0f6fc0 (1061 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:33.248717 nta.c:3028 agent_recv_request() nta: received INFO sip:12345678@127.0.0.1:5060 SIP/2.0 (CSeq 3) | |
| 2019-06-27 10:15:33.248776 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:15:33.248823 nta.c:3209 agent_recv_request() nta: INFO (3) going to existing leg | |
| 2019-06-27 10:15:33.248879 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:15:33.248964 SipDialogController::processRequestInsideDialog: INFO irq 0x55d8ce0f8a60 | |
| 2019-06-27 10:15:33.249075 ClientController::addNetTransaction: transactionId ecb63e17-e717-4b1e-b4de-66e425f6a4da; size: 1 | |
| 2019-06-27 10:15:33.249305 Client::write_handler - wrote 1262 bytes: system:0 | |
| 2019-06-27 10:15:33.249407 SipDialogController::addIncomingRequestTransaction - adding transactionId ecb63e17-e717-4b1e-b4de-66e425f6a4da for irq:0x55d8ce0f8a60 | |
| 2019-06-27 10:15:33.253232 Client::read_handler read: ab152015-3ab8-4341-9444-73354f8e5076|sip|ecb63e17-e717-4b1e-b4de-66e425f6a4da| | |
| SIP/2.0 200 OK | |
| Call-ID: 1-45583@192.168.47.161 | |
| cseq: 3 INFO | |
| from: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| to: sut <sip:12345678@127.0.0.1:5060> | |
| Content-Length: 28 | |
| content-type: application/msml+xml | |
| <MSML value='response=200'/> | |
| 2019-06-27 10:15:33.253373 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:33.253421 Client::processMessage - request id ab152015-3ab8-4341-9444-73354f8e5076, request type: sip transaction id: ecb63e17-e717-4b1e-b4de-66e425f6a4da, dialog id: | |
| 2019-06-27 10:15:33.253483 ClientController::addApiRequest: clientMsgId ab152015-3ab8-4341-9444-73354f8e5076; size: 1 | |
| 2019-06-27 10:15:33.253636 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:15:33.253675 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId ecb63e17-e717-4b1e-b4de-66e425f6a4da | |
| 2019-06-27 10:15:33.253715 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d8ce0f8a60 | |
| 2019-06-27 10:15:33.253868 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:15:33.254406 makeTags - Adding well-known header 'Call-ID' with value '1-45583@192.168.47.161' | |
| 2019-06-27 10:15:33.254518 makeTags - Adding well-known header 'cseq' with value '3 INFO' | |
| 2019-06-27 10:15:33.254584 makeTags - Adding well-known header 'from' with value 'sipp <sip:sipp@192.168.47.161:5061>;tag=1' | |
| 2019-06-27 10:15:33.254691 makeTags - Adding well-known header 'to' with value 'sut <sip:12345678@127.0.0.1:5060>' | |
| 2019-06-27 10:15:33.254773 makeTags - Adding well-known header 'content-type' with value 'application/msml+xml' | |
| 2019-06-27 10:15:33.254973 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:60980 | |
| 2019-06-27 10:15:33.255081 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:33.255276 tport.c:3531 tport_send_msg() tport_vsend returned 351 | |
| 2019-06-27 10:15:33.255444 send 351 bytes to udp/[172.17.0.1]:60980 at 10:15:33.255175: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-10;received=172.17.0.1;rport=60980 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 3 INFO | |
| Content-Type: application/msml+xml | |
| Content-Length: 28 | |
| <MSML value='response=200'/ | |
| 2019-06-27 10:15:33.255509 nta.c:6939 incoming_reply() nta: sent 200 OK for INFO (3) | |
| 2019-06-27 10:15:33.255694 SipDialogController::doRespondToSipRequest destroying irq 0x55d8ce0f8a60 | |
| 2019-06-27 10:15:33.255794 ClientController::removeApiRequest: clientMsgId ab152015-3ab8-4341-9444-73354f8e5076; size: 0 | |
| 2019-06-27 10:15:33.256313 Client::write_handler - wrote 542 bytes: system:0 | |
| ############################################################################################### | |
| Our javascript pretends to have recorded name. | |
| ############################################################################################### | |
| 2019-06-27 10:15:33.256484 Client::read_handler read: db7396ee-118f-41b6-befe-5ad51b1d4bd9|sip||1-45583@192.168.47.161;from-tag=1 | |
| INFO sip:placeholder SIP/2.0 | |
| Content-Type: application/msml+xml | |
| Content-Length: 177 | |
| <?xml version="1.0"?><msml version="1.1"><event name="msml.dialog.exit" id="conn:NoTagMappingFound/dialog:recordname"><name>record.len</name><value>2500ms</value></event></msml> | |
| 2019-06-27 10:15:33.256675 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:33.256898 Client::processMessage - request id db7396ee-118f-41b6-befe-5ad51b1d4bd9, request type: sip transaction id: , dialog id: 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:33.256978 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:15:33.257124 ClientController::addAppTransaction: transactionId abb3c8fc-99be-4369-840d-9d1ce3eb053e; size: 1 | |
| 2019-06-27 10:15:33.257248 ClientController::addApiRequest: clientMsgId db7396ee-118f-41b6-befe-5ad51b1d4bd9; size: 1 | |
| 2019-06-27 10:15:33.257372 ClientController::removeNetTransaction: transactionId ecb63e17-e717-4b1e-b4de-66e425f6a4da; size: 0 | |
| 2019-06-27 10:15:33.257465 SipDialogController::doSendRequestInsideDialog dialog id: 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:33.257829 makeTags - Adding well-known header 'Content-Type' with value 'application/msml+xml' | |
| 2019-06-27 10:15:33.257925 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:sipp@192.168.47.161:5061 | |
| 2019-06-27 10:15:33.257964 DrachtioController::findTportForSubscription: no transport found for sipp@192.168.47.161 | |
| 2019-06-27 10:15:33.258001 SipDialogController::doSendRequestInsideDialog - sending request to nat'ed address using route sip:172.17.0.1:60980 | |
| 2019-06-27 10:15:33.258099 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:15:33.258154 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = udp/172.17.0.1:60980 | |
| 2019-06-27 10:15:33.258199 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:33.258369 tport.c:3531 tport_send_msg() tport_vsend returned 517 | |
| 2019-06-27 10:15:33.258509 send 517 bytes to udp/[172.17.0.1]:60980 at 10:15:33.258286: | |
| INFO sip:sipp@192.168.47.161:5061 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKygtDQNU9SHprc | |
| Max-Forwards: 70 | |
| From: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| To: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 3 INFO | |
| Content-Type: application/msml+xml | |
| Content-Length: 177 | |
| <?xml version="1.0"?><msml version="1.1"><event name="msml.dialog.exit" id="conn:NoTagMappingFound/dialog:recordname"><name>record.len</name><value>2500ms</value></event></msml | |
| 2019-06-27 10:15:33.258556 nta.c:8470 outgoing_send() nta: sent INFO (3) to udp/172.17.0.1:60980 | |
| 2019-06-27 10:15:33.258589 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce0facc0 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:15:33.258811 nta.c:1409 set_timeout() nta: timer shortened to 1000 ms | |
| 2019-06-27 10:15:33.258905 SipDialogController::doSendRequestInsideDialog - created orq 0x55d8ce0fe620 sending INFO to sip:sipp@192.168.47.161:5061 | |
| 2019-06-27 10:15:33.258975 SipDialogController::addRIP adding orq 0x55d8ce0fe620 | |
| 2019-06-27 10:15:33.259060 ClientController::removeApiRequest: clientMsgId db7396ee-118f-41b6-befe-5ad51b1d4bd9; size: 0 | |
| 2019-06-27 10:15:33.259404 Client::write_handler - wrote 708 bytes: system:0 | |
| 2019-06-27 10:15:33.259488 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:33.259607 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:33.259703 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0ff340 from (udp/172.17.0.2:5060) has 307 bytes, veclen = 1 | |
| 2019-06-27 10:15:33.259885 recv 307 bytes from udp/[172.17.0.1]:60980 at 10:15:33.259751: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKygtDQNU9SHprc | |
| From: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| To: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 3 INFO | |
| Contact: <sip:192.168.47.161:5061;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:15:33.259978 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0ff340 (307 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:33.260064 nta.c:3448 agent_recv_response() nta: received 200 OK for INFO (3) | |
| 2019-06-27 10:15:33.260155 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:15:33.260219 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 2.054 ms | |
| 2019-06-27 10:15:33.260303 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0facc0 by 0x55d8ce0fe620 with 0x55d8ce0ff340 | |
| 2019-06-27 10:15:33.260392 SipDialogController::processResponseInsideDialog: | |
| 2019-06-27 10:15:33.260482 SipDialogController::findRIPByOrq orq 0x55d8ce0fe620 | |
| 2019-06-27 10:15:33.260539 SipDialogController::processResponseInsideDialog: found request for response | |
| 2019-06-27 10:15:33.260671 Client::write_handler - wrote 474 bytes: system:0 | |
| 2019-06-27 10:15:33.260768 ClientController::removeAppTransaction: transactionId abb3c8fc-99be-4369-840d-9d1ce3eb053e; size: 0 | |
| 2019-06-27 10:15:33.260853 SipDialogController::clearRIP clearing orq 0x55d8ce0fe620 | |
| 2019-06-27 10:15:34.260540 nta.c:1357 agent_timer() nta: timer set next to 2934 ms | |
| 2019-06-27 10:15:34.262621 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:34.262715 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:34.262768 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0fcaa0 from (udp/172.17.0.2:5060) has 1725 bytes, veclen = 1 | |
| ############################################################################################### | |
| Emulated application server requests to join conference, listen for menu presses, and | |
| play announcement. | |
| ############################################################################################### | |
| 2019-06-27 10:15:34.263147 recv 1725 bytes from udp/[172.17.0.1]:60980 at 10:15:34.262814: | |
| INFO sip:12345678@127.0.0.1:5060 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-15 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060> | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 4 INFO | |
| Contact: sip:sipp@192.168.47.161:5061 | |
| Max-Forwards: 70 | |
| Content-Type: application/msml+xml | |
| Content-Length: 1366 | |
| <?xml version='1.0' encoding='US-ASCII'?> | |
| <msml version="1.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="http://convedia.com/msml" xmlns:cvd="http://convedia.com/ext"> | |
| <join id1="conn:4m6SD4me13tUr" id2="conf:5923373421817"> | |
| <stream dir="to-id1" media="audio"> | |
| <gain amt="0"/> | |
| </stream> | |
| <stream dir="from-id1" media="audio" dlb:audio_processing="enable" dlb:audio_processing_ver="1" > | |
| <clamp dtmf="true"/> | |
| <gain amt="0"/> | |
| </stream> | |
| </join> | |
| <dialogstart target="conn:4m6SD4me13tUr" type="application/moml+xml" name="listen"> | |
| <dtmf fdt="0s" idt="5s" edt="5s" cleardb="true"> | |
| <pattern digits="length=2" format="moml+digits"> | |
| <exit namelist="dtmf.digits dtmf.end"/> | |
| </pattern> | |
| <noinput> | |
| <exit namelist="dtmf.digits dtmf.end"/> | |
| </noinput> | |
| <nomatch> | |
| <exit namelist="dtmf.digits dtmf.end"/> | |
| </nomatch> | |
| </dtmf> | |
| </dialogstart> | |
| <dialogstart target="conf:5923373421817" type="application/moml+xml" name="playAnnc0"> | |
| <play cvd:barge="false" cvd:cleardb="true"> | |
| <audio uri="file://provisioned/bt/MM2/eng/first_person.wav"/> | |
| <playexit> | |
| <exit namelist="play.end" /> | |
| </playexit> | |
| </play> | |
| </dialogstart> | |
| </msml> | |
| 2019-06-27 10:15:34.263254 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0fcaa0 (1725 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:34.263313 nta.c:3028 agent_recv_request() nta: received INFO sip:12345678@127.0.0.1:5060 SIP/2.0 (CSeq 4) | |
| 2019-06-27 10:15:34.263357 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:15:34.263455 nta.c:3209 agent_recv_request() nta: INFO (4) going to existing leg | |
| 2019-06-27 10:15:34.263517 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:15:34.263556 SipDialogController::processRequestInsideDialog: INFO irq 0x55d8ce100480 | |
| 2019-06-27 10:15:34.263705 ClientController::addNetTransaction: transactionId 65161d77-8e30-4576-9b16-b588025c57f9; size: 1 | |
| 2019-06-27 10:15:34.263941 Client::write_handler - wrote 1926 bytes: system:0 | |
| 2019-06-27 10:15:34.264032 SipDialogController::addIncomingRequestTransaction - adding transactionId 65161d77-8e30-4576-9b16-b588025c57f9 for irq:0x55d8ce100480 | |
| 2019-06-27 10:15:34.266916 Client::read_handler read: 86ba4933-e5c3-4bbf-8f8f-360ab724248a|sip|65161d77-8e30-4576-9b16-b588025c57f9| | |
| SIP/2.0 200 OK | |
| Call-ID: 1-45583@192.168.47.161 | |
| cseq: 4 INFO | |
| from: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| to: sut <sip:12345678@127.0.0.1:5060> | |
| Content-Length: 28 | |
| content-type: application/msml+xml | |
| <MSML value='response=200'/> | |
| 2019-06-27 10:15:34.267062 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:34.267122 Client::processMessage - request id 86ba4933-e5c3-4bbf-8f8f-360ab724248a, request type: sip transaction id: 65161d77-8e30-4576-9b16-b588025c57f9, dialog id: | |
| 2019-06-27 10:15:34.267216 ClientController::addApiRequest: clientMsgId 86ba4933-e5c3-4bbf-8f8f-360ab724248a; size: 1 | |
| 2019-06-27 10:15:34.267324 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:15:34.267417 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 65161d77-8e30-4576-9b16-b588025c57f9 | |
| 2019-06-27 10:15:34.267478 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d8ce100480 | |
| 2019-06-27 10:15:34.267543 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:15:34.268124 makeTags - Adding well-known header 'Call-ID' with value '1-45583@192.168.47.161' | |
| 2019-06-27 10:15:34.268221 makeTags - Adding well-known header 'cseq' with value '4 INFO' | |
| 2019-06-27 10:15:34.268335 makeTags - Adding well-known header 'from' with value 'sipp <sip:sipp@192.168.47.161:5061>;tag=1' | |
| 2019-06-27 10:15:34.268407 makeTags - Adding well-known header 'to' with value 'sut <sip:12345678@127.0.0.1:5060>' | |
| 2019-06-27 10:15:34.268524 makeTags - Adding well-known header 'content-type' with value 'application/msml+xml' | |
| 2019-06-27 10:15:34.268710 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:60980 | |
| 2019-06-27 10:15:34.268811 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:34.268958 tport.c:3531 tport_send_msg() tport_vsend returned 351 | |
| 2019-06-27 10:15:34.269124 send 351 bytes to udp/[172.17.0.1]:60980 at 10:15:34.268865: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-15;received=172.17.0.1;rport=60980 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 4 INFO | |
| Content-Type: application/msml+xml | |
| Content-Length: 28 | |
| <MSML value='response=200'/ | |
| 2019-06-27 10:15:34.269170 nta.c:6939 incoming_reply() nta: sent 200 OK for INFO (4) | |
| 2019-06-27 10:15:34.269208 SipDialogController::doRespondToSipRequest destroying irq 0x55d8ce100480 | |
| 2019-06-27 10:15:34.269260 ClientController::removeApiRequest: clientMsgId 86ba4933-e5c3-4bbf-8f8f-360ab724248a; size: 0 | |
| 2019-06-27 10:15:34.269520 Client::write_handler - wrote 542 bytes: system:0 | |
| 2019-06-27 10:15:34.269638 ClientController::removeNetTransaction: transactionId 65161d77-8e30-4576-9b16-b588025c57f9; size: 0 | |
| ############################################################################################### | |
| Our javascript pretends the announcement is finished. | |
| ############################################################################################### | |
| 2019-06-27 10:15:34.271892 Client::read_handler read: 3fe391eb-1e3e-4f8c-8550-ae886d72d921|sip||1-45583@192.168.47.161;from-tag=1 | |
| INFO sip:placeholder SIP/2.0 | |
| Content-Type: application/msml+xml | |
| Content-Length: 181 | |
| <?xml version="1.0"?><msml version="1.1"><event name="msml.dialog.exit" id="conn:NoTagMappingFound/dialog:playAnnc0"><name>play.end</name><value>play.complete</value></event></msml> | |
| 2019-06-27 10:15:34.272040 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:34.272089 Client::processMessage - request id 3fe391eb-1e3e-4f8c-8550-ae886d72d921, request type: sip transaction id: , dialog id: 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:34.272139 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:15:34.272245 ClientController::addAppTransaction: transactionId 51043cd5-5fef-42a4-82d1-110022ac0eea; size: 1 | |
| 2019-06-27 10:15:34.272306 ClientController::addApiRequest: clientMsgId 3fe391eb-1e3e-4f8c-8550-ae886d72d921; size: 1 | |
| 2019-06-27 10:15:34.272409 SipDialogController::doSendRequestInsideDialog dialog id: 1-45583@192.168.47.161;from-tag=1 | |
| 2019-06-27 10:15:34.272929 makeTags - Adding well-known header 'Content-Type' with value 'application/msml+xml' | |
| 2019-06-27 10:15:34.273030 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:sipp@192.168.47.161:5061 | |
| 2019-06-27 10:15:34.273084 DrachtioController::findTportForSubscription: no transport found for sipp@192.168.47.161 | |
| 2019-06-27 10:15:34.273174 SipDialogController::doSendRequestInsideDialog - sending request to nat'ed address using route sip:172.17.0.1:60980 | |
| 2019-06-27 10:15:34.273256 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:15:34.273393 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = udp/172.17.0.1:60980 | |
| 2019-06-27 10:15:34.273453 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:34.273613 tport.c:3531 tport_send_msg() tport_vsend returned 521 | |
| 2019-06-27 10:15:34.273810 send 521 bytes to udp/[172.17.0.1]:60980 at 10:15:34.273513: | |
| INFO sip:sipp@192.168.47.161:5061 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKZSK6rgcDQtcBr | |
| Max-Forwards: 70 | |
| From: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| To: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 4 INFO | |
| Content-Type: application/msml+xml | |
| Content-Length: 181 | |
| <?xml version="1.0"?><msml version="1.1"><event name="msml.dialog.exit" id="conn:NoTagMappingFound/dialog:playAnnc0"><name>play.end</name><value>play.complete</value></event></msml | |
| 2019-06-27 10:15:34.273870 nta.c:8470 outgoing_send() nta: sent INFO (4) to udp/172.17.0.1:60980 | |
| 2019-06-27 10:15:34.273926 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce103660 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:15:34.274032 nta.c:1409 set_timeout() nta: timer shortened to 1000 ms | |
| 2019-06-27 10:15:34.274084 SipDialogController::doSendRequestInsideDialog - created orq 0x55d8ce103b20 sending INFO to sip:sipp@192.168.47.161:5061 | |
| 2019-06-27 10:15:34.274163 SipDialogController::addRIP adding orq 0x55d8ce103b20 | |
| 2019-06-27 10:15:34.274260 ClientController::removeApiRequest: clientMsgId 3fe391eb-1e3e-4f8c-8550-ae886d72d921; size: 0 | |
| 2019-06-27 10:15:34.274479 Client::write_handler - wrote 712 bytes: system:0 | |
| 2019-06-27 10:15:34.279638 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:34.279776 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:34.279929 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce105080 from (udp/172.17.0.2:5060) has 307 bytes, veclen = 1 | |
| 2019-06-27 10:15:34.280224 recv 307 bytes from udp/[172.17.0.1]:60980 at 10:15:34.279991: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bKZSK6rgcDQtcBr | |
| From: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| To: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 4 INFO | |
| Contact: <sip:192.168.47.161:5061;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:15:34.280303 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce105080 (307 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:34.280350 nta.c:3448 agent_recv_response() nta: received 200 OK for INFO (4) | |
| 2019-06-27 10:15:34.280395 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:15:34.280450 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 7.059 ms | |
| 2019-06-27 10:15:34.280492 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce103660 by 0x55d8ce103b20 with 0x55d8ce105080 | |
| 2019-06-27 10:15:34.280543 SipDialogController::processResponseInsideDialog: | |
| 2019-06-27 10:15:34.280584 SipDialogController::findRIPByOrq orq 0x55d8ce103b20 | |
| 2019-06-27 10:15:34.280628 SipDialogController::processResponseInsideDialog: found request for response | |
| 2019-06-27 10:15:34.280728 ClientController::removeAppTransaction: transactionId 51043cd5-5fef-42a4-82d1-110022ac0eea; size: 0 | |
| 2019-06-27 10:15:34.280770 SipDialogController::clearRIP clearing orq 0x55d8ce103b20 | |
| 2019-06-27 10:15:34.280825 Client::write_handler - wrote 474 bytes: system:0 | |
| 2019-06-27 10:15:35.277303 nta.c:1357 agent_timer() nta: timer set next to 1917 ms | |
| 2019-06-27 10:15:35.278552 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:35.278732 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:35.278790 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce100710 from (udp/172.17.0.2:5060) has 362 bytes, veclen = 1 | |
| ############################################################################################### | |
| All is good. We're now in the conference. | |
| sipp script completes and hangs up the call. | |
| ############################################################################################### | |
| 2019-06-27 10:15:35.278982 recv 362 bytes from udp/[172.17.0.1]:60980 at 10:15:35.278826: | |
| BYE sip:12345678@127.0.0.1:5060 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-20 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 5 BYE | |
| Contact: sip:sipp@192.168.47.161:5061 | |
| Max-Forwards: 70 | |
| Subject: Performance Test | |
| Content-Length: 0 | |
| 2019-06-27 10:15:35.279071 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce100710 (362 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:15:35.279177 nta.c:3028 agent_recv_request() nta: received BYE sip:12345678@127.0.0.1:5060 SIP/2.0 (CSeq 5) | |
| 2019-06-27 10:15:35.279278 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:15:35.279367 nta.c:3209 agent_recv_request() nta: BYE (5) going to existing leg | |
| 2019-06-27 10:15:35.279469 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:15:35.279524 SipDialogController::processRequestInsideDialog: BYE irq 0x55d8ce1034c0 | |
| 2019-06-27 10:15:35.279639 ClientController::addNetTransaction: transactionId caabd1fa-f4c2-4736-8c9a-59b67cbf121d; size: 1 | |
| 2019-06-27 10:15:35.279747 ClientController::removeDialog - after removing dialogs count is now: 1 | |
| 2019-06-27 10:15:35.279798 SipDialogController::addIncomingRequestTransaction - adding transactionId caabd1fa-f4c2-4736-8c9a-59b67cbf121d for irq:0x55d8ce1034c0 | |
| 2019-06-27 10:15:35.279855 SipDialogController::clearSipTimers for 1-45583@192.168.47.161 | |
| 2019-06-27 10:15:35.279891 Client::write_handler - wrote 561 bytes: system:0 | |
| 2019-06-27 10:15:35.279942 SipDialogController::clearDialog - cleared dialog id 1-45583@192.168.47.161;from-tag=1 referenced from leg 0x55d8ce0f3200 | |
| 2019-06-27 10:15:35.280046 No connected clients found to handle incoming cdr:stop request | |
| 2019-06-27 10:15:35.280152 SipDialog::~SipDialog - destroying sip dialog with call-id 1-45583@192.168.47.161 | |
| 2019-06-27 10:15:35.280206 nta.c:4619 nta_leg_destroy() nta_leg_destroy(0x55d8ce0f3200) | |
| 2019-06-27 10:15:35.285981 Client::read_handler read: 2c4f5590-5991-4873-a13f-6841960b875f|sip|caabd1fa-f4c2-4736-8c9a-59b67cbf121d| | |
| SIP/2.0 200 OK | |
| Call-ID: 1-45583@192.168.47.161 | |
| cseq: 5 BYE | |
| from: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| to: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Content-Length: 0 | |
| 2019-06-27 10:15:35.286117 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:35.286170 Client::processMessage - request id 2c4f5590-5991-4873-a13f-6841960b875f, request type: sip transaction id: caabd1fa-f4c2-4736-8c9a-59b67cbf121d, dialog id: | |
| 2019-06-27 10:15:35.286231 ClientController::addApiRequest: clientMsgId 2c4f5590-5991-4873-a13f-6841960b875f; size: 1 | |
| 2019-06-27 10:15:35.286464 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:15:35.286536 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId caabd1fa-f4c2-4736-8c9a-59b67cbf121d | |
| 2019-06-27 10:15:35.286602 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d8ce1034c0 | |
| 2019-06-27 10:15:35.286707 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:15:35.287407 makeTags - Adding well-known header 'Call-ID' with value '1-45583@192.168.47.161' | |
| 2019-06-27 10:15:35.287557 makeTags - Adding well-known header 'cseq' with value '5 BYE' | |
| 2019-06-27 10:15:35.287653 makeTags - Adding well-known header 'from' with value 'sipp <sip:sipp@192.168.47.161:5061>;tag=1' | |
| 2019-06-27 10:15:35.287727 makeTags - Adding well-known header 'to' with value 'sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH' | |
| 2019-06-27 10:15:35.287835 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:60980 | |
| 2019-06-27 10:15:35.287903 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:60980 | |
| 2019-06-27 10:15:35.288057 tport.c:3531 tport_send_msg() tport_vsend returned 285 | |
| 2019-06-27 10:15:35.288292 send 285 bytes to udp/[172.17.0.1]:60980 at 10:15:35.287976: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161:5061;branch=z9hG4bK-45583-1-20;received=172.17.0.1;rport=60980 | |
| From: sipp <sip:sipp@192.168.47.161:5061>;tag=1 | |
| To: sut <sip:12345678@127.0.0.1:5060>;tag=veeyQtZZyBeyH | |
| Call-ID: 1-45583@192.168.47.161 | |
| CSeq: 5 BYE | |
| Content-Length: 0 | |
| 2019-06-27 10:15:35.288409 nta.c:6939 incoming_reply() nta: sent 200 OK for BYE (5) | |
| 2019-06-27 10:15:35.288487 SipDialogController::doRespondToSipRequest destroying irq 0x55d8ce1034c0 | |
| 2019-06-27 10:15:35.288577 ClientController::removeApiRequest: clientMsgId 2c4f5590-5991-4873-a13f-6841960b875f; size: 0 | |
| 2019-06-27 10:15:35.289005 ClientController::removeNetTransaction: transactionId caabd1fa-f4c2-4736-8c9a-59b67cbf121d; size: 0 | |
| 2019-06-27 10:15:35.289259 Client::write_handler - wrote 476 bytes: system:0 | |
| 2019-06-27 10:15:35.290587 Client::read_handler read: b121d875-cace-4522-aacd-b7813fe2d08f|sip||563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| BYE sip:placeholder SIP/2.0 | |
| Content-Length: 0 | |
| 2019-06-27 10:15:35.290777 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:15:35.290837 Client::processMessage - request id b121d875-cace-4522-aacd-b7813fe2d08f, request type: sip transaction id: , dialog id: 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:35.290893 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:15:35.290971 ClientController::addAppTransaction: transactionId acb0f84f-5189-4194-9825-15dfc82646eb; size: 1 | |
| 2019-06-27 10:15:35.291031 ClientController::addApiRequest: clientMsgId b121d875-cace-4522-aacd-b7813fe2d08f; size: 1 | |
| 2019-06-27 10:15:35.291386 SipDialogController::doSendRequestInsideDialog dialog id: 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:35.292055 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:192.168.47.161:5063;transport=UDP | |
| 2019-06-27 10:15:35.292187 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:15:35.292290 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/192.168.47.161:5063 | |
| 2019-06-27 10:15:35.292384 tport.c:4085 tport_resolve() tport_resolve addrinfo = 192.168.47.161:5063 | |
| 2019-06-27 10:15:35.292603 tport.c:3531 tport_send_msg() tport_vsend returned 331 | |
| 2019-06-27 10:15:35.292870 send 331 bytes to udp/[192.168.47.161]:5063 at 10:15:35.292505: | |
| BYE sip:192.168.47.161:5063;transport=UDP SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK02cZtBXgm32XK | |
| Max-Forwards: 70 | |
| From: <sip:192.168.47.161:5060>;tag=U5m5NZev12QBp | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0115 | |
| Call-ID: 563f7afb-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261475 BYE | |
| Content-Length: 0 | |
| 2019-06-27 10:15:35.292987 nta.c:8470 outgoing_send() nta: sent BYE (6261475) to UDP/192.168.47.161:5063 | |
| 2019-06-27 10:15:35.293046 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce104c70 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:15:35.293126 nta.c:1409 set_timeout() nta: timer shortened to 1000 ms | |
| 2019-06-27 10:15:35.293226 SipDialogController::doSendRequestInsideDialog - created orq 0x55d8ce105430 sending BYE to sip:192.168.47.161:5063;transport=UDP | |
| 2019-06-27 10:15:35.293318 SipDialogController::addRIP adding orq 0x55d8ce105430 | |
| 2019-06-27 10:15:35.293435 No connected clients found to handle incoming cdr:stop request | |
| 2019-06-27 10:15:35.293541 ClientController::removeApiRequest: clientMsgId b121d875-cace-4522-aacd-b7813fe2d08f; size: 0 | |
| 2019-06-27 10:15:35.293892 Client::write_handler - wrote 522 bytes: system:0 | |
| 2019-06-27 10:15:35.295835 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:15:35.295992 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:15:35.296077 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce107930 from (udp/172.17.0.2:5060) has 328 bytes, veclen = 1 | |
| 2019-06-27 10:15:35.296462 recv 328 bytes from udp/[192.168.47.161]:5063 at 10:15:35.296247: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK02cZtBXgm32XK | |
| From: <sip:192.168.47.161:5060>;tag=U5m5NZev12QBp | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0115 | |
| Call-ID: 563f7afb-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261475 BYE | |
| Contact: <sip:192.168.47.161:5063;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:15:35.296589 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce107930 (328 bytes) from udp/192.168.47.161:5060 next=(nil) | |
| 2019-06-27 10:15:35.296648 nta.c:3448 agent_recv_response() nta: received 200 OK for BYE (6261475) | |
| 2019-06-27 10:15:35.296707 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:15:35.296774 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 4.484 ms | |
| 2019-06-27 10:15:35.296825 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce104c70 by 0x55d8ce105430 with 0x55d8ce107930 | |
| 2019-06-27 10:15:35.296875 SipDialogController::processResponseInsideDialog: | |
| 2019-06-27 10:15:35.296923 SipDialogController::findRIPByOrq orq 0x55d8ce105430 | |
| 2019-06-27 10:15:35.296970 SipDialogController::processResponseInsideDialog: found request for response | |
| 2019-06-27 10:15:35.297077 ClientController::removeAppTransaction: transactionId acb0f84f-5189-4194-9825-15dfc82646eb; size: 0 | |
| 2019-06-27 10:15:35.297135 ClientController::removeDialog - after removing dialogs count is now: 0 | |
| 2019-06-27 10:15:35.297149 Client::write_handler - wrote 524 bytes: system:0 | |
| 2019-06-27 10:15:35.297190 SipDialogController::processResponseInsideDialog: clearing dialog after receiving response to BYE or notify w/ subscription-state terminated | |
| 2019-06-27 10:15:35.297279 SipDialogController::clearDialog - cleared dialog id 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:35.297332 ClientController::removeDialog - dialog not found: 563f7afb-1367-1238-98a7-0242ac110002;from-tag=U5m5NZev12QBp | |
| 2019-06-27 10:15:35.297381 SipDialogController::clearRIP clearing orq 0x55d8ce105430 | |
| 2019-06-27 10:15:35.297428 SipDialog::~SipDialog - destroying sip dialog with call-id 563f7afb-1367-1238-98a7-0242ac110002 | |
| 2019-06-27 10:15:35.297472 nta.c:4619 nta_leg_destroy() nta_leg_destroy(0x55d8ce0e9b00) | |
| ############################################################################################### | |
| Successful test result! | |
| ############################################################################################### | |
| 2019-06-27 10:15:36.296967 nta.c:1357 agent_timer() nta: timer set next to 897 ms | |
| 2019-06-27 10:15:37.199890 nta.c:7281 _nta_incoming_timer() nta: timer I fired, terminate 200 response | |
| 2019-06-27 10:15:37.200106 nta.c:5973 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:15:37.200257 nta.c:7335 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/5 term, 1/5 free | |
| 2019-06-27 10:15:37.200404 nta.c:1357 agent_timer() nta: timer set next to 51 ms | |
| 2019-06-27 10:15:37.252861 nta.c:9267 outgoing_timer_dk() nta: timer K fired, terminate INFO (2) | |
| 2019-06-27 10:15:37.252990 nta.c:8965 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:15:37.253042 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/5 term, 1/6 free | |
| 2019-06-27 10:15:37.253104 nta.c:1357 agent_timer() nta: timer set next to 1007 ms | |
| 2019-06-27 10:15:38.261505 nta.c:9267 outgoing_timer_dk() nta: timer K fired, terminate INFO (3) | |
| 2019-06-27 10:15:38.261642 nta.c:8965 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:15:38.261739 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/4 term, 1/5 free | |
| 2019-06-27 10:15:38.262493 nta.c:1357 agent_timer() nta: timer set next to 1020 ms | |
| 2019-06-27 10:15:39.286553 nta.c:9267 outgoing_timer_dk() nta: timer K fired, terminate INFO (4) | |
| 2019-06-27 10:15:39.286737 nta.c:8965 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:15:39.286816 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free | |
| 2019-06-27 10:15:39.286899 nta.c:1357 agent_timer() nta: timer set next to 1011 ms | |
| 2019-06-27 10:15:40.300222 nta.c:9267 outgoing_timer_dk() nta: timer K fired, terminate BYE (6261475) | |
| 2019-06-27 10:15:40.300399 nta.c:8965 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:15:40.300478 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free | |
| 2019-06-27 10:15:40.300563 nta.c:1357 agent_timer() nta: timer set next to 23834 ms | |
| 2019-06-27 10:16:02.550102 DrachtioController::processWatchdogTimer | |
| 2019-06-27 10:16:02.550291 size of hash table for server-side transactions 31 | |
| 2019-06-27 10:16:02.550359 size of hash table for client-side transactions 31 | |
| 2019-06-27 10:16:02.550431 size of hash table for dialogs 31 | |
| 2019-06-27 10:16:02.550582 number of server-side transactions in the hash table 4 | |
| 2019-06-27 10:16:02.550803 number of client-side transactions in the hash table 2 | |
| 2019-06-27 10:16:02.550908 number of dialogs in the hash table 0 | |
| 2019-06-27 10:16:02.550969 number of sip messages received 12 | |
| 2019-06-27 10:16:02.551013 number of sip messages sent 12 | |
| 2019-06-27 10:16:02.551055 number of sip requests received 6 | |
| 2019-06-27 10:16:02.551105 number of sip requests sent 6 | |
| 2019-06-27 10:16:02.551189 number of bad sip messages received 0 | |
| 2019-06-27 10:16:02.551273 number of bad sip requests received 0 | |
| 2019-06-27 10:16:02.551344 number of bad sip requests dropped 0 | |
| 2019-06-27 10:16:02.551415 number of bad sip reponses dropped 0 | |
| 2019-06-27 10:16:02.551526 number of client transactions created 6 | |
| 2019-06-27 10:16:02.551691 number of server transactions created 6 | |
| 2019-06-27 10:16:02.551783 number of in-dialog server transactions created 5 | |
| 2019-06-27 10:16:02.551863 number of server transactions that have received ack 0 | |
| 2019-06-27 10:16:02.551971 number of server transactions that have received cancel 0 | |
| 2019-06-27 10:16:02.552095 number of requests that were processed stateless 1 | |
| 2019-06-27 10:16:02.552267 number of requests converted to transactions by message callback 0 | |
| 2019-06-27 10:16:02.552358 number of responses without matching request 0 | |
| 2019-06-27 10:16:02.552435 number of successful responses missing INVITE client transaction 0 | |
| 2019-06-27 10:16:02.552515 number of requests merged by UAS 0 | |
| 2019-06-27 10:16:02.552707 number of SIP responses sent by stack 6 | |
| 2019-06-27 10:16:02.552787 number of SIP requests retransmitted by stack 0 | |
| 2019-06-27 10:16:02.552847 number of SIP responses retransmitted by stack 0 | |
| 2019-06-27 10:16:02.553053 number of retransmitted SIP requests received by stack 0 | |
| 2019-06-27 10:16:02.553134 number of SIP client transactions that has timeout 0 | |
| 2019-06-27 10:16:02.553212 number of SIP server transactions that has timeout 0 | |
| 2019-06-27 10:16:02.553336 SipDialogController storage counts | |
| 2019-06-27 10:16:02.553431 ---------------------------------- | |
| 2019-06-27 10:16:02.553503 m_mapIrq2IIP size: 0 | |
| 2019-06-27 10:16:02.553583 m_mapOrq2IIP size: 0 | |
| 2019-06-27 10:16:02.553718 m_mapTransactionId2IIP size: 0 | |
| 2019-06-27 10:16:02.553791 m_mapLeg2Dialog size: 0 | |
| 2019-06-27 10:16:02.553883 m_mapId2Dialog size: 0 | |
| 2019-06-27 10:16:02.553960 m_mapOrq2RIP size: 0 | |
| 2019-06-27 10:16:02.554050 number of outgoing transactions held for timerD: 1 | |
| 2019-06-27 10:16:02.554097 number of outgoing transactions waiting for ACK from app: 0 | |
| 2019-06-27 10:16:02.554148 general queue size: 0 | |
| 2019-06-27 10:16:02.554229 timer A queue size: 0 | |
| 2019-06-27 10:16:02.554275 timer B queue size: 0 | |
| 2019-06-27 10:16:02.554321 timer C queue size: 0 | |
| 2019-06-27 10:16:02.554380 timer D queue size: 1 | |
| 2019-06-27 10:16:02.554424 timer E queue size: 0 | |
| 2019-06-27 10:16:02.554464 timer F queue size: 0 | |
| 2019-06-27 10:16:02.554510 timer G queue size: 0 | |
| 2019-06-27 10:16:02.554585 timer K queue size: 0 | |
| 2019-06-27 10:16:02.554791 ClientController storage counts | |
| 2019-06-27 10:16:02.554831 ---------------------------------- | |
| 2019-06-27 10:16:02.554864 m_clients size: 1 | |
| 2019-06-27 10:16:02.554909 m_services size: 0 | |
| 2019-06-27 10:16:02.554937 m_request_types size: 1 | |
| 2019-06-27 10:16:02.554963 m_map_of_request_type_offsets size: 1 | |
| 2019-06-27 10:16:02.554994 m_mapDialogs size: 0 | |
| 2019-06-27 10:16:02.555129 m_mapNetTransactions size: 0 | |
| 2019-06-27 10:16:02.555299 m_mapAppTransactions size: 0 | |
| 2019-06-27 10:16:02.555354 m_mapApiRequests size: 0 | |
| 2019-06-27 10:16:02.555385 m_mapDialogId2Appname size: 0 | |
| 2019-06-27 10:16:02.555446 PendingRequestController storage counts | |
| 2019-06-27 10:16:02.555501 ---------------------------------- | |
| 2019-06-27 10:16:02.555547 m_mapCallId2Invite size: 0 | |
| 2019-06-27 10:16:02.555584 m_mapTxnId2Invite size: 0 | |
| 2019-06-27 10:16:02.555629 SipProxyController storage counts | |
| 2019-06-27 10:16:02.555676 ---------------------------------- | |
| 2019-06-27 10:16:02.555798 m_mapCallId2Proxy size: 0 | |
| 2019-06-27 10:16:02.555850 m_mapNonce2Challenge size: 0 | |
| 2019-06-27 10:16:02.555881 general queue size: 0 | |
| 2019-06-27 10:16:02.555913 timer A queue size: 0 | |
| 2019-06-27 10:16:02.555939 timer B queue size: 0 | |
| 2019-06-27 10:16:02.555967 timer C queue size: 0 | |
| 2019-06-27 10:16:02.555994 timer D queue size: 0 | |
| 2019-06-27 10:16:02.556022 timer E queue size: 0 | |
| 2019-06-27 10:16:02.556049 timer F queue size: 0 | |
| 2019-06-27 10:16:02.556076 timer G queue size: 0 | |
| 2019-06-27 10:16:02.556103 timer K queue size: 0 | |
| 2019-06-27 10:16:02.556131 m_mapUri2InvalidData size: 0 | |
| 2019-06-27 10:16:04.144129 nta.c:9267 outgoing_timer_dk() nta: timer D fired, terminate INVITE (6261474) | |
| 2019-06-27 10:16:04.144267 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 0/2 free | |
| 2019-06-27 10:16:04.144377 nta.c:1357 agent_timer() nta: timer set next to 36 ms | |
| 2019-06-27 10:16:04.183334 nta.c:9148 outgoing_timer_bf() nta: timer F fired, terminating ACK (6261474) | |
| 2019-06-27 10:16:04.183471 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 0/2 free | |
| 2019-06-27 10:16:04.183733 nta.c:1357 agent_timer() nta: timer set next to 44 ms | |
| 2019-06-27 10:16:04.228802 nta.c:7306 _nta_incoming_timer() nta: timer J fired, terminate 200 response | |
| 2019-06-27 10:16:04.230070 nta.c:5973 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:16:04.231058 nta.c:7335 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/4 term, 1/4 free | |
| 2019-06-27 10:16:04.231350 nta.c:1357 agent_timer() nta: timer set next to 1027 ms | |
| 2019-06-27 10:16:04.640187 timerD: running timer function | |
| 2019-06-27 10:16:04.640292 timerD: timer not set (queue is empty after processing expired timers), length: 0 | |
| 2019-06-27 10:16:04.640345 TimerDHandler::timerD - freeing ACK orq 0x55d8ce0ecc40 associated with invite orq 0x55d8ce0ef220 for call-id/cseq 563f7afb-1367-1238-98a7-0242ac1100026261474 | |
| 2019-06-27 10:16:04.640399 nta.c:8888 outgoing_free() nta: outgoing_free(0x55d8ce0ecc40) | |
| 2019-06-27 10:16:05.257976 nta.c:7306 _nta_incoming_timer() nta: timer J fired, terminate 200 response | |
| 2019-06-27 10:16:05.258123 nta.c:5973 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:16:05.258213 nta.c:7335 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free | |
| 2019-06-27 10:16:05.258289 nta.c:1357 agent_timer() nta: timer set next to 1011 ms | |
| 2019-06-27 10:16:06.274405 nta.c:7306 _nta_incoming_timer() nta: timer J fired, terminate 200 response | |
| 2019-06-27 10:16:06.274534 nta.c:5973 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:16:06.274597 nta.c:7335 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free | |
| 2019-06-27 10:16:06.274811 nta.c:1357 agent_timer() nta: timer set next to 1014 ms | |
| 2019-06-27 10:16:07.290367 nta.c:7306 _nta_incoming_timer() nta: timer J fired, terminate 200 response | |
| 2019-06-27 10:16:07.290503 nta.c:5973 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:16:07.290594 nta.c:7335 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free | |
| 2019-06-27 10:16:07.290670 nta.c:1350 agent_timer() nta: timer not set | |
| ############################################################################################### | |
| Now I have pointed sipp (using basic UAC function) at our application server. | |
| And told our application server that this is it's media server. | |
| We should see exactly the same call flow. | |
| ############################################################################################### | |
| 2019-06-27 10:16:15.574279 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.574367 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.574415 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0ff340 from (udp/172.17.0.2:5060) has 548 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.574611 recv 548 bytes from udp/[172.17.0.1]:33236 at 10:16:15.574454: | |
| INVITE sip:msml@192.168.47.161:5060 SIP/2.0 | |
| Max-Forwards: 70 | |
| Content-Length: 139 | |
| Contact: <sip:mm2dev-slee@192.168.46.213:5062;transport=UDP> | |
| To: <sip:msml@192.168.47.161:5060> | |
| CSeq: 1 INVITE | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKnNYZWIVgUh8FzJ6r9s8HA1 | |
| Call-ID: lpiKp4Uozz | |
| Content-Type: application/sdp | |
| From: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6000 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:16:15.574662 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0ff340 (548 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:16:15.574709 nta.c:3028 agent_recv_request() nta: received INVITE sip:msml@192.168.47.161:5060 SIP/2.0 (CSeq 1) | |
| 2019-06-27 10:16:15.574891 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:16:15.574958 nta.c:3397 agent_aliases() nta: canonizing sip:msml@192.168.47.161:5060 with contact | |
| 2019-06-27 10:16:15.575019 nta.c:3243 agent_recv_request() nta: INVITE (1) to message callback | |
| 2019-06-27 10:16:15.575081 processMessageStatelessly - incoming message with call-id lpiKp4Uozz does not match an existing call leg, processed in thread 140631196501824 | |
| 2019-06-27 10:16:15.575174 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:33236 | |
| 2019-06-27 10:16:15.575272 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:33236 | |
| 2019-06-27 10:16:15.575387 tport.c:3531 tport_send_msg() tport_vsend returned 304 | |
| 2019-06-27 10:16:15.575529 send 304 bytes to udp/[172.17.0.1]:33236 at 10:16:15.575333: | |
| SIP/2.0 100 Trying | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKnNYZWIVgUh8FzJ6r9s8HA1;received=172.17.0.1;rport=33236 | |
| From: "mm2dev-slee" <sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| To: <sip:msml@192.168.47.161:5060> | |
| Call-ID: lpiKp4Uozz | |
| CSeq: 1 INVITE | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.575593 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 | |
| 2019-06-27 10:16:15.575646 ClientController::route_request_outside_dialog - Selected client at offset 0 | |
| 2019-06-27 10:16:15.575710 PendingRequestController::add - tport: 0x55d8ce0e55a0, Call-ID: lpiKp4Uozz, transactionId 3e186ad5-2911-4a4f-b60e-96a259aa04c3 | |
| 2019-06-27 10:16:15.575767 pending-request: Adding entry to go off in 64000ms | |
| 2019-06-27 10:16:15.575812 pending-request: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:16:15.575886 ClientController::addNetTransaction: transactionId 3e186ad5-2911-4a4f-b60e-96a259aa04c3; size: 1 | |
| 2019-06-27 10:16:15.576058 Client::write_handler - wrote 713 bytes: system:0 | |
| 2019-06-27 10:16:15.576138 No connected clients found to handle incoming cdr:attempt request | |
| 2019-06-27 10:16:15.579484 Client::read_handler read: 36c365fd-e084-4d09-9686-8f2ce19a8c35|sip|| | |
| INVITE sip:1234@192.168.47.161:5063 SIP/2.0 | |
| Content-Length: 139 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6000 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:16:15.579653 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:16:15.579717 Client::processMessage - request id 36c365fd-e084-4d09-9686-8f2ce19a8c35, request type: sip transaction id: , dialog id: | |
| 2019-06-27 10:16:15.579842 Client::processMessage - sending a request outside of a dialog | |
| 2019-06-27 10:16:15.579931 ClientController::addAppTransaction: transactionId 96d934eb-566d-4103-914e-382c53ed7d1b; size: 1 | |
| 2019-06-27 10:16:15.579978 ClientController::addApiRequest: clientMsgId 36c365fd-e084-4d09-9686-8f2ce19a8c35; size: 1 | |
| 2019-06-27 10:16:15.580175 DrachtioController::findTportForSubscription: no transport found for 1234@192.168.47.161 | |
| 2019-06-27 10:16:15.583045 SipTransport::findAppropriateTransport: searching for a transport to reach udp/sip:1234@192.168.47.161:5063 | |
| 2019-06-27 10:16:15.583372 SipTransport::findAppropriateTransport - after filtering for transport we have 4 candidates | |
| 2019-06-27 10:16:15.583520 SipTransport::findAppropriateTransport - after filtering for protocol we have 2 candidates | |
| 2019-06-27 10:16:15.586516 SipTransport::findAppropriateTransport: - returning the best match 0x55d8ce0e55a0: udp/172.17.0.2:5060 | |
| 2019-06-27 10:16:15.586612 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:16:15.586649 SipDialogController::doSendRequestOutsideDialog selected transport 0x55d8ce0e55a0udp/172.17.0.2:5060 | |
| 2019-06-27 10:16:15.586950 makeTags - using external IP as replacement for 'localhost': 192.168.47.161 | |
| 2019-06-27 10:16:15.587019 SipDialogController::doSendRequestOutsideDialog - from: <sip:192.168.47.161:5060> | |
| 2019-06-27 10:16:15.587087 SipDialogController::doSendRequestOutsideDialog - to: sip:1234@192.168.47.161:5063 | |
| 2019-06-27 10:16:15.587127 SipDialogController::doSendRequestOutsideDialog - contact: <sip:192.168.47.161:5060> | |
| 2019-06-27 10:16:15.587187 SipDialogController::doSendRequestOutsideDialog - automatically detecting content-type as application/sdp | |
| 2019-06-27 10:16:15.587227 isLocalSipUri: checking to see if this is one of mine: sip:1234@192.168.47.161:5063 | |
| 2019-06-27 10:16:15.587315 nta.c:4566 nta_leg_tcreate() nta_leg_tcreate(0x55d8ce0f1b00) | |
| 2019-06-27 10:16:15.587477 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:16:15.587778 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = */192.168.47.161:5063 | |
| 2019-06-27 10:16:15.587839 tport.c:4085 tport_resolve() tport_resolve addrinfo = 192.168.47.161:5063 | |
| 2019-06-27 10:16:15.588141 tport.c:3531 tport_send_msg() tport_vsend returned 515 | |
| 2019-06-27 10:16:15.588314 send 515 bytes to udp/[192.168.47.161]:5063 at 10:16:15.588057: | |
| INVITE sip:1234@192.168.47.161:5063 SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK1B6Qv6DmHcSgF | |
| Max-Forwards: 70 | |
| From: <sip:192.168.47.161:5060>;tag=XQ7pSNg3Um4gD | |
| To: <sip:1234@192.168.47.161:5063> | |
| Call-ID: 7027dde2-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261495 INVITE | |
| Contact: <sip:192.168.47.161:5060> | |
| Content-Type: application/sdp | |
| Content-Length: 139 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6000 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:16:15.588363 nta.c:8470 outgoing_send() nta: sent INVITE (6261495) to */192.168.47.161:5063 | |
| 2019-06-27 10:16:15.588393 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce0f4c30 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:16:15.588436 nta.c:1411 set_timeout() nta: timer set to 32000 ms | |
| 2019-06-27 10:16:15.588487 nta.c:1409 set_timeout() nta: timer shortened to 1000 ms | |
| 2019-06-27 10:16:15.588554 SipDialog::SipDialog - creating dialog for outbound INVITE sent from udp/172.17.0.2:5060 to 192.168.47.161:5063 | |
| 2019-06-27 10:16:15.588695 SipDialogController::addOutgoingInviteTransaction: adding leg 0x55d8ce0f1b00 | |
| 2019-06-27 10:16:15.588913 No connected clients found to handle incoming cdr:attempt request | |
| 2019-06-27 10:16:15.589039 ClientController::removeApiRequest: clientMsgId 36c365fd-e084-4d09-9686-8f2ce19a8c35; size: 0 | |
| 2019-06-27 10:16:15.589439 Client::write_handler - wrote 706 bytes: system:0 | |
| 2019-06-27 10:16:15.589599 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.589831 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.589915 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0f7280 from (udp/172.17.0.2:5060) has 336 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.590296 recv 336 bytes from udp/[192.168.47.161]:5063 at 10:16:15.590091: | |
| SIP/2.0 180 Ringing | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK1B6Qv6DmHcSgF | |
| From: <sip:192.168.47.161:5060>;tag=XQ7pSNg3Um4gD | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0116 | |
| Call-ID: 7027dde2-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261495 INVITE | |
| Contact: <sip:192.168.47.161:5063;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.590567 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0f7280 (336 bytes) from udp/192.168.47.161:5060 next=(nil) | |
| 2019-06-27 10:16:15.590786 nta.c:3448 agent_recv_response() nta: received 180 Ringing for INVITE (6261495) | |
| 2019-06-27 10:16:15.590976 nta.c:3515 agent_recv_response() nta: 180 Ringing is going to a transaction | |
| 2019-06-27 10:16:15.591138 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 3.357 ms | |
| 2019-06-27 10:16:15.591208 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0f4c30 by 0x55d8ce1046e0 with 0x55d8ce0f7280 (preliminary) | |
| 2019-06-27 10:16:15.591383 SipDialogController::processResponseOutsideDialog | |
| 2019-06-27 10:16:15.591650 Client::write_handler - wrote 532 bytes: system:0 | |
| 2019-06-27 10:16:15.591908 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.592045 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.592135 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0ecc00 from (udp/172.17.0.2:5060) has 505 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.592411 recv 505 bytes from udp/[192.168.47.161]:5063 at 10:16:15.592262: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK1B6Qv6DmHcSgF | |
| From: <sip:192.168.47.161:5060>;tag=XQ7pSNg3Um4gD | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0116 | |
| Call-ID: 7027dde2-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261495 INVITE | |
| Contact: <sip:192.168.47.161:5063;transport=UDP> | |
| Content-Type: application/sdp | |
| Content-Length: 139 | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6001 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:16:15.592470 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0ecc00 (505 bytes) from udp/192.168.47.161:5060 next=(nil) | |
| 2019-06-27 10:16:15.592502 nta.c:3448 agent_recv_response() nta: received 200 OK for INVITE (6261495) | |
| 2019-06-27 10:16:15.592533 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:16:15.592557 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0f4c30 by 0x55d8ce1046e0 with 0x55d8ce0ecc00 | |
| 2019-06-27 10:16:15.592594 SipDialogController::processResponseOutsideDialog | |
| 2019-06-27 10:16:15.592641 SipDialogController::processResponse - adding dialog id: 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.592691 ClientController::addDialogForTransaction - added dialog (uac), now tracking: 1 dialogs and 1 app transactions | |
| 2019-06-27 10:16:15.592731 ClientController::addDialogForTransaction - transaction id 96d934eb-566d-4103-914e-382c53ed7d1b has associated dialog 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.592778 timerD: Adding entry to go off in 32500ms | |
| 2019-06-27 10:16:15.592811 timerD: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:16:15.592854 TimerDHandler::addInvite 0x55d8ce1046e0, 7027dde2-1367-1238-98a7-0242ac1100026261495 | |
| 2019-06-27 10:16:15.592948 Client::write_handler - wrote 701 bytes: system:0 | |
| 2019-06-27 10:16:15.592995 ClientController::removeAppTransaction: transactionId 96d934eb-566d-4103-914e-382c53ed7d1b; size: 0 | |
| 2019-06-27 10:16:15.593039 No connected clients found to handle incoming cdr:start request | |
| 2019-06-27 10:16:15.639624 Client::read_handler read: 06d45985-4f1c-464d-8604-39c238fd6fac|sip||7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| ACK sip:1234@192.168.47.161:5063 SIP/2.0 | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.640060 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:16:15.640250 Client::processMessage - request id 06d45985-4f1c-464d-8604-39c238fd6fac, request type: sip transaction id: , dialog id: 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.640305 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:16:15.640375 ClientController::addApiRequest: clientMsgId 06d45985-4f1c-464d-8604-39c238fd6fac; size: 1 | |
| 2019-06-27 10:16:15.640627 Client::read_handler read: 5444e352-67a0-4179-ba2d-511bda82187c|sip|3e186ad5-2911-4a4f-b60e-96a259aa04c3| | |
| SIP/2.0 200 OK | |
| Call-ID: lpiKp4Uozz | |
| cseq: 1 INVITE | |
| from: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| to: <sip:msml@192.168.47.161:5060> | |
| Content-Length: 139 | |
| user-agent: drachtio/iechyd-da | |
| X-Linked-UUID: 1e2587c | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6001 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:16:15.640747 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:16:15.640833 Client::processMessage - request id 5444e352-67a0-4179-ba2d-511bda82187c, request type: sip transaction id: 3e186ad5-2911-4a4f-b60e-96a259aa04c3, dialog id: | |
| 2019-06-27 10:16:15.640897 ClientController::addApiRequest: clientMsgId 5444e352-67a0-4179-ba2d-511bda82187c; size: 2 | |
| 2019-06-27 10:16:15.643419 SipDialogController::doSendRequestInsideDialog dialog id: 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.645623 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:192.168.47.161:5063;transport=UDP | |
| 2019-06-27 10:16:15.645773 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:16:15.645899 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/192.168.47.161:5063 | |
| 2019-06-27 10:16:15.646048 tport.c:4085 tport_resolve() tport_resolve addrinfo = 192.168.47.161:5063 | |
| 2019-06-27 10:16:15.646351 tport.c:3531 tport_send_msg() tport_vsend returned 331 | |
| 2019-06-27 10:16:15.646612 send 331 bytes to udp/[192.168.47.161]:5063 at 10:16:15.646145: | |
| ACK sip:192.168.47.161:5063;transport=UDP SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK2mZgy1yQeNF3a | |
| Max-Forwards: 70 | |
| From: <sip:192.168.47.161:5060>;tag=XQ7pSNg3Um4gD | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0116 | |
| Call-ID: 7027dde2-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261495 ACK | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.646786 nta.c:8470 outgoing_send() nta: sent ACK (6261495) to UDP/192.168.47.161:5063 | |
| 2019-06-27 10:16:15.646977 TimerDHandler::addAck 0x55d8ce1023f0, 7027dde2-1367-1238-98a7-0242ac1100026261495 | |
| 2019-06-27 10:16:15.647160 SipDialogController::doSendRequestInsideDialog - clearing IIP that we generated as uac | |
| 2019-06-27 10:16:15.647281 SipDialogController::clearIIP: clearing leg 0x55d8ce0f1b00, irq: 0, orq: 0x55d8ce1046e0, rel: 0 | |
| 2019-06-27 10:16:15.647409 SipDialogController::clearIIP: clearing m_mapOrq2IIP for leg 0x55d8ce0f1b00 | |
| 2019-06-27 10:16:15.647571 ClientController::removeApiRequest: clientMsgId 06d45985-4f1c-464d-8604-39c238fd6fac; size: 1 | |
| 2019-06-27 10:16:15.648010 Client::write_handler - wrote 522 bytes: system:0 | |
| 2019-06-27 10:16:15.648280 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:16:15.648393 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 3e186ad5-2911-4a4f-b60e-96a259aa04c3 | |
| 2019-06-27 10:16:15.648516 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - failed to find transactionId 3e186ad5-2911-4a4f-b60e-96a259aa04c3, most likely this is a response to an invite we sent | |
| 2019-06-27 10:16:15.648635 pending-request: removing entry, prior to removal length: 1 | |
| 2019-06-27 10:16:15.648731 pending-request: removed entry, timer not set (queue is empty after removal), length: 0 | |
| 2019-06-27 10:16:15.648918 nta.c:1409 set_timeout() nta: timer shortened to 200 ms | |
| 2019-06-27 10:16:15.649079 nta.c:4566 nta_leg_tcreate() nta_leg_tcreate(0x55d8ce0ef410) | |
| 2019-06-27 10:16:15.649186 DrachtioController::setupLegForIncomingRequest - created leg: 0x55d8ce0ef410, irq: 0x55d8ce0ede10, for transactionId: 3e186ad5-2911-4a4f-b60e-96a259aa04c3 | |
| 2019-06-27 10:16:15.649297 SipDialog::SipDialog - (UAS) detected client behind nat, using 172.17.0.1:33236 as route for requests within this dialog | |
| 2019-06-27 10:16:15.649415 SipDialog::SipDialog - creating dialog for inbound INVITE sent from UDP/172.17.0.2:5060 | |
| 2019-06-27 10:16:15.649567 SipDialogController::addIncomingInviteTransaction: added iip: 0x55d8ce0f1060 with leg 0x55d8ce0ef410, irq: 0x55d8ce0ede10, transactionId 3e186ad5-2911-4a4f-b60e-96a259aa04c3, iip size: 1 | |
| 2019-06-27 10:16:15.649725 SipDialogController::doRespondToSipRequest found invite or subscribe in progress 0x55d8ce0f1060 | |
| 2019-06-27 10:16:15.649878 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:16:15.650716 makeTags - Adding well-known header 'Call-ID' with value 'lpiKp4Uozz' | |
| 2019-06-27 10:16:15.650848 makeTags - Adding well-known header 'cseq' with value '1 INVITE' | |
| 2019-06-27 10:16:15.650901 makeTags - Adding well-known header 'from' with value '"mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0' | |
| 2019-06-27 10:16:15.650983 makeTags - Adding well-known header 'to' with value '<sip:msml@192.168.47.161:5060>' | |
| 2019-06-27 10:16:15.651055 makeTags - Adding well-known header 'user-agent' with value 'drachtio/iechyd-da' | |
| 2019-06-27 10:16:15.651136 makeTags - custom header: 'X-Linked-UUID', value: 1e2587c | |
| 2019-06-27 10:16:15.651208 Sending 200 response (not reliably) on irq 0x55d8ce0ede10 | |
| 2019-06-27 10:16:15.651337 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:33236 | |
| 2019-06-27 10:16:15.651383 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:33236 | |
| 2019-06-27 10:16:15.651541 tport.c:3531 tport_send_msg() tport_vsend returned 582 | |
| 2019-06-27 10:16:15.651751 send 582 bytes to udp/[172.17.0.1]:33236 at 10:16:15.651463: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKnNYZWIVgUh8FzJ6r9s8HA1;received=172.17.0.1;rport=33236 | |
| From: "mm2dev-slee" <sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| To: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Call-ID: lpiKp4Uozz | |
| CSeq: 1 INVITE | |
| Contact: <sip:192.168.47.161:5060> | |
| User-Agent: drachtio/iechyd-da | |
| Content-Type: application/sdp | |
| Content-Length: 139 | |
| X-Linked-UUID: 1e2587c | |
| v=0 | |
| o=user1 53655765 2353687637 IN IP4 192.168.47.161 | |
| s=- | |
| c=IN IP4 192.168.47.161 | |
| t=0 0 | |
| m=audio 6001 RTP/AVP 0 | |
| a=rtpmap:0 PCMU/8000 | |
| 2019-06-27 10:16:15.651846 nta.c:6939 incoming_reply() nta: sent 200 OK for INVITE (1) | |
| 2019-06-27 10:16:15.651909 ClientController::addDialogForTransaction - added dialog (uas), now tracking: 2 dialogs and 1 net transactions | |
| 2019-06-27 10:16:15.652004 ClientController::addDialogForTransaction - transaction id 3e186ad5-2911-4a4f-b60e-96a259aa04c3 has associated dialog lpiKp4Uozz;from-tag=1213582715616305755441.0 | |
| 2019-06-27 10:16:15.652067 timerG: Adding entry to go off in 500ms | |
| 2019-06-27 10:16:15.652136 timerG: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:16:15.652187 timerH: Adding entry to go off in 32000ms | |
| 2019-06-27 10:16:15.652247 timerH: Adding entry to the head (queue was empty), length: 1 | |
| 2019-06-27 10:16:15.652330 ClientController::removeApiRequest: clientMsgId 5444e352-67a0-4179-ba2d-511bda82187c; size: 0 | |
| 2019-06-27 10:16:15.652906 Client::write_handler - wrote 820 bytes: system:0 | |
| 2019-06-27 10:16:15.653044 No connected clients found to handle incoming cdr:start request | |
| 2019-06-27 10:16:15.665409 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.665612 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.665670 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce102e60 from (udp/172.17.0.2:5060) has 321 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.665850 recv 321 bytes from udp/[172.17.0.1]:33236 at 10:16:15.665709: | |
| ACK sip:192.168.47.161:5060 SIP/2.0 | |
| Max-Forwards: 70 | |
| Content-Length: 0 | |
| To: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| CSeq: 1 ACK | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKnGPqpcL0GGPOAeivcxgaH1 | |
| Call-ID: lpiKp4Uozz | |
| From: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| 2019-06-27 10:16:15.665897 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce102e60 (321 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:16:15.665951 nta.c:3028 agent_recv_request() nta: received ACK sip:192.168.47.161:5060 SIP/2.0 (CSeq 1) | |
| 2019-06-27 10:16:15.666062 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:16:15.666140 nta.c:3397 agent_aliases() nta: canonizing sip:192.168.47.161:5060 with contact | |
| 2019-06-27 10:16:15.666205 nta.c:3209 agent_recv_request() nta: ACK (1) going to existing leg | |
| 2019-06-27 10:16:15.666278 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:16:15.666323 SipDialogController::processRequestInsideDialog: ACK irq 0x55d8ce103f20 | |
| ############################################################################################### | |
| B2B established as before. | |
| ############################################################################################### | |
| 2019-06-27 10:16:15.666402 SipDialogController::clearIIP: clearing leg 0x55d8ce0ef410, irq: 0x55d8ce0ede10, orq: 0, rel: 0 | |
| 2019-06-27 10:16:15.666485 SipDialogController::clearIIP: clearing m_mapIrq2IIP for leg 0x55d8ce0ef410 | |
| 2019-06-27 10:16:15.666530 SipDialogController::clearSipTimers for lpiKp4Uozz | |
| 2019-06-27 10:16:15.666569 timerG: removing entry, prior to removal length: 1 | |
| 2019-06-27 10:16:15.666606 timerG: removed entry, timer not set (queue is empty after removal), length: 0 | |
| 2019-06-27 10:16:15.666680 timerH: removing entry, prior to removal length: 1 | |
| 2019-06-27 10:16:15.666721 timerH: removed entry, timer not set (queue is empty after removal), length: 0 | |
| 2019-06-27 10:16:15.666846 Client::write_handler - wrote 528 bytes: system:0 | |
| 2019-06-27 10:16:15.666927 ClientController::removeNetTransaction: transactionId 3e186ad5-2911-4a4f-b60e-96a259aa04c3; size: 0 | |
| 2019-06-27 10:16:15.666969 ClientController::route_ack_request_inside_dialog - removed incoming invite transaction, map size is now: 0 request | |
| 2019-06-27 10:16:15.667053 nta.c:5892 incoming_free() nta: incoming_free(0x55d8ce103f20) | |
| 2019-06-27 10:16:15.667127 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.667197 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.667249 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce102e60 from (udp/172.17.0.2:5060) has 954 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.667524 recv 954 bytes from udp/[172.17.0.1]:33236 at 10:16:15.667280: | |
| INFO sip:192.168.47.161:5060 SIP/2.0 | |
| Content-Length: 561 | |
| To: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Contact: <sip:192.168.46.213:5062;transport=UDP> | |
| CSeq: 2 INFO | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKntqzCicGdQ8lljinl9kT61 | |
| Call-ID: lpiKp4Uozz | |
| Content-Type: application/msml+xml | |
| From: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| <?xml version='1.0' encoding='US-ASCII'?> | |
| <msml version='1.1'> | |
| <dialogstart target='conn:y00FUg16rXt3r' type='application/moml+xml' > | |
| <play cvd:barge='true' cvd:cleardb='false' > | |
| <audio uri='file://provisioned/bt/MM2/eng/pin_prompt.wav' /> | |
| </play> | |
| <dtmf fdt='10s' idt='20s' edt='20s' cleardb='false' > | |
| <pattern digits='min=1;max=27;rtk=#' format='moml+digits'> | |
| <exit namelist='dtmf.digits dtmf.end'/> | |
| </pattern> | |
| <noinput><exit namelist='dtmf.digits dtmf.end'/></noinput> | |
| <nomatch><exit namelist='dtmf.digits dtmf.end'/></nomatch> | |
| </dtmf> | |
| </dialogstart> | |
| </msml> | |
| ############################################################################################### | |
| INFO received as before. | |
| ############################################################################################### | |
| 2019-06-27 10:16:15.667639 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce102e60 (954 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:16:15.667684 nta.c:3028 agent_recv_request() nta: received INFO sip:192.168.47.161:5060 SIP/2.0 (CSeq 2) | |
| 2019-06-27 10:16:15.667766 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:16:15.667808 nta.c:3397 agent_aliases() nta: canonizing sip:192.168.47.161:5060 with contact | |
| 2019-06-27 10:16:15.667841 nta.c:3209 agent_recv_request() nta: INFO (2) going to existing leg | |
| 2019-06-27 10:16:15.667935 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:16:15.667977 SipDialogController::processRequestInsideDialog: INFO irq 0x55d8ce1041a0 | |
| 2019-06-27 10:16:15.668042 ClientController::addNetTransaction: transactionId e27b05c9-5be9-4cca-a22b-430c0563c7d0; size: 1 | |
| 2019-06-27 10:16:15.668421 Client::write_handler - wrote 1165 bytes: system:0 | |
| 2019-06-27 10:16:15.668574 SipDialogController::addIncomingRequestTransaction - adding transactionId e27b05c9-5be9-4cca-a22b-430c0563c7d0 for irq:0x55d8ce1041a0 | |
| 2019-06-27 10:16:15.675551 Client::read_handler read: 7c951738-f69e-497b-bd1a-e6ab0ea2b21a|sip|e27b05c9-5be9-4cca-a22b-430c0563c7d0| | |
| SIP/2.0 200 OK | |
| Call-ID: lpiKp4Uozz | |
| cseq: 2 INFO | |
| from: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| to: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Content-Length: 0 | |
| ############################################################################################### | |
| This time the INFO event handler in our javascript does not get called. | |
| It seems the 200 OK has been sent automatically. | |
| ############################################################################################### | |
| 2019-06-27 10:16:15.676148 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:16:15.676295 Client::processMessage - request id 7c951738-f69e-497b-bd1a-e6ab0ea2b21a, request type: sip transaction id: e27b05c9-5be9-4cca-a22b-430c0563c7d0, dialog id: | |
| 2019-06-27 10:16:15.676426 ClientController::addApiRequest: clientMsgId 7c951738-f69e-497b-bd1a-e6ab0ea2b21a; size: 1 | |
| 2019-06-27 10:16:15.676659 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:16:15.676742 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId e27b05c9-5be9-4cca-a22b-430c0563c7d0 | |
| 2019-06-27 10:16:15.676815 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d8ce1041a0 | |
| 2019-06-27 10:16:15.676915 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:16:15.677527 makeTags - Adding well-known header 'Call-ID' with value 'lpiKp4Uozz' | |
| 2019-06-27 10:16:15.677701 makeTags - Adding well-known header 'cseq' with value '2 INFO' | |
| 2019-06-27 10:16:15.677790 makeTags - Adding well-known header 'from' with value '"mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0' | |
| 2019-06-27 10:16:15.677847 makeTags - Adding well-known header 'to' with value '<sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r' | |
| 2019-06-27 10:16:15.677920 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:33236 | |
| 2019-06-27 10:16:15.677975 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:33236 | |
| 2019-06-27 10:16:15.678312 tport.c:3531 tport_send_msg() tport_vsend returned 316 | |
| 2019-06-27 10:16:15.678618 send 316 bytes to udp/[172.17.0.1]:33236 at 10:16:15.678026: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKntqzCicGdQ8lljinl9kT61;received=172.17.0.1;rport=33236 | |
| From: "mm2dev-slee" <sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| To: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Call-ID: lpiKp4Uozz | |
| CSeq: 2 INFO | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.678686 nta.c:6939 incoming_reply() nta: sent 200 OK for INFO (2) | |
| 2019-06-27 10:16:15.678746 SipDialogController::doRespondToSipRequest destroying irq 0x55d8ce1041a0 | |
| 2019-06-27 10:16:15.678858 ClientController::removeApiRequest: clientMsgId 7c951738-f69e-497b-bd1a-e6ab0ea2b21a; size: 0 | |
| 2019-06-27 10:16:15.679537 Client::write_handler - wrote 507 bytes: system:0 | |
| 2019-06-27 10:16:15.679816 ClientController::removeNetTransaction: transactionId e27b05c9-5be9-4cca-a22b-430c0563c7d0; size: 0 | |
| 2019-06-27 10:16:15.685464 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.685649 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.685730 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce1025e0 from (udp/172.17.0.2:5060) has 353 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.686079 recv 353 bytes from udp/[172.17.0.1]:33236 at 10:16:15.685787: | |
| BYE sip:192.168.47.161:5060 SIP/2.0 | |
| Content-Length: 0 | |
| To: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Contact: <sip:192.168.46.213:5062;transport=UDP> | |
| CSeq: 3 BYE | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKnWWs2oBn9VRzSVTdzfsZ31 | |
| Call-ID: lpiKp4Uozz | |
| From: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| ############################################################################################### | |
| Our application server aborts the process because there is no MSML in the 200 OK. | |
| ############################################################################################### | |
| 2019-06-27 10:16:15.686175 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce1025e0 (353 bytes) from udp/172.17.0.1:5060 next=(nil) | |
| 2019-06-27 10:16:15.686272 nta.c:3028 agent_recv_request() nta: received BYE sip:192.168.47.161:5060 SIP/2.0 (CSeq 3) | |
| 2019-06-27 10:16:15.686329 nta.c:3323 agent_check_request_via() nta: Via check: received=172.17.0.1 | |
| 2019-06-27 10:16:15.686422 nta.c:3397 agent_aliases() nta: canonizing sip:192.168.47.161:5060 with contact | |
| 2019-06-27 10:16:15.686477 nta.c:3209 agent_recv_request() nta: BYE (3) going to existing leg | |
| 2019-06-27 10:16:15.686591 DrachtioController::processRequestInsideDialog | |
| 2019-06-27 10:16:15.686644 SipDialogController::processRequestInsideDialog: BYE irq 0x55d8ce0f9fd0 | |
| 2019-06-27 10:16:15.686781 ClientController::addNetTransaction: transactionId b4644bee-8a04-4cd1-93e9-3adf0b1f7584; size: 1 | |
| 2019-06-27 10:16:15.686916 Client::write_handler - wrote 563 bytes: system:0 | |
| 2019-06-27 10:16:15.687066 ClientController::removeDialog - after removing dialogs count is now: 1 | |
| 2019-06-27 10:16:15.687122 SipDialogController::addIncomingRequestTransaction - adding transactionId b4644bee-8a04-4cd1-93e9-3adf0b1f7584 for irq:0x55d8ce0f9fd0 | |
| 2019-06-27 10:16:15.687171 SipDialogController::clearSipTimers for lpiKp4Uozz | |
| 2019-06-27 10:16:15.687421 SipDialogController::clearDialog - cleared dialog id lpiKp4Uozz;from-tag=1213582715616305755441.0 referenced from leg 0x55d8ce0ef410 | |
| 2019-06-27 10:16:15.687527 No connected clients found to handle incoming cdr:stop request | |
| 2019-06-27 10:16:15.687600 SipDialog::~SipDialog - destroying sip dialog with call-id lpiKp4Uozz | |
| 2019-06-27 10:16:15.687728 nta.c:4619 nta_leg_destroy() nta_leg_destroy(0x55d8ce0ef410) | |
| 2019-06-27 10:16:15.727142 Client::read_handler read: fdcf82d7-7a60-4e57-8f3e-40e08b38cebd|sip|b4644bee-8a04-4cd1-93e9-3adf0b1f7584| | |
| SIP/2.0 200 OK | |
| Call-ID: lpiKp4Uozz | |
| cseq: 3 BYE | |
| from: "mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| to: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.727368 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:16:15.727436 Client::processMessage - request id fdcf82d7-7a60-4e57-8f3e-40e08b38cebd, request type: sip transaction id: b4644bee-8a04-4cd1-93e9-3adf0b1f7584, dialog id: | |
| 2019-06-27 10:16:15.727500 ClientController::addApiRequest: clientMsgId fdcf82d7-7a60-4e57-8f3e-40e08b38cebd; size: 1 | |
| 2019-06-27 10:16:15.727670 Client::read_handler read: 63c48529-2c63-426a-a436-cb7f33b72d4e|sip||7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| BYE sip:placeholder SIP/2.0 | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.727755 Client::processMessage - got request with 4 tokens | |
| 2019-06-27 10:16:15.727859 Client::processMessage - request id 63c48529-2c63-426a-a436-cb7f33b72d4e, request type: sip transaction id: , dialog id: 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.727889 SipDialogController::doRespondToSipRequest thread 140631196501824 | |
| 2019-06-27 10:16:15.727919 Client::processMessage - sending a request inside a dialog (dialogId provided) | |
| 2019-06-27 10:16:15.727942 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId b4644bee-8a04-4cd1-93e9-3adf0b1f7584 | |
| 2019-06-27 10:16:15.727989 ClientController::addAppTransaction: transactionId 9938102d-b122-4290-9beb-3bc1c8f1d92e; size: 1 | |
| 2019-06-27 10:16:15.727989 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d8ce0f9fd0 | |
| 2019-06-27 10:16:15.728088 ClientController::addApiRequest: clientMsgId 63c48529-2c63-426a-a436-cb7f33b72d4e; size: 2 | |
| 2019-06-27 10:16:15.728138 SipTransport::getContactUri - created Contact header: sip:192.168.47.161:5060 | |
| 2019-06-27 10:16:15.728587 makeTags - Adding well-known header 'Call-ID' with value 'lpiKp4Uozz' | |
| 2019-06-27 10:16:15.728640 makeTags - Adding well-known header 'cseq' with value '3 BYE' | |
| 2019-06-27 10:16:15.728691 makeTags - Adding well-known header 'from' with value '"mm2dev-slee"<sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0' | |
| 2019-06-27 10:16:15.728741 makeTags - Adding well-known header 'to' with value '<sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r' | |
| 2019-06-27 10:16:15.728803 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/172.17.0.1:33236 | |
| 2019-06-27 10:16:15.728843 tport.c:4085 tport_resolve() tport_resolve addrinfo = 172.17.0.1:33236 | |
| 2019-06-27 10:16:15.728960 tport.c:3531 tport_send_msg() tport_vsend returned 315 | |
| 2019-06-27 10:16:15.729068 send 315 bytes to udp/[172.17.0.1]:33236 at 10:16:15.728887: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.46.213:5062;branch=z9hG4bKnWWs2oBn9VRzSVTdzfsZ31;received=172.17.0.1;rport=33236 | |
| From: "mm2dev-slee" <sip:mm2dev-slee@192.168.46.213>;tag=1213582715616305755441.0 | |
| To: <sip:msml@192.168.47.161:5060>;tag=y00FUg16rXt3r | |
| Call-ID: lpiKp4Uozz | |
| CSeq: 3 BYE | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.729113 nta.c:6939 incoming_reply() nta: sent 200 OK for BYE (3) | |
| 2019-06-27 10:16:15.729232 SipDialogController::doRespondToSipRequest destroying irq 0x55d8ce0f9fd0 | |
| 2019-06-27 10:16:15.729393 ClientController::removeApiRequest: clientMsgId fdcf82d7-7a60-4e57-8f3e-40e08b38cebd; size: 1 | |
| 2019-06-27 10:16:15.729476 ClientController::removeNetTransaction: transactionId b4644bee-8a04-4cd1-93e9-3adf0b1f7584; size: 0 | |
| 2019-06-27 10:16:15.729540 SipDialogController::doSendRequestInsideDialog dialog id: 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.730290 SipDialogController::doSendRequestInsideDialog - defaulting request uri to sip:192.168.47.161:5063;transport=UDP | |
| 2019-06-27 10:16:15.730437 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip | |
| 2019-06-27 10:16:15.730596 tport.c:3285 tport_tsend() tport_tsend(0x55d8ce0e55a0) tpn = UDP/192.168.47.161:5063 | |
| 2019-06-27 10:16:15.730664 tport.c:4085 tport_resolve() tport_resolve addrinfo = 192.168.47.161:5063 | |
| 2019-06-27 10:16:15.730927 tport.c:3531 tport_send_msg() tport_vsend returned 331 | |
| 2019-06-27 10:16:15.731155 send 331 bytes to udp/[192.168.47.161]:5063 at 10:16:15.730796: | |
| BYE sip:192.168.47.161:5063;transport=UDP SIP/2.0 | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK3Xr9ZvFUBy5Np | |
| Max-Forwards: 70 | |
| From: <sip:192.168.47.161:5060>;tag=XQ7pSNg3Um4gD | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0116 | |
| Call-ID: 7027dde2-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261496 BYE | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.731351 nta.c:8470 outgoing_send() nta: sent BYE (6261496) to UDP/192.168.47.161:5063 | |
| 2019-06-27 10:16:15.731480 tport.c:4199 tport_pend() tport_pend(0x55d8ce0e55a0): pending 0x55d8ce0f3b40 for udp/172.17.0.2:5060 (already 0) | |
| 2019-06-27 10:16:15.731600 SipDialogController::doSendRequestInsideDialog - created orq 0x55d8ce102200 sending BYE to sip:192.168.47.161:5063;transport=UDP | |
| 2019-06-27 10:16:15.731680 SipDialogController::addRIP adding orq 0x55d8ce102200 | |
| 2019-06-27 10:16:15.731745 No connected clients found to handle incoming cdr:stop request | |
| 2019-06-27 10:16:15.731794 ClientController::removeApiRequest: clientMsgId 63c48529-2c63-426a-a436-cb7f33b72d4e; size: 0 | |
| 2019-06-27 10:16:15.731947 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55d8ce0e55a0): events IN | |
| 2019-06-27 10:16:15.732024 tport.c:2892 tport_recv_event() tport_recv_event(0x55d8ce0e55a0) | |
| 2019-06-27 10:16:15.732085 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55d8ce0e55a0) msg 0x55d8ce0f5940 from (udp/172.17.0.2:5060) has 328 bytes, veclen = 1 | |
| 2019-06-27 10:16:15.732220 recv 328 bytes from udp/[192.168.47.161]:5063 at 10:16:15.732120: | |
| SIP/2.0 200 OK | |
| Via: SIP/2.0/UDP 192.168.47.161;rport;branch=z9hG4bK3Xr9ZvFUBy5Np | |
| From: <sip:192.168.47.161:5060>;tag=XQ7pSNg3Um4gD | |
| To: <sip:1234@192.168.47.161:5063>;tag=45313SIPpTag0116 | |
| Call-ID: 7027dde2-1367-1238-98a7-0242ac110002 | |
| CSeq: 6261496 BYE | |
| Contact: <sip:192.168.47.161:5063;transport=UDP> | |
| Content-Length: 0 | |
| 2019-06-27 10:16:15.732314 tport.c:3051 tport_deliver() tport_deliver(0x55d8ce0e55a0): msg 0x55d8ce0f5940 (328 bytes) from udp/192.168.47.161:5060 next=(nil) | |
| 2019-06-27 10:16:15.732360 nta.c:3448 agent_recv_response() nta: received 200 OK for BYE (6261496) | |
| 2019-06-27 10:16:15.732440 nta.c:3515 agent_recv_response() nta: 200 OK is going to a transaction | |
| 2019-06-27 10:16:15.732488 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 1.901 ms | |
| 2019-06-27 10:16:15.732527 tport.c:4261 tport_release() tport_release(0x55d8ce0e55a0): 0x55d8ce0f3b40 by 0x55d8ce102200 with 0x55d8ce0f5940 | |
| 2019-06-27 10:16:15.732617 SipDialogController::processResponseInsideDialog: | |
| 2019-06-27 10:16:15.732676 SipDialogController::findRIPByOrq orq 0x55d8ce102200 | |
| 2019-06-27 10:16:15.732715 SipDialogController::processResponseInsideDialog: found request for response | |
| 2019-06-27 10:16:15.732773 ClientController::removeAppTransaction: transactionId 9938102d-b122-4290-9beb-3bc1c8f1d92e; size: 0 | |
| 2019-06-27 10:16:15.732855 ClientController::removeDialog - after removing dialogs count is now: 0 | |
| 2019-06-27 10:16:15.732893 SipDialogController::processResponseInsideDialog: clearing dialog after receiving response to BYE or notify w/ subscription-state terminated | |
| 2019-06-27 10:16:15.732924 SipDialogController::clearDialog - cleared dialog id 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.732955 ClientController::removeDialog - dialog not found: 7027dde2-1367-1238-98a7-0242ac110002;from-tag=XQ7pSNg3Um4gD | |
| 2019-06-27 10:16:15.733024 SipDialogController::clearRIP clearing orq 0x55d8ce102200 | |
| 2019-06-27 10:16:15.733069 SipDialog::~SipDialog - destroying sip dialog with call-id 7027dde2-1367-1238-98a7-0242ac110002 | |
| 2019-06-27 10:16:15.733113 nta.c:4619 nta_leg_destroy() nta_leg_destroy(0x55d8ce0f1b00) | |
| 2019-06-27 10:16:15.733410 Client::write_handler - wrote 506 bytes: system:0 | |
| 2019-06-27 10:16:15.733485 Client::write_handler - wrote 522 bytes: system:0 | |
| 2019-06-27 10:16:15.733539 Client::write_handler - wrote 524 bytes: system:0 | |
| 2019-06-27 10:16:15.851698 nta.c:1357 agent_timer() nta: timer set next to 4800 ms | |
| 2019-06-27 10:16:20.653991 nta.c:7281 _nta_incoming_timer() nta: timer I fired, terminate 200 response | |
| 2019-06-27 10:16:20.654133 nta.c:5973 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:16:20.654218 nta.c:7335 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free | |
| 2019-06-27 10:16:20.654413 nta.c:1357 agent_timer() nta: timer set next to 79 ms | |
| 2019-06-27 10:16:20.735111 nta.c:9267 outgoing_timer_dk() nta: timer K fired, terminate BYE (6261496) | |
| 2019-06-27 10:16:20.735241 nta.c:8965 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7ffc67568160) | |
| 2019-06-27 10:16:20.735300 nta.c:9095 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/4 free | |
| 2019-06-27 10:16:20.735366 nta.c:1357 agent_timer() nta: timer set next to 26858 ms |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment