[Dec 4 18:52:55] Asterisk Ready. *CLI> sip debug SIP Debugging enabled *CLI> [Dec 4 18:53:36] <-- SIP read from 192.168.101.9:5060: INVITE sip:s@192.168.101.247:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0 From: sipp ;tag=23618SIPpTag001 To: sut Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE Contact: sip:sipp@192.168.101.9:5060 Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 137 v=0 o=user1 53655765 2353687637 IN IP4 192.168.101.9 s=- c=IN IP4 192.168.101.9 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 0: INVITE sip:s@192.168.101.247:5060 SIP/2.0 (41) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0 (60) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 2: From: sipp ;tag=23618SIPpTag001 (60) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 3: To: sut (36) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 4: Call-ID: 1-23618@192.168.101.9 (30) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 5: CSeq: 1 INVITE (14) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 6: Contact: sip:sipp@192.168.101.9:5060 (36) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 7: Max-Forwards: 70 (16) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 8: Subject: Performance Test (25) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 9: Content-Type: application/sdp (29) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 10: Content-Length: 137 (20) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 11: (0) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: v=0 (3) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: o=user1 53655765 2353687637 IN IP4 192.168.101.9 (48) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: s=- (3) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: c=IN IP4 192.168.101.9 (22) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: t=0 0 (5) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: m=audio 6000 RTP/AVP 0 (22) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 4 18:53:36] --- (11 headers 7 lines) --- [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3201 sip_alloc: Allocating new SIP dialog for 1-23618@192.168.101.9 - INVITE (With RTP) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:11304 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 4 18:53:36] Using INVITE request as basis request - 1-23618@192.168.101.9 [Dec 4 18:53:36] Sending to 192.168.101.9 : 5060 (non-NAT) [Dec 4 18:53:36] Found peer 'sippuas' [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:7379 check_user_full: Setting NAT on RTP to 524288 [Dec 4 18:53:36] Found RTP audio format 0 [Dec 4 18:53:36] Peer audio RTP is at port 192.168.101.9:6000 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3693 process_sdp: Peer audio RTP is at port 192.168.101.9:6000 [Dec 4 18:53:36] Found description format PCMU [Dec 4 18:53:36] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Dec 4 18:53:36] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:10657 handle_request_invite: Checking SIP call limits for device sippuas [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:2237 update_call_counter: Updating call counter for incoming call [Dec 4 18:53:36] Looking for s in test (domain 192.168.101.247) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:6267 build_route: build_route: Contact hop: sip:sipp@192.168.101.9:5060 [Dec 4 18:53:36] list_route: hop: [Dec 4 18:53:36] Transmitting (NAT) to 192.168.101.9:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Dec 4 18:53:36] DEBUG[5373]: chan_sip.c:11847 sip_devicestate: Checking device state for peer sippuas [Dec 4 18:53:36] DEBUG[5373]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'SIP/sippuas-0818fc40' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' [Dec 4 18:53:36] -- Executing Dial("SIP/sippuas-0818fc40", "SIP/sippuas|20") in new stack [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3201 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:1904 create_addr_from_peer: Setting NAT on RTP to 524288 [Dec 4 18:53:36] DEBUG[5386]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-test-s-1. [Dec 4 18:53:36] DEBUG[5386]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Dec 4 18:53:36] DEBUG[5386]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Dec 4 18:53:36] DEBUG[5386]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI. [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:2098 sip_call: Outgoing Call for sippuas [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:2237 update_call_counter: Updating call counter for outgoing call [Dec 4 18:53:36] We're at 192.168.101.247 port 12970 [Dec 4 18:53:36] Adding codec 0x4 (ulaw) to SDP [Dec 4 18:53:36] Adding codec 0x2 (gsm) to SDP [Dec 4 18:53:36] Adding codec 0x8 (alaw) to SDP [Dec 4 18:53:36] Adding non-codec 0x1 (telephone-event) to SDP [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 0: INVITE sip:sippuas@192.168.101.9:5061 SIP/2.0 (45) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK0d9bd5fb;rport (66) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 2: From: "sipp" ;tag=as0ad83f2c (54) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 3: To: (36) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 4: Contact: (35) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 5: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 (57) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 6: CSeq: 102 INVITE (16) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 8: Max-Forwards: 70 (16) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 9: Date: Mon, 04 Dec 2006 21:53:36 GMT (35) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 11: Content-Type: application/sdp (29) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 12: Content-Length: 267 (19) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3452 parse_request: Header 13: (0) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: v=0 (3) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: o=root 5368 5368 IN IP4 192.168.101.247 (39) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: s=session (9) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: c=IN IP4 192.168.101.247 (24) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: t=0 0 (5) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: m=audio 12970 RTP/AVP 0 3 8 101 (31) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 18:53:36] DEBUG[5373]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'SIP/sippuas-08195180' [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:3484 parse_request: Line: a=silenceSupp:off - - - - (25) [Dec 4 18:53:36] 13 headers, 12 lines [Dec 4 18:53:36] Reliably Transmitting (NAT) to 192.168.101.9:5061: INVITE sip:sippuas@192.168.101.9:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK0d9bd5fb;rport From: "sipp" ;tag=as0ad83f2c To: Contact: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 04 Dec 2006 21:53:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 267 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 12970 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:1322 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1 [Dec 4 18:53:36] -- Called sippuas [Dec 4 18:53:36] DEBUG[5373]: devicestate.c:187 do_state_change: Changing state for SIP/sippuas - state 2 (In use) [Dec 4 18:53:36] DEBUG[5387]: app_queue.c:500 changethread: Device 'SIP/sippuas' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 18:53:36] <-- SIP read from 192.168.101.9:5061: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK0d9bd5fb;rport From: "sipp" ;tag=as0ad83f2c To: ;tag=23587SIPpTag011 Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 CSeq: 102 INVITE Contact: Content-Length: 0 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK0d9bd5fb;rport (66) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 2: From: "sipp" ;tag=as0ad83f2c (54) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 3: To: ;tag=23587SIPpTag011 (56) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 4: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 (57) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 6: Contact: (43) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 7: Content-Length: 0 (17) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 8: (0) [Dec 4 18:53:36] --- (8 headers 0 lines) --- [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:1474 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1 - INVITE (got response) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:1483 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '238eba3135513e124d5cb41942bbb945@192.168.101.247' Request 102: Found [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:9721 handle_response_invite: SIP response 180 to standard invite [Dec 4 18:53:36] <-- SIP read from 192.168.101.9:5061: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK0d9bd5fb;rport From: "sipp" ;tag=as0ad83f2c To: ;tag=23587SIPpTag011 Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 CSeq: 102 INVITE Contact: Content-Type: application/sdp Content-Length: 129 v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6001 RTP/AVP 0 a=rtpmap:0 PCMU/8000 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 0: SIP/2.0 200 OK (14) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK0d9bd5fb;rport (66) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 2: From: "sipp" ;tag=as0ad83f2c (54) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 3: To: ;tag=23587SIPpTag011 (56) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 4: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 (57) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 6: Contact: (43) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 7: Content-Type: application/sdp (29) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 8: Content-Length: 129 (20) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 9: (0) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: v=0 (3) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: o=user1 53655765 2353687637 IN IP4 127.0.0.1 (44) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: s=- (3) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: c=IN IP4 127.0.0.1 (18) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: t=0 0 (5) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: m=audio 6001 RTP/AVP 0 (22) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3484 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 4 18:53:36] --- (9 headers 7 lines) --- [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:1407 __sip_ack: Acked pending invite 102 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:1430 __sip_ack: Stopping retransmission on '238eba3135513e124d5cb41942bbb945@192.168.101.247' of Request 102: Match Found [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:9721 handle_response_invite: SIP response 200 to standard invite [Dec 4 18:53:36] Found RTP audio format 0 [Dec 4 18:53:36] Peer audio RTP is at port 127.0.0.1:6001 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3693 process_sdp: Peer audio RTP is at port 127.0.0.1:6001 [Dec 4 18:53:36] Found description format PCMU [Dec 4 18:53:36] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Dec 4 18:53:36] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:6267 build_route: build_route: Contact hop: [Dec 4 18:53:36] list_route: hop: [Dec 4 18:53:36] set_destination: Parsing for address/port to send to [Dec 4 18:53:36] set_destination: set destination to 127.0.0.1, port 5061 [Dec 4 18:53:36] Transmitting (NAT) to 192.168.101.9:5061: ACK sip:127.0.0.1:5061;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK57591a8f;rport From: "sipp" ;tag=as0ad83f2c To: ;tag=23587SIPpTag011 Contact: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Dec 4 18:53:36] DEBUG[5373]: chan_sip.c:11847 sip_devicestate: Checking device state for peer sippuas [Dec 4 18:53:36] DEBUG[5373]: devicestate.c:187 do_state_change: Changing state for SIP/sippuas - state 6 (Ringing) [Dec 4 18:53:36] DEBUG[5388]: app_queue.c:500 changethread: Device 'SIP/sippuas' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Dec 4 18:53:36] -- SIP/sippuas-08195180 is ringing [Dec 4 18:53:36] Transmitting (NAT) to 192.168.101.9:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Dec 4 18:53:36] -- SIP/sippuas-08195180 answered SIP/sippuas-0818fc40 [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:2580 sip_answer: sip_answer(SIP/sippuas-0818fc40) [Dec 4 18:53:36] We're at 192.168.101.247 port 14010 [Dec 4 18:53:36] Adding codec 0x4 (ulaw) to SDP [Dec 4 18:53:36] Reliably Transmitting (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:1322 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #2 [Dec 4 18:53:36] -- Attempting native bridge of SIP/sippuas-0818fc40 and SIP/sippuas-08195180 [Dec 4 18:53:36] DEBUG[5373]: chan_sip.c:11847 sip_devicestate: Checking device state for peer sippuas [Dec 4 18:53:36] DEBUG[5373]: devicestate.c:187 do_state_change: Changing state for SIP/sippuas - state 2 (In use) [Dec 4 18:53:36] DEBUG[5389]: app_queue.c:500 changethread: Device 'SIP/sippuas' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 18:53:36] DEBUG[5373]: chan_sip.c:11847 sip_devicestate: [Dec 4 18:53:36] <-- SIP read from 192.168.101.9:5060: BYE sip:s@192.168.101.247:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-5 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 2 BYE Contact: sip:sipp@192.168.101.9:5060 Max-Forwards: 70 Subject: Performance Test Content-Length: 0 Checking device state for peer sippuas [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 0: BYE sip:s@192.168.101.247:5060 SIP/2.0 (38) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-5 (60) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 2: From: sipp ;tag=23618SIPpTag001 (60) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 3: To: sut ;tag=as6ac9adc3 (51) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 4: Call-ID: 1-23618@192.168.101.9 (30) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 5: CSeq: 2 BYE (11) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 6: Contact: sip:sipp@192.168.101.9:5060 (36) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 7: Max-Forwards: 70 (16) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 8: Subject: Performance Test (25) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 9: Content-Length: 0 (17) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 10: (0) [Dec 4 18:53:36] --- (10 headers 0 lines) --- [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:11304 handle_request: **** Received BYE (8) - Command in SIP BYE [Dec 4 18:53:36] Sending to 192.168.101.9 : 5060 (NAT) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:10957 handle_request_bye: Received bye, issuing owner hangup . [Dec 4 18:53:36] Transmitting (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-5;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 2 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- [Dec 4 18:53:36] DEBUG[5373]: devicestate.c:187 do_state_change: Changing state for SIP/sippuas - state 2 (In use) [Dec 4 18:53:36] DEBUG[5390]: app_queue.c:500 changethread: Device 'SIP/sippuas' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 18:53:36] DEBUG[5386]: channel.c:3377 ast_generic_bridge: Didn't get a frame from channel: SIP/sippuas-0818fc40 [Dec 4 18:53:36] DEBUG[5386]: channel.c:3575 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/sippuas-0818fc40, c1=SIP/sippuas-08195180, flags: No,Yes,No,No [Dec 4 18:53:36] DEBUG[5386]: channel.c:3664 ast_channel_bridge: Bridge stops bridging channels SIP/sippuas-0818fc40 and SIP/sippuas-08195180 [Dec 4 18:53:36] DEBUG[5386]: channel.c:1367 ast_hangup: Hanging up channel 'SIP/sippuas-08195180' [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:2447 sip_hangup: Hangup call SIP/sippuas-08195180, SIP callid 238eba3135513e124d5cb41942bbb945@192.168.101.247) [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:2456 sip_hangup: update_call_counter(sippuas) - decrement call limit counter [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:2237 update_call_counter: Updating call counter for outgoing call [Dec 4 18:53:36] Scheduling destruction of call '238eba3135513e124d5cb41942bbb945@192.168.101.247' in 32000 ms [Dec 4 18:53:36] set_destination: Parsing for address/port to send to [Dec 4 18:53:36] set_destination: set destination to 127.0.0.1, port 5061 [Dec 4 18:53:36] Reliably Transmitting (NAT) to 192.168.101.9:5061: BYE sip:127.0.0.1:5061;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK220f8bc0;rport From: "sipp" ;tag=as0ad83f2c To: ;tag=23587SIPpTag011 Contact: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Dec 4 18:53:36] DEBUG[5386]: chan_sip.c:1322 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4 [Dec 4 18:53:36] DEBUG[5386]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 4 18:53:36] DEBUG[5386]: pbx.c:2316 __ast_pbx_run: Spawn extension (test,s,1) exited non-zero on 'SIP/sippuas-0818fc40' [Dec 4 18:53:36] == Spawn extension (test, s, 1) exited non-zero on 'SIP/sippuas-0818fc40' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"sipp" ' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'sipp' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: [Dec 4 18:53:36] <-- SIP read from 192.168.101.9:5061: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK220f8bc0;rport From: "sipp" ;tag=as0ad83f2c To: ;tag=23587SIPpTag011 Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 CSeq: 103 BYE Contact: Content-Length: 0 Function result is 's' [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 0: SIP/2.0 200 OK (14) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.101.247:5060;branch=z9hG4bK220f8bc0;rport (66) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 2: From: "sipp" ;tag=as0ad83f2c (54) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 3: To: ;tag=23587SIPpTag011 (56) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 4: Call-ID: 238eba3135513e124d5cb41942bbb945@192.168.101.247 (57) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 5: CSeq: 103 BYE (13) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 6: Contact: (43) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 7: Content-Length: 0 (17) [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:3452 parse_request: Header 8: (0) [Dec 4 18:53:36] --- (8 headers 0 lines) --- [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:1418 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4 [Dec 4 18:53:36] DEBUG[5379]: chan_sip.c:1430 __sip_ack: Stopping retransmission on '238eba3135513e124d5cb41942bbb945@192.168.101.247' of Request 103: Match Found [Dec 4 18:53:36] Destroying call '238eba3135513e124d5cb41942bbb945@192.168.101.247' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'test' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/sippuas-0818fc40' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/sippuas-08195180' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/sippuas|20' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 18:53:36' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 18:53:36' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 18:53:36' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165269216.0' [Dec 4 18:53:36] DEBUG[5386]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 18:53:36] DEBUG[5386]: channel.c:1367 ast_hangup: Hanging up channel 'SIP/sippuas-0818fc40' [Dec 4 18:53:36] == Parsing '/etc/asterisk/logger.conf': Parsing /etc/asterisk/logger.conf [Dec 4 18:53:36] Found [Dec 4 18:53:36] Asterisk Event Logger restarted [Dec 4 18:53:37] Asterisk Queue Logger restarted [Dec 4 18:53:37] DEBUG[5373]: chan_sip.c:11847 sip_devicestate: Checking device state for peer sippuas [Dec 4 18:53:37] DEBUG[5373]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'SIP/sippuas-0818fc40' [Dec 4 18:53:37] Rotated Logs Per SIGXFSZ (Exceeded file size limit) [Dec 4 18:53:37] DEBUG[5386]: chan_sip.c:2447 sip_hangup: Hangup call SIP/sippuas-0818fc40, SIP callid 1-23618@192.168.101.9) [Dec 4 18:53:37] DEBUG[5386]: chan_sip.c:2456 sip_hangup: update_call_counter(sippuas) - decrement call limit counter [Dec 4 18:53:37] DEBUG[5386]: chan_sip.c:2237 update_call_counter: Updating call counter for incoming call [Dec 4 18:53:37] DEBUG[5373]: devicestate.c:187 do_state_change: Changing state for SIP/sippuas - state 1 (Not in use) [Dec 4 18:53:37] DEBUG[5391]: app_queue.c:500 changethread: Device 'SIP/sippuas' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 4 18:53:37] DEBUG[5373]: chan_sip.c:11847 sip_devicestate: Checking device state for peer sippuas [Dec 4 18:53:37] DEBUG[5373]: devicestate.c:187 do_state_change: Changing state for SIP/sippuas - state 1 (Not in use) [Dec 4 18:53:37] DEBUG[5392]: app_queue.c:500 changethread: Device 'SIP/sippuas' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 4 18:53:37] DEBUG[5379]: chan_sip.c:1210 retrans_pkt: SIP TIMER: Rescheduling retransmission #2 (1) SIP/2.0 - 1 [Dec 4 18:53:37] DEBUG[5379]: chan_sip.c:1224 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #2)) [Dec 4 18:53:37] Retransmitting #1 (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:38] DEBUG[5379]: chan_sip.c:1210 retrans_pkt: SIP TIMER: Rescheduling retransmission #2 (2) SIP/2.0 - 1 [Dec 4 18:53:38] DEBUG[5379]: chan_sip.c:1224 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #2)) [Dec 4 18:53:38] Retransmitting #2 (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:40] DEBUG[5379]: chan_sip.c:1210 retrans_pkt: SIP TIMER: Rescheduling retransmission #2 (3) SIP/2.0 - 1 [Dec 4 18:53:40] DEBUG[5379]: chan_sip.c:1224 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #2)) [Dec 4 18:53:40] Retransmitting #3 (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:44] DEBUG[5379]: chan_sip.c:1210 retrans_pkt: SIP TIMER: Rescheduling retransmission #2 (4) SIP/2.0 - 1 [Dec 4 18:53:44] DEBUG[5379]: chan_sip.c:1224 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #2)) [Dec 4 18:53:44] Retransmitting #4 (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:48] DEBUG[5379]: chan_sip.c:1210 retrans_pkt: SIP TIMER: Rescheduling retransmission #2 (5) SIP/2.0 - 1 [Dec 4 18:53:48] DEBUG[5379]: chan_sip.c:1224 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #2)) [Dec 4 18:53:48] Retransmitting #5 (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:52] DEBUG[5379]: chan_sip.c:1210 retrans_pkt: SIP TIMER: Rescheduling retransmission #2 (6) SIP/2.0 - 1 [Dec 4 18:53:52] DEBUG[5379]: chan_sip.c:1224 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #2)) [Dec 4 18:53:52] Retransmitting #6 (NAT) to 192.168.101.9:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.101.9:5060;branch=z9hG4bK-23618-1-0;received=192.168.101.9 From: sipp ;tag=23618SIPpTag001 To: sut ;tag=as6ac9adc3 Call-ID: 1-23618@192.168.101.9 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 164 v=0 o=root 5368 5368 IN IP4 192.168.101.247 s=session c=IN IP4 192.168.101.247 t=0 0 m=audio 14010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- [Dec 4 18:53:56] WARNING[5379]: chan_sip.c:1243 retrans_pkt: Maximum retries exceeded on transmission 1-23618@192.168.101.9 for seqno 1 (Critical Response) [Dec 4 18:53:56] Destroying call '1-23618@192.168.101.9'