[2009-09-03 07:06:26.3786] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> INVITE sip:22600@192.168.1.93;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585960238 Max-Forwards: 70 From: ;tag=1c585956343 To: Call-ID: 585956038112000176@192.168.0.37 CSeq: 1 INVITE Contact: Supported: em,100rel,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Authorization: Digest username="90027",realm="asterisk",nonce="58b7884b",uri="sip:22600@192.168.1.93",algorithm=MD5,response="a36a4204620db6af121498489bbae60a" User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Type: application/sdp Content-Length: 299 v=0 o=AudiocodesGW 585951917 585951836 IN IP4 192.168.0.37 s=Phone-Call c=IN IP4 192.168.0.37 t=0 0 m=audio 6000 RTP/AVP 0 8 18 96 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 a=ptime:20 a=sendrecv <-------------> [2009-09-03 07:06:26.3792] VERBOSE[24359] chan_sip.c: --- (14 headers 14 lines) --- [2009-09-03 07:06:26.3799] VERBOSE[24359] netsock.c: == Using SIP RTP TOS bits 24 [2009-09-03 07:06:26.3801] VERBOSE[24359] netsock.c: == Using SIP RTP CoS mark 5 [2009-09-03 07:06:26.3803] VERBOSE[24359] netsock.c: == Using UDPTL TOS bits 24 [2009-09-03 07:06:26.3805] VERBOSE[24359] netsock.c: == Using UDPTL CoS mark 5 [2009-09-03 07:06:26.3807] DEBUG[24359] chan_sip.c: Setting NAT on RTP to Off [2009-09-03 07:06:26.3808] DEBUG[24359] chan_sip.c: Setting NAT on UDPTL to Off [2009-09-03 07:06:26.3809] DEBUG[24359] chan_sip.c: Allocating new SIP dialog for 585956038112000176@192.168.0.37 - INVITE (With RTP) [2009-09-03 07:06:26.3810] VERBOSE[24359] chan_sip.c: Sending to 192.168.0.37 : 5060 (no NAT) [2009-09-03 07:06:26.3812] DEBUG[24359] chan_sip.c: Initializing initreq for method INVITE - callid 585956038112000176@192.168.0.37 [2009-09-03 07:06:26.3813] VERBOSE[24359] chan_sip.c: Using INVITE request as basis request - 585956038112000176@192.168.0.37 [2009-09-03 07:06:26.3815] VERBOSE[24359] chan_sip.c: Found peer '90027' for '90027' from 192.168.0.37:5060 [2009-09-03 07:06:26.3817] DEBUG[24359] chan_sip.c: Setting NAT on RTP to On [2009-09-03 07:06:26.3818] DEBUG[24359] chan_sip.c: Setting NAT on UDPTL to On [2009-09-03 07:06:26.3819] VERBOSE[24359] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.0.37:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585960238;received=192.168.0.37 From: ;tag=1c585956343 To: ;tag=as647a2039 Call-ID: 585956038112000176@192.168.0.37 CSeq: 1 INVITE Server: Asterisk PBX 1.6.1.5 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="01615441" Content-Length: 0 <------------> [2009-09-03 07:06:26.3823] DEBUG[24359] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:26.3824] VERBOSE[24359] chan_sip.c: Scheduling destruction of SIP dialog '585956038112000176@192.168.0.37' in 32000 ms (Method: INVITE) [2009-09-03 07:06:26.3967] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> ACK sip:22600@192.168.1.93;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585960238 Max-Forwards: 70 From: ;tag=1c585956343 To: ;tag=as647a2039 Call-ID: 585956038112000176@192.168.0.37 CSeq: 1 ACK Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Length: 0 <-------------> [2009-09-03 07:06:26.3971] VERBOSE[24359] chan_sip.c: --- (12 headers 0 lines) --- [2009-09-03 07:06:26.3973] DEBUG[24359] chan_sip.c: Stopping retransmission on '585956038112000176@192.168.0.37' of Response 1: Match Found [2009-09-03 07:06:26.4005] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> INVITE sip:22600@192.168.1.93;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585987921 Max-Forwards: 70 From: ;tag=1c585956343 To: Call-ID: 585956038112000176@192.168.0.37 CSeq: 2 INVITE Contact: Supported: em,100rel,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Authorization: Digest username="90027",realm="asterisk",nonce="01615441",uri="sip:22600@192.168.1.93",algorithm=MD5,response="b29bfef10daa9106e1b524ac97895130" User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Type: application/sdp Content-Length: 299 v=0 o=AudiocodesGW 585951917 585951836 IN IP4 192.168.0.37 s=Phone-Call c=IN IP4 192.168.0.37 t=0 0 m=audio 6000 RTP/AVP 0 8 18 96 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 a=ptime:20 a=sendrecv <-------------> [2009-09-03 07:06:26.4010] VERBOSE[24359] chan_sip.c: --- (14 headers 14 lines) --- [2009-09-03 07:06:26.4012] VERBOSE[24359] chan_sip.c: Sending to 192.168.0.37 : 5060 (NAT) [2009-09-03 07:06:26.4014] DEBUG[24359] chan_sip.c: Initializing initreq for method INVITE - callid 585956038112000176@192.168.0.37 [2009-09-03 07:06:26.4015] VERBOSE[24359] chan_sip.c: Using INVITE request as basis request - 585956038112000176@192.168.0.37 [2009-09-03 07:06:26.4017] VERBOSE[24359] chan_sip.c: Found peer '90027' for '90027' from 192.168.0.37:5060 [2009-09-03 07:06:26.4019] DEBUG[24359] chan_sip.c: Setting NAT on RTP to On [2009-09-03 07:06:26.4020] DEBUG[24359] chan_sip.c: Setting NAT on UDPTL to On [2009-09-03 07:06:26.4023] VERBOSE[24359] chan_sip.c: Found RTP audio format 0 [2009-09-03 07:06:26.4024] VERBOSE[24359] chan_sip.c: Found RTP audio format 8 [2009-09-03 07:06:26.4026] VERBOSE[24359] chan_sip.c: Found RTP audio format 18 [2009-09-03 07:06:26.4028] VERBOSE[24359] chan_sip.c: Found RTP audio format 96 [2009-09-03 07:06:26.4030] DEBUG[24359] chan_sip.c: Peer doesn't provide T.38 UDPTL [2009-09-03 07:06:26.4031] VERBOSE[24359] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6000 [2009-09-03 07:06:26.4033] VERBOSE[24359] chan_sip.c: Found audio description format PCMU for ID 0 [2009-09-03 07:06:26.4035] VERBOSE[24359] chan_sip.c: Found audio description format PCMA for ID 8 [2009-09-03 07:06:26.4037] VERBOSE[24359] chan_sip.c: Found audio description format G729 for ID 18 [2009-09-03 07:06:26.4039] VERBOSE[24359] chan_sip.c: Found audio description format telephone-event for ID 96 [2009-09-03 07:06:26.4041] VERBOSE[24359] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [2009-09-03 07:06:26.4043] VERBOSE[24359] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2009-09-03 07:06:26.4046] VERBOSE[24359] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6000 [2009-09-03 07:06:26.4047] DEBUG[24359] chan_sip.c: Checking SIP call limits for device 90027 [2009-09-03 07:06:26.4051] VERBOSE[24359] chan_sip.c: Looking for 22600 in default-sip (domain 192.168.1.93) [2009-09-03 07:06:26.4055] VERBOSE[24359] chan_sip.c: list_route: hop: [2009-09-03 07:06:26.4058] VERBOSE[24359] chan_sip.c: <--- Transmitting (NAT) to 192.168.0.37:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585987921;received=192.168.0.37 From: ;tag=1c585956343 To: Call-ID: 585956038112000176@192.168.0.37 CSeq: 2 INVITE Server: Asterisk PBX 1.6.1.5 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [2009-09-03 07:06:26.4061] DEBUG[24359] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:26.4068] DEBUG[24363] pbx.c: Launching 'NoOp' [2009-09-03 07:06:26.4069] VERBOSE[24363] pbx.c: -- Executing [22600@default-sip:1] NoOp("SIP/90027-089d5e88", "-(B)------------------------------------- context default_from_local ---------------") in new stack ... [2009-09-03 07:06:26.6884] DEBUG[24363] pbx.c: Launching 'Dial' [2009-09-03 07:06:26.6885] VERBOSE[24363] pbx.c: -- Executing [22600@local_dial:87] Dial("SIP/90027-089d5e88", "SIP/90028,30,gtiU(agent_call_answer^22600)") in new stack [2009-09-03 07:06:26.6889] DEBUG[24363] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [2009-09-03 07:06:26.6894] VERBOSE[24363] netsock.c: == Using SIP RTP TOS bits 24 [2009-09-03 07:06:26.6896] VERBOSE[24363] netsock.c: == Using SIP RTP CoS mark 5 [2009-09-03 07:06:26.6898] VERBOSE[24363] netsock.c: == Using UDPTL TOS bits 24 [2009-09-03 07:06:26.6900] VERBOSE[24363] netsock.c: == Using UDPTL CoS mark 5 [2009-09-03 07:06:26.6903] DEBUG[24363] chan_sip.c: Allocating new SIP dialog for 6dc4863737d703bb25acfa18705acbf0@127.0.0.1 - INVITE (With RTP) [2009-09-03 07:06:26.6904] DEBUG[24363] chan_sip.c: Setting NAT on RTP to On [2009-09-03 07:06:26.6905] DEBUG[24363] chan_sip.c: Setting NAT on UDPTL to On [2009-09-03 07:06:26.6905] DEBUG[24363] chan_sip.c: OBPROXY: Not applying OBproxy to this call ... copying variables ... [2009-09-03 07:06:26.7085] DEBUG[24363] chan_sip.c: Outgoing Call for 90028 [2009-09-03 07:06:26.7091] DEBUG[24363] chan_sip.c: ** Our capability: 0xc7f9afe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140) Video flag: False Text flag: False [2009-09-03 07:06:26.7092] DEBUG[24363] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [2009-09-03 07:06:26.7092] VERBOSE[24363] chan_sip.c: Audio is at 192.168.1.93 port 44120 [2009-09-03 07:06:26.7096] VERBOSE[24363] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2009-09-03 07:06:26.7098] VERBOSE[24363] chan_sip.c: Adding codec 0x2 (gsm) to SDP [2009-09-03 07:06:26.7100] VERBOSE[24363] chan_sip.c: Adding codec 0x8 (alaw) to SDP [2009-09-03 07:06:26.7102] VERBOSE[24363] chan_sip.c: Adding codec 0x10 (g726aal2) to SDP [2009-09-03 07:06:26.7104] VERBOSE[24363] chan_sip.c: Adding codec 0x20 (adpcm) to SDP [2009-09-03 07:06:26.7105] VERBOSE[24363] chan_sip.c: Adding codec 0x40 (slin) to SDP [2009-09-03 07:06:26.7107] VERBOSE[24363] chan_sip.c: Adding codec 0x80 (lpc10) to SDP [2009-09-03 07:06:26.7109] VERBOSE[24363] chan_sip.c: Adding codec 0x200 (speex) to SDP [2009-09-03 07:06:26.7111] VERBOSE[24363] chan_sip.c: Adding codec 0x800 (g726) to SDP [2009-09-03 07:06:26.7113] VERBOSE[24363] chan_sip.c: Adding codec 0x1000 (g722) to SDP [2009-09-03 07:06:26.7115] VERBOSE[24363] chan_sip.c: Adding codec 0x8000 (slin16) to SDP [2009-09-03 07:06:26.7117] VERBOSE[24363] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2009-09-03 07:06:26.7120] DEBUG[24363] chan_sip.c: Initializing initreq for method INVITE - callid 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 [2009-09-03 07:06:26.7121] VERBOSE[24363] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.37:5060: INVITE sip:90028@192.168.0.37 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK689f604d;rport Max-Forwards: 70 From: "Victor Negru" ;tag=as16bdb286 To: Contact: Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.1.5 Date: Thu, 03 Sep 2009 14:06:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Type: application/sdp Content-Length: 500 v=0 o=root 450098132 450098132 IN IP4 192.168.1.93 s=Asterisk PBX 1.6.1.5 c=IN IP4 192.168.1.93 t=0 0 m=audio 44120 RTP/AVP 0 3 8 112 5 10 7 110 111 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:112 AAL2-G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:10 L16/8000 a=rtpmap:7 LPC/8000 a=rtpmap:110 speex/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [2009-09-03 07:06:26.7125] DEBUG[24363] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:26.7127] VERBOSE[24363] app_dial.c: -- Called 90028 [2009-09-03 07:06:26.7611] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK689f604d;rport From: "Victor Negru" ;tag=as16bdb286 To: ;tag=1c586423056 Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 102 INVITE Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Length: 0 <-------------> [2009-09-03 07:06:26.7612] VERBOSE[24359] chan_sip.c: --- (10 headers 0 lines) --- [2009-09-03 07:06:26.7614] DEBUG[24359] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0cb3a1345aa8f6836dd920a050964d12@192.168.1.93' Request 102: Found [2009-09-03 07:06:26.7674] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK689f604d;rport From: "Victor Negru" ;tag=as16bdb286 To: ;tag=1c586423056 Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 102 INVITE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Length: 0 <-------------> [2009-09-03 07:06:26.7675] VERBOSE[24359] chan_sip.c: --- (11 headers 0 lines) --- [2009-09-03 07:06:26.7675] DEBUG[24359] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0cb3a1345aa8f6836dd920a050964d12@192.168.1.93' Request 102: Found [2009-09-03 07:06:26.7684] VERBOSE[24363] app_dial.c: -- SIP/90028-08a08e48 is ringing [2009-09-03 07:06:26.7687] VERBOSE[24363] chan_sip.c: <--- Transmitting (NAT) to 192.168.0.37:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585987921;received=192.168.0.37 From: ;tag=1c585956343 To: ;tag=as39f2e056 Call-ID: 585956038112000176@192.168.0.37 CSeq: 2 INVITE Server: Asterisk PBX 1.6.1.5 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [2009-09-03 07:06:26.7690] DEBUG[24363] chan_sip.c: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:28.2203] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK689f604d;rport From: "Victor Negru" ;tag=as16bdb286 To: ;tag=1c586423056 Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 102 INVITE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Type: application/sdp Content-Length: 231 v=0 o=AudiocodesGW 586437061 586436981 IN IP4 192.168.0.37 s=Phone-Call c=IN IP4 192.168.0.37 t=0 0 m=audio 6010 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [2009-09-03 07:06:28.2205] VERBOSE[24359] chan_sip.c: --- (12 headers 11 lines) --- [2009-09-03 07:06:28.2206] DEBUG[24359] chan_sip.c: Acked pending invite 102 [2009-09-03 07:06:28.2206] DEBUG[24359] chan_sip.c: Stopping retransmission on '0cb3a1345aa8f6836dd920a050964d12@192.168.1.93' of Request 102: Match Found [2009-09-03 07:06:28.2207] VERBOSE[24359] chan_sip.c: Found RTP audio format 0 [2009-09-03 07:06:28.2208] VERBOSE[24359] chan_sip.c: Found RTP audio format 101 [2009-09-03 07:06:28.2209] DEBUG[24359] chan_sip.c: Peer doesn't provide T.38 UDPTL [2009-09-03 07:06:28.2209] VERBOSE[24359] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6010 [2009-09-03 07:06:28.2210] VERBOSE[24359] chan_sip.c: Found audio description format PCMU for ID 0 [2009-09-03 07:06:28.2210] VERBOSE[24359] chan_sip.c: Found audio description format telephone-event for ID 101 [2009-09-03 07:06:28.2211] VERBOSE[24359] chan_sip.c: Capabilities: us - 0xc7f9fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [2009-09-03 07:06:28.2211] VERBOSE[24359] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2009-09-03 07:06:28.2212] VERBOSE[24359] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6010 [2009-09-03 07:06:28.2213] VERBOSE[24359] chan_sip.c: list_route: hop: [2009-09-03 07:06:28.2214] DEBUG[24359] chan_sip.c: Strict routing enforced for session 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 [2009-09-03 07:06:28.2215] VERBOSE[24359] chan_sip.c: set_destination: Parsing for address/port to send to [2009-09-03 07:06:28.2215] VERBOSE[24359] chan_sip.c: set_destination: set destination to 192.168.0.37, port 5060 [2009-09-03 07:06:28.2216] VERBOSE[24359] chan_sip.c: Transmitting (NAT) to 192.168.0.37:5060: ACK sip:90028@192.168.0.37 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK19369de7;rport Max-Forwards: 70 From: "Victor Negru" ;tag=as16bdb286 To: ;tag=1c586423056 Contact: Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 102 ACK User-Agent: Asterisk PBX 1.6.1.5 Content-Length: 0 --- [2009-09-03 07:06:28.2216] DEBUG[24359] chan_sip.c: Trying to put 'ACK sip:90' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:28.2234] VERBOSE[24363] app_dial.c: -- SIP/90028-08a08e48 answered SIP/90027-089d5e88 [2009-09-03 07:06:28.2238] DEBUG[24363] app_stack.c: Channel SIP/90028-08a08e48 has no datastore, so we're allocating one. [2009-09-03 07:06:28.2239] DEBUG[24363] app_stack.c: Setting 'ARG1' to '22600' [2009-09-03 07:06:28.2241] DEBUG[24363] pbx.c: Launching 'Set' [2009-09-03 07:06:28.2242] VERBOSE[24363] pbx.c: -- Executing [s@agent_call_answer:1] Set("SIP/90028-08a08e48", "LOCAL(agent_answered)=22600") in new stack [2009-09-03 07:06:28.2245] DEBUG[24363] pbx.c: Launching 'NoOp' [2009-09-03 07:06:28.2246] VERBOSE[24363] pbx.c: -- Executing [s@agent_call_answer:2] NoOp("SIP/90028-08a08e48", "--(B)--------------------------- agent_call_answer(22600)------------------------") in new stack ... dialplan ... [2009-09-03 07:06:28.2940] DEBUG[24363] pbx.c: Launching 'Return' [2009-09-03 07:06:28.2941] VERBOSE[24363] pbx.c: -- Executing [s@agent_call_answer:14] Return("SIP/90028-08a08e48", "") in new stack [2009-09-03 07:06:28.2944] DEBUG[24363] pbx.c: Launching 'NoOp' [2009-09-03 07:06:28.2945] VERBOSE[24363] pbx.c: -- Executing [s@app_dial_gosub_virtual_context:1] NoOp("SIP/90028-08a08e48", "") in new stack [2009-09-03 07:06:28.2948] VERBOSE[24363] pbx.c: -- Auto fallthrough, channel 'SIP/90028-08a08e48' status is 'UNKNOWN' [2009-09-03 07:06:28.2950] DEBUG[24363] app_dial.c: Gosub exited with status 0 [2009-09-03 07:06:28.2956] DEBUG[24363] chan_sip.c: SIP answering channel: SIP/90027-089d5e88 [2009-09-03 07:06:28.2957] DEBUG[24363] chan_sip.c: Setting framing from config on incoming call [2009-09-03 07:06:28.2958] DEBUG[24363] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2009-09-03 07:06:28.2959] DEBUG[24363] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2009-09-03 07:06:28.2960] VERBOSE[24363] chan_sip.c: Audio is at 192.168.1.93 port 47828 [2009-09-03 07:06:28.2962] VERBOSE[24363] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2009-09-03 07:06:28.2964] VERBOSE[24363] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2009-09-03 07:06:28.2966] VERBOSE[24363] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.0.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac585987921;received=192.168.0.37 From: ;tag=1c585956343 To: ;tag=as39f2e056 Call-ID: 585956038112000176@192.168.0.37 CSeq: 2 INVITE Server: Asterisk PBX 1.6.1.5 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Content-Length: 260 v=0 o=root 2025335659 2025335659 IN IP4 192.168.1.93 s=Asterisk PBX 1.6.1.5 c=IN IP4 192.168.1.93 t=0 0 m=audio 47828 RTP/AVP 0 96 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [2009-09-03 07:06:28.2970] DEBUG[24363] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:28.2975] DEBUG[24363] rtp.c: Got RTCP report of 44 bytes [2009-09-03 07:06:28.2977] DEBUG[24363] rtp.c: Ooh, format changed from unknown to ulaw [2009-09-03 07:06:28.2978] DEBUG[24363] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2009-09-03 07:06:28.3357] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> ACK sip:22600@192.168.1.93 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac588406002 Max-Forwards: 70 From: ;tag=1c585956343 To: ;tag=as39f2e056 Call-ID: 585956038112000176@192.168.0.37 CSeq: 2 ACK Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Length: 0 <-------------> [2009-09-03 07:06:28.3361] VERBOSE[24359] chan_sip.c: --- (12 headers 0 lines) --- [2009-09-03 07:06:28.3362] DEBUG[24359] chan_sip.c: Stopping retransmission on '585956038112000176@192.168.0.37' of Response 2: Match Found [2009-09-03 07:06:28.3493] DEBUG[24363] rtp.c: Ooh, format changed from unknown to ulaw [2009-09-03 07:06:28.3495] DEBUG[24363] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2009-09-03 07:06:28.3496] DEBUG[24363] rtp.c: Got RTCP report of 68 bytes [2009-09-03 07:06:32.1894] DEBUG[24363] rtp.c: Got RTCP report of 68 bytes [2009-09-03 07:06:32.2452] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> BYE sip:22600@192.168.1.93 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac593294492 Max-Forwards: 70 From: ;tag=1c585956343 To: ;tag=as39f2e056 Call-ID: 585956038112000176@192.168.0.37 CSeq: 3 BYE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Authorization: Digest username="90027",realm="asterisk",nonce="01615441",uri="sip:22600@192.168.1.93",algorithm=MD5,response="0f5e8f2d56e67077c86b57ffcaca5403" User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Reason: Q.850 ;cause=16 Content-Length: 0 <-------------> [2009-09-03 07:06:32.2453] VERBOSE[24359] chan_sip.c: --- (14 headers 0 lines) --- [2009-09-03 07:06:32.2454] DEBUG[24359] chan_sip.c: Initializing initreq for method BYE - callid 585956038112000176@192.168.0.37 [2009-09-03 07:06:32.2455] VERBOSE[24359] chan_sip.c: Sending to 192.168.0.37 : 5060 (NAT) [2009-09-03 07:06:32.2459] VERBOSE[24359] chan_sip.c: <--- Transmitting (NAT) to 192.168.0.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.37;branch=z9hG4bKac593294492;received=192.168.0.37 From: ;tag=1c585956343 To: ;tag=as39f2e056 Call-ID: 585956038112000176@192.168.0.37 CSeq: 3 BYE Server: Asterisk PBX 1.6.1.5 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [2009-09-03 07:06:32.2460] DEBUG[24359] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:32.2468] DEBUG[24363] channel.c: Didn't get a frame from channel: SIP/90027-089d5e88 [2009-09-03 07:06:32.2470] DEBUG[24363] channel.c: Bridge stops bridging channels SIP/90027-089d5e88 and SIP/90028-08a08e48 [2009-09-03 07:06:32.2474] DEBUG[24363] cdr_addon_mysql.c: Inserting a CDR record. [2009-09-03 07:06:32.2475] DEBUG[24363] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr_post (calldate,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2009-09-03 07:06:26','22609','22600','local_dial','SIP/90027-089d5e88','SIP/90028-08a08e48','Dial','SIP/90028,30,gtiU(agent_call_answer^22600)','6','4','ANSWERED','3','1251986786.0','1251986786.0','#call_id=1251986786.0-1#agent=22600#t_id=35422#t_ext=90028#t_ext_id=34575#t_wg=1#t_dpt=1#s_type=agent#s_num=22609#s_id=35686#s_ext=90027#s_ext_id=34574#s_wg=1#s_dpt=1') [2009-09-03 07:06:32.2480] DEBUG[24363] channel.c: Hanging up channel 'SIP/90028-08a08e48' [2009-09-03 07:06:32.2481] DEBUG[24363] chan_sip.c: Hangup call SIP/90028-08a08e48, SIP callid 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 [2009-09-03 07:06:32.2482] DEBUG[24363] chan_sip.c: update_call_counter(90028) - decrement call limit counter on hangup [2009-09-03 07:06:32.2486] VERBOSE[24363] chan_sip.c: Scheduling destruction of SIP dialog '0cb3a1345aa8f6836dd920a050964d12@192.168.1.93' in 32000 ms (Method: INVITE) [2009-09-03 07:06:32.2490] DEBUG[24363] chan_sip.c: Strict routing enforced for session 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 [2009-09-03 07:06:32.2491] VERBOSE[24363] chan_sip.c: set_destination: Parsing for address/port to send to [2009-09-03 07:06:32.2493] VERBOSE[24363] chan_sip.c: set_destination: set destination to 192.168.0.37, port 5060 [2009-09-03 07:06:32.2495] VERBOSE[24363] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.37:5060: BYE sip:90028@192.168.0.37 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK38cf63ce;rport Max-Forwards: 70 From: "Victor Negru" ;tag=as16bdb286 To: ;tag=1c586423056 Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 103 BYE User-Agent: Asterisk PBX 1.6.1.5 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [2009-09-03 07:06:32.2498] DEBUG[24363] chan_sip.c: Trying to put 'BYE sip:90' onto UDP socket destined for 192.168.0.37:5060 [2009-09-03 07:06:32.2762] DEBUG[24363] rtp.c: Channel '' has no RTP, not doing anything [2009-09-03 07:06:32.2764] DEBUG[24363] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2009-09-03 07:06:32.2765] DEBUG[24363] pbx.c: Spawn extension (local_dial,22600,87) exited non-zero on 'SIP/90027-089d5e88' [2009-09-03 07:06:32.2766] VERBOSE[24363] pbx.c: == Spawn extension (local_dial, 22600, 87) exited non-zero on 'SIP/90027-089d5e88' [2009-09-03 07:06:32.2769] DEBUG[24363] channel.c: Soft-Hanging up channel 'SIP/90027-089d5e88' [2009-09-03 07:06:32.2772] DEBUG[24363] pbx.c: Expression result is '1' [2009-09-03 07:06:32.2773] DEBUG[24363] pbx.c: Launching 'GotoIf' [2009-09-03 07:06:32.2774] VERBOSE[24363] pbx.c: -- Executing [h@local_dial:1] GotoIf("SIP/90027-089d5e88", "1?2:3") in new stack [2009-09-03 07:06:32.2776] VERBOSE[24363] pbx.c: -- Goto (local_dial,h,2) [2009-09-03 07:06:32.2778] DEBUG[24363] pbx.c: Launching 'Goto' [2009-09-03 07:06:32.2779] VERBOSE[24363] pbx.c: -- Executing [h@local_dial:2] Goto("SIP/90027-089d5e88", "hangup_callback,h,1") in new stack [2009-09-03 07:06:32.2781] VERBOSE[24363] pbx.c: -- Goto (hangup_callback,h,1) [2009-09-03 07:06:32.2784] DEBUG[24363] pbx.c: Launching 'NoOp' [2009-09-03 07:06:32.2785] VERBOSE[24363] pbx.c: -- Executing [h@hangup_callback:1] NoOp("SIP/90027-089d5e88", "-(B)----------------------- context hangup_callback h --------------------------") in new stack [2009-09-03 07:06:32.2787] DEBUG[24363] pbx.c: Launching 'Gosub' [2009-09-03 07:06:32.2788] VERBOSE[24363] pbx.c: -- Executing [h@hangup_callback:2] Gosub("SIP/90027-089d5e88", "agent_call_end,s,1") in new stack [2009-09-03 07:06:32.2792] VERBOSE[24359] chan_sip.c: <--- SIP read from UDP://192.168.0.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.93:5060;branch=z9hG4bK38cf63ce;rport From: "Victor Negru" ;tag=as16bdb286 To: ;tag=1c586423056 Call-ID: 0cb3a1345aa8f6836dd920a050964d12@192.168.1.93 CSeq: 103 BYE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Length: 0 <-------------> [2009-09-03 07:06:32.2792] VERBOSE[24359] chan_sip.c: --- (11 headers 0 lines) --- [2009-09-03 07:06:32.2794] DEBUG[24359] chan_sip.c: Stopping retransmission on '0cb3a1345aa8f6836dd920a050964d12@192.168.1.93' of Request 103: Match Found [2009-09-03 07:06:32.2795] VERBOSE[24359] chan_sip.c: Really destroying SIP dialog '0cb3a1345aa8f6836dd920a050964d12@192.168.1.93' Method: INVITE [2009-09-03 07:06:32.2791] DEBUG[24363] pbx.c: Launching 'Gosub' [2009-09-03 07:06:32.2803] VERBOSE[24363] pbx.c: -- Executing [s@agent_call_end:1] Gosub("SIP/90027-089d5e88", "read_vars,s,1") in new stack [2009-09-03 07:06:32.2806] DEBUG[24363] pbx.c: Launching 'NoOp' [2009-09-03 07:06:32.2807] VERBOSE[24363] pbx.c: -- Executing [s@read_vars:1] NoOp("SIP/90027-089d5e88", "-(B)------------------------------------- macro read_vars (SIP/90027-089d5e88) -----------") in new stack ... dialplan ... [2009-09-03 07:06:32.3265] DEBUG[24363] pbx.c: Launching 'NoOp' [2009-09-03 07:06:32.3265] VERBOSE[24363] pbx.c: -- Executing [h@hangup_callback:29] NoOp("SIP/90027-089d5e88", "-(E)----------------------- context hangup_callback h --------------------------") in new stack [2009-09-03 07:06:32.3268] DEBUG[24363] channel.c: Hanging up channel 'SIP/90027-089d5e88' [2009-09-03 07:06:32.3269] DEBUG[24363] chan_sip.c: Hangup call SIP/90027-089d5e88, SIP callid 585956038112000176@192.168.0.37 [2009-09-03 07:06:32.3270] DEBUG[24363] chan_sip.c: update_call_counter(90027) - decrement call limit counter on hangup [2009-09-03 07:06:33.2790] VERBOSE[24359] chan_sip.c: Really destroying SIP dialog '585956038112000176@192.168.0.37' Method: BYE