[2009-09-07 04:14:19.4415] VERBOSE[26070] 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=z9hG4bKac1989808860 Max-Forwards: 70 From: ;tag=1c1989806184 To: Call-ID: 198980446711200023054@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="4038d18e",uri="sip:22600@192.168.1.93",algorithm=MD5,response="e3afdf4661b82a109d74741eacf84fd8" User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Type: application/sdp Content-Length: 301 v=0 o=AudiocodesGW 1989800336 1989800252 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-07 04:14:19.4423] VERBOSE[26070] chan_sip.c: --- (14 headers 14 lines) --- [2009-09-07 04:14:19.4429] VERBOSE[26070] netsock.c: == Using SIP RTP TOS bits 24 [2009-09-07 04:14:19.4432] VERBOSE[26070] netsock.c: == Using SIP RTP CoS mark 5 [2009-09-07 04:14:19.4435] VERBOSE[26070] netsock.c: == Using UDPTL TOS bits 24 [2009-09-07 04:14:19.4438] VERBOSE[26070] netsock.c: == Using UDPTL CoS mark 5 [2009-09-07 04:14:19.4441] DEBUG[26070] chan_sip.c: Setting NAT on RTP to Off [2009-09-07 04:14:19.4442] DEBUG[26070] chan_sip.c: Setting NAT on UDPTL to Off [2009-09-07 04:14:19.4443] DEBUG[26070] chan_sip.c: Allocating new SIP dialog for 198980446711200023054@192.168.0.37 - INVITE (With RTP) [2009-09-07 04:14:19.4444] VERBOSE[26070] chan_sip.c: Sending to 192.168.0.37 : 5060 (no NAT) [2009-09-07 04:14:19.4446] DEBUG[26070] chan_sip.c: Initializing initreq for method INVITE - callid 198980446711200023054@192.168.0.37 [2009-09-07 04:14:19.4447] VERBOSE[26070] chan_sip.c: Using INVITE request as basis request - 198980446711200023054@192.168.0.37 [2009-09-07 04:14:19.4450] VERBOSE[26070] chan_sip.c: Found peer '90027' for '90027' from 192.168.0.37:5060 [2009-09-07 04:14:19.4453] DEBUG[26070] chan_sip.c: Setting NAT on RTP to On [2009-09-07 04:14:19.4454] DEBUG[26070] chan_sip.c: Setting NAT on UDPTL to On [2009-09-07 04:14:19.4455] VERBOSE[26070] 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=z9hG4bKac1989808860;received=192.168.0.37 From: ;tag=1c1989806184 To: ;tag=as23bc29c7 Call-ID: 198980446711200023054@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="51a577b6" Content-Length: 0 <------------> [2009-09-07 04:14:19.4460] DEBUG[26070] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:19.4461] VERBOSE[26070] chan_sip.c: Scheduling destruction of SIP dialog '198980446711200023054@192.168.0.37' in 32000 ms (Method: INVITE) [2009-09-07 04:14:19.4597] VERBOSE[26070] 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=z9hG4bKac1989808860 Max-Forwards: 70 From: ;tag=1c1989806184 To: ;tag=as23bc29c7 Call-ID: 198980446711200023054@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-07 04:14:19.4601] VERBOSE[26070] chan_sip.c: --- (12 headers 0 lines) --- [2009-09-07 04:14:19.4605] DEBUG[26070] chan_sip.c: Stopping retransmission on '198980446711200023054@192.168.0.37' of Response 1: Match Found [2009-09-07 04:14:19.4635] VERBOSE[26070] 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=z9hG4bKac1989836584 Max-Forwards: 70 From: ;tag=1c1989806184 To: Call-ID: 198980446711200023054@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="51a577b6",uri="sip:22600@192.168.1.93",algorithm=MD5,response="6b98757cfc89daeb4871a00bf5b832e3" User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Content-Type: application/sdp Content-Length: 301 v=0 o=AudiocodesGW 1989800336 1989800252 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-07 04:14:19.4641] VERBOSE[26070] chan_sip.c: --- (14 headers 14 lines) --- [2009-09-07 04:14:19.4645] VERBOSE[26070] chan_sip.c: Sending to 192.168.0.37 : 5060 (NAT) [2009-09-07 04:14:19.4647] DEBUG[26070] chan_sip.c: Initializing initreq for method INVITE - callid 198980446711200023054@192.168.0.37 [2009-09-07 04:14:19.4648] VERBOSE[26070] chan_sip.c: Using INVITE request as basis request - 198980446711200023054@192.168.0.37 [2009-09-07 04:14:19.4651] VERBOSE[26070] chan_sip.c: Found peer '90027' for '90027' from 192.168.0.37:5060 [2009-09-07 04:14:19.4654] DEBUG[26070] chan_sip.c: Setting NAT on RTP to On [2009-09-07 04:14:19.4655] DEBUG[26070] chan_sip.c: Setting NAT on UDPTL to On [2009-09-07 04:14:19.4657] VERBOSE[26070] chan_sip.c: Found RTP audio format 0 [2009-09-07 04:14:19.4660] VERBOSE[26070] chan_sip.c: Found RTP audio format 8 [2009-09-07 04:14:19.4663] VERBOSE[26070] chan_sip.c: Found RTP audio format 18 [2009-09-07 04:14:19.4665] VERBOSE[26070] chan_sip.c: Found RTP audio format 96 [2009-09-07 04:14:19.4668] DEBUG[26070] chan_sip.c: Peer doesn't provide T.38 UDPTL [2009-09-07 04:14:19.4669] VERBOSE[26070] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6000 [2009-09-07 04:14:19.4671] VERBOSE[26070] chan_sip.c: Found audio description format PCMU for ID 0 [2009-09-07 04:14:19.4674] VERBOSE[26070] chan_sip.c: Found audio description format PCMA for ID 8 [2009-09-07 04:14:19.4677] VERBOSE[26070] chan_sip.c: Found audio description format G729 for ID 18 [2009-09-07 04:14:19.4680] VERBOSE[26070] chan_sip.c: Found audio description format telephone-event for ID 96 [2009-09-07 04:14:19.4682] VERBOSE[26070] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [2009-09-07 04:14:19.4685] VERBOSE[26070] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2009-09-07 04:14:19.4688] VERBOSE[26070] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6000 [2009-09-07 04:14:19.4691] DEBUG[26070] chan_sip.c: Checking SIP call limits for device 90027 [2009-09-07 04:14:19.4694] VERBOSE[26070] chan_sip.c: Looking for 22600 in default-sip (domain 192.168.1.93) [2009-09-07 04:14:19.4700] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:19.4704] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO channels (uniqueid, started, channel, state, callerid_num, callerid_name, accountcode, context, exten, priority, application, data) VALUES ('1252322059.5', '1252322059', 'SIP/90027-09869be0', 'Down', '90027', 'AudioCodes 1 - Port 01', '', 'default-sip', '22600', '1', '', '') [2009-09-07 04:14:19.4708] DEBUG[26070] res_config_mysql.c: MySQL RealTime: row inserted on table: channels, id: 0 [2009-09-07 04:14:19.4710] VERBOSE[26070] chan_sip.c: list_route: hop: [2009-09-07 04:14:19.4714] VERBOSE[26070] 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=z9hG4bKac1989836584;received=192.168.0.37 From: ;tag=1c1989806184 To: Call-ID: 198980446711200023054@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-07 04:14:19.4718] DEBUG[26070] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:19.4724] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:19.4727] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET state = 'Ring', accountcode = '', context = 'default-sip', exten = '22600', priority = '1', application = '', data = '' WHERE uniqueid = '1252322059.5' [2009-09-07 04:14:19.4730] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:19.4733] DEBUG[26117] pbx.c: Launching 'NoOp' [2009-09-07 04:14:19.4734] VERBOSE[26117] pbx.c: -- Executing [22600@default-sip:1] NoOp("SIP/90027-09869be0", "-(B)------------------------------------- context default_from_local ---------------") in new stack ... dialplan ... [2009-09-07 04:14:19.8116] DEBUG[26117] pbx.c: Launching 'Dial' [2009-09-07 04:14:19.8117] VERBOSE[26117] pbx.c: -- Executing [22600@local_dial:87] Dial("SIP/90027-09869be0", "SIP/90028,30,gtiU(agent_call_answer^22600)") in new stack [2009-09-07 04:14:19.8121] DEBUG[26117] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [2009-09-07 04:14:19.8125] VERBOSE[26117] netsock.c: == Using SIP RTP TOS bits 24 [2009-09-07 04:14:19.8129] VERBOSE[26117] netsock.c: == Using SIP RTP CoS mark 5 [2009-09-07 04:14:19.8131] VERBOSE[26117] netsock.c: == Using UDPTL TOS bits 24 [2009-09-07 04:14:19.8134] VERBOSE[26117] netsock.c: == Using UDPTL CoS mark 5 [2009-09-07 04:14:19.8137] DEBUG[26117] chan_sip.c: Allocating new SIP dialog for 379f369c6b0abf3079c451836ad19c22@127.0.0.1 - INVITE (With RTP) [2009-09-07 04:14:19.8139] DEBUG[26117] chan_sip.c: Setting NAT on RTP to On [2009-09-07 04:14:19.8139] DEBUG[26117] chan_sip.c: Setting NAT on UDPTL to On [2009-09-07 04:14:19.8140] DEBUG[26117] chan_sip.c: OBPROXY: Not applying OBproxy to this call [2009-09-07 04:14:19.8145] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:19.8149] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO channels (uniqueid, started, channel, state, callerid_num, callerid_name, accountcode, context, exten, priority, application, data) VALUES ('1252322059.6', '1252322059', 'SIP/90028-09884f08', 'Down', '', '', '', 'default-sip', 's', '1', '', '') [2009-09-07 04:14:19.8152] DEBUG[26117] res_config_mysql.c: MySQL RealTime: row inserted on table: channels, id: 0 .. variables .. [2009-09-07 04:14:19.8331] DEBUG[26117] chan_sip.c: Outgoing Call for 90028 [2009-09-07 04:14:19.8337] DEBUG[26117] 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-07 04:14:19.8337] DEBUG[26117] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [2009-09-07 04:14:19.8338] VERBOSE[26117] chan_sip.c: Audio is at 192.168.1.93 port 42292 [2009-09-07 04:14:19.8342] VERBOSE[26117] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2009-09-07 04:14:19.8345] VERBOSE[26117] chan_sip.c: Adding codec 0x2 (gsm) to SDP [2009-09-07 04:14:19.8348] VERBOSE[26117] chan_sip.c: Adding codec 0x8 (alaw) to SDP [2009-09-07 04:14:19.8351] VERBOSE[26117] chan_sip.c: Adding codec 0x10 (g726aal2) to SDP [2009-09-07 04:14:19.8353] VERBOSE[26117] chan_sip.c: Adding codec 0x20 (adpcm) to SDP [2009-09-07 04:14:19.8356] VERBOSE[26117] chan_sip.c: Adding codec 0x40 (slin) to SDP [2009-09-07 04:14:19.8359] VERBOSE[26117] chan_sip.c: Adding codec 0x80 (lpc10) to SDP [2009-09-07 04:14:19.8361] VERBOSE[26117] chan_sip.c: Adding codec 0x200 (speex) to SDP [2009-09-07 04:14:19.8399] VERBOSE[26117] chan_sip.c: Adding codec 0x800 (g726) to SDP [2009-09-07 04:14:19.8402] VERBOSE[26117] chan_sip.c: Adding codec 0x1000 (g722) to SDP [2009-09-07 04:14:19.8405] VERBOSE[26117] chan_sip.c: Adding codec 0x8000 (slin16) to SDP [2009-09-07 04:14:19.8407] VERBOSE[26117] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2009-09-07 04:14:19.8410] DEBUG[26117] chan_sip.c: Initializing initreq for method INVITE - callid 2ad73517048e492839fefe3a0a97da25@192.168.1.93 [2009-09-07 04:14:19.8412] VERBOSE[26117] 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=z9hG4bK75ce6e31;rport Max-Forwards: 70 From: "Victor Negru" ;tag=as1e41170f To: Contact: Call-ID: 2ad73517048e492839fefe3a0a97da25@192.168.1.93 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.1.5 Date: Mon, 07 Sep 2009 11:14:19 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 583285126 583285126 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 42292 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-07 04:14:19.8418] DEBUG[26117] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:19.8420] VERBOSE[26117] app_dial.c: -- Called 90028 [2009-09-07 04:14:19.8425] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:19.8428] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET callerid_num = '22600', callerid_name = '', accountcode = '1252322059.5', context = 'default-sip', exten = '22600', priority = '1', application = 'AppDial', data = '(Outgoing Line)' WHERE uniqueid = '1252322059.6' [2009-09-07 04:14:19.8432] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:19.8742] VERBOSE[26070] 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=z9hG4bK75ce6e31;rport From: "Victor Negru" ;tag=as1e41170f To: ;tag=1c1990334361 Call-ID: 2ad73517048e492839fefe3a0a97da25@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-07 04:14:19.8743] VERBOSE[26070] chan_sip.c: --- (10 headers 0 lines) --- [2009-09-07 04:14:19.8745] DEBUG[26070] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2ad73517048e492839fefe3a0a97da25@192.168.1.93' Request 102: Found [2009-09-07 04:14:19.8804] VERBOSE[26070] 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=z9hG4bK75ce6e31;rport From: "Victor Negru" ;tag=as1e41170f To: ;tag=1c1990334361 Call-ID: 2ad73517048e492839fefe3a0a97da25@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-07 04:14:19.8805] VERBOSE[26070] chan_sip.c: --- (11 headers 0 lines) --- [2009-09-07 04:14:19.8806] DEBUG[26070] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2ad73517048e492839fefe3a0a97da25@192.168.1.93' Request 102: Found [2009-09-07 04:14:19.8809] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:19.8811] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET state = 'Ringing', accountcode = '1252322059.5', context = 'default-sip', exten = '22600', priority = '1', application = 'AppDial', data = '(Outgoing Line)' WHERE uniqueid = '1252322059.6' [2009-09-07 04:14:19.8814] DEBUG[26070] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:19.8824] VERBOSE[26117] app_dial.c: -- SIP/90028-09884f08 is ringing [2009-09-07 04:14:19.8828] VERBOSE[26117] 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=z9hG4bKac1989836584;received=192.168.0.37 From: ;tag=1c1989806184 To: ;tag=as09232835 Call-ID: 198980446711200023054@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-07 04:14:19.8832] DEBUG[26117] chan_sip.c: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:22.0073] VERBOSE[26070] 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=z9hG4bK75ce6e31;rport From: "Victor Negru" ;tag=as1e41170f To: ;tag=1c1990334361 Call-ID: 2ad73517048e492839fefe3a0a97da25@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: 233 v=0 o=AudiocodesGW 1990348274 1990348192 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-07 04:14:22.0075] VERBOSE[26070] chan_sip.c: --- (12 headers 11 lines) --- [2009-09-07 04:14:22.0076] DEBUG[26070] chan_sip.c: Acked pending invite 102 [2009-09-07 04:14:22.0076] DEBUG[26070] chan_sip.c: Stopping retransmission on '2ad73517048e492839fefe3a0a97da25@192.168.1.93' of Request 102: Match Found [2009-09-07 04:14:22.0078] VERBOSE[26070] chan_sip.c: Found RTP audio format 0 [2009-09-07 04:14:22.0078] VERBOSE[26070] chan_sip.c: Found RTP audio format 101 [2009-09-07 04:14:22.0079] DEBUG[26070] chan_sip.c: Peer doesn't provide T.38 UDPTL [2009-09-07 04:14:22.0079] VERBOSE[26070] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6010 [2009-09-07 04:14:22.0080] VERBOSE[26070] chan_sip.c: Found audio description format PCMU for ID 0 [2009-09-07 04:14:22.0080] VERBOSE[26070] chan_sip.c: Found audio description format telephone-event for ID 101 [2009-09-07 04:14:22.0081] VERBOSE[26070] 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-07 04:14:22.0082] VERBOSE[26070] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2009-09-07 04:14:22.0082] VERBOSE[26070] chan_sip.c: Peer audio RTP is at port 192.168.0.37:6010 [2009-09-07 04:14:22.0083] VERBOSE[26070] chan_sip.c: list_route: hop: [2009-09-07 04:14:22.0084] DEBUG[26070] chan_sip.c: Strict routing enforced for session 2ad73517048e492839fefe3a0a97da25@192.168.1.93 [2009-09-07 04:14:22.0084] VERBOSE[26070] chan_sip.c: set_destination: Parsing for address/port to send to [2009-09-07 04:14:22.0085] VERBOSE[26070] chan_sip.c: set_destination: set destination to 192.168.0.37, port 5060 [2009-09-07 04:14:22.0086] VERBOSE[26070] 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=z9hG4bK49b1ebcb;rport Max-Forwards: 70 From: "Victor Negru" ;tag=as1e41170f To: ;tag=1c1990334361 Contact: Call-ID: 2ad73517048e492839fefe3a0a97da25@192.168.1.93 CSeq: 102 ACK User-Agent: Asterisk PBX 1.6.1.5 Content-Length: 0 --- [2009-09-07 04:14:22.0086] DEBUG[26070] chan_sip.c: Trying to put 'ACK sip:90' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:22.0108] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:22.0111] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET state = 'Up', accountcode = '1252322059.5', context = 'default-sip', exten = '22600', priority = '1', application = 'AppDial', data = '(Outgoing Line)' WHERE uniqueid = '1252322059.6' [2009-09-07 04:14:22.0115] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:22.0116] VERBOSE[26117] app_dial.c: -- SIP/90028-09884f08 answered SIP/90027-09869be0 [2009-09-07 04:14:22.0122] DEBUG[26117] app_stack.c: Channel SIP/90028-09884f08 has no datastore, so we're allocating one. [2009-09-07 04:14:22.0123] DEBUG[26117] app_stack.c: Setting 'ARG1' to '22600' [2009-09-07 04:14:22.0125] DEBUG[26117] pbx.c: Launching 'Set' [2009-09-07 04:14:22.0126] VERBOSE[26117] pbx.c: -- Executing [s@agent_call_answer:1] Set("SIP/90028-09884f08", "LOCAL(agent_answered)=22600") in new stack ... dialplan ... [2009-09-07 04:14:22.0757] DEBUG[26117] pbx.c: Launching 'Return' [2009-09-07 04:14:22.0758] VERBOSE[26117] pbx.c: -- Executing [s@agent_call_answer:14] Return("SIP/90028-09884f08", "") in new stack [2009-09-07 04:14:22.0761] DEBUG[26117] pbx.c: Launching 'NoOp' [2009-09-07 04:14:22.0762] VERBOSE[26117] pbx.c: -- Executing [s@app_dial_gosub_virtual_context:1] NoOp("SIP/90028-09884f08", "") in new stack [2009-09-07 04:14:22.0765] VERBOSE[26117] pbx.c: -- Auto fallthrough, channel 'SIP/90028-09884f08' status is 'UNKNOWN' [2009-09-07 04:14:22.0768] DEBUG[26117] app_dial.c: Gosub exited with status 0 [2009-09-07 04:14:22.0776] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:22.0778] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET state = 'Up', accountcode = '1252322059.5', context = 'local_dial', exten = '22600', priority = '87', application = 'Dial', data = 'SIP/90028,30,gtiU(agent_call_answer^22600)' WHERE uniqueid = '1252322059.5' [2009-09-07 04:14:22.0782] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:22.0783] DEBUG[26117] chan_sip.c: SIP answering channel: SIP/90027-09869be0 [2009-09-07 04:14:22.0785] DEBUG[26117] chan_sip.c: Setting framing from config on incoming call [2009-09-07 04:14:22.0786] DEBUG[26117] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2009-09-07 04:14:22.0787] DEBUG[26117] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2009-09-07 04:14:22.0788] VERBOSE[26117] chan_sip.c: Audio is at 192.168.1.93 port 45238 [2009-09-07 04:14:22.0791] VERBOSE[26117] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2009-09-07 04:14:22.0794] VERBOSE[26117] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2009-09-07 04:14:22.0797] VERBOSE[26117] 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=z9hG4bKac1989836584;received=192.168.0.37 From: ;tag=1c1989806184 To: ;tag=as09232835 Call-ID: 198980446711200023054@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: 258 v=0 o=root 664093169 664093169 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 45238 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-07 04:14:22.0802] DEBUG[26117] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:22.0806] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:22.0808] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET bridgedto = '1252322059.6', accountcode = '1252322059.5', context = 'local_dial', exten = '22600', priority = '87', application = 'Dial', data = 'SIP/90028,30,gtiU(agent_call_answer^22600)' WHERE uniqueid = '1252322059.5' [2009-09-07 04:14:22.0812] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:22.0814] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:22.0817] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET bridgedto = '1252322059.5', accountcode = '1252322059.5', context = 'app_dial_gosub_virtual_context', exten = 's', priority = '2', application = 'AppDial', data = '(Outgoing Line)' WHERE uniqueid = '1252322059.6' [2009-09-07 04:14:22.0819] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:22.0823] DEBUG[26117] rtp.c: Got RTCP report of 44 bytes [2009-09-07 04:14:22.0826] DEBUG[26117] rtp.c: Ooh, format changed from unknown to ulaw [2009-09-07 04:14:22.0827] DEBUG[26117] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2009-09-07 04:14:22.1229] VERBOSE[26070] 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=z9hG4bKac1993161788 Max-Forwards: 70 From: ;tag=1c1989806184 To: ;tag=as09232835 Call-ID: 198980446711200023054@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-07 04:14:22.1229] VERBOSE[26070] chan_sip.c: --- (12 headers 0 lines) --- [2009-09-07 04:14:22.1230] DEBUG[26070] chan_sip.c: Stopping retransmission on '198980446711200023054@192.168.0.37' of Response 2: Match Found [2009-09-07 04:14:22.1338] DEBUG[26117] rtp.c: Ooh, format changed from unknown to ulaw [2009-09-07 04:14:22.1339] DEBUG[26117] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2009-09-07 04:14:22.1341] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:26.3373] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:27.6533] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:31.4731] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:32.0770] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:34.9130] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:37.4365] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:38.9729] DEBUG[26117] rtp.c: Got RTCP report of 68 bytes [2009-09-07 04:14:39.6586] VERBOSE[26070] 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=z9hG4bKac2015082335 Max-Forwards: 70 From: ;tag=1c1989806184 To: ;tag=as09232835 Call-ID: 198980446711200023054@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="51a577b6",uri="sip:22600@192.168.1.93",algorithm=MD5,response="da3d01ff4da217e63d4979e197c8f42a" User-Agent: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004 Reason: Q.850 ;cause=16 Content-Length: 0 <-------------> [2009-09-07 04:14:39.6587] VERBOSE[26070] chan_sip.c: --- (14 headers 0 lines) --- [2009-09-07 04:14:39.6588] DEBUG[26070] chan_sip.c: Initializing initreq for method BYE - callid 198980446711200023054@192.168.0.37 [2009-09-07 04:14:39.6589] VERBOSE[26070] chan_sip.c: Sending to 192.168.0.37 : 5060 (NAT) [2009-09-07 04:14:39.6593] VERBOSE[26070] 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=z9hG4bKac2015082335;received=192.168.0.37 From: ;tag=1c1989806184 To: ;tag=as09232835 Call-ID: 198980446711200023054@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-07 04:14:39.6593] DEBUG[26070] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:39.6603] DEBUG[26117] channel.c: Didn't get a frame from channel: SIP/90027-09869be0 [2009-09-07 04:14:39.6605] DEBUG[26117] channel.c: Bridge stops bridging channels SIP/90027-09869be0 and SIP/90028-09884f08 [2009-09-07 04:14:39.6607] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:39.6610] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET bridgedto = '', accountcode = '1252322059.5', context = 'local_dial', exten = '22600', priority = '87', application = 'Dial', data = 'SIP/90028,30,gtiU(agent_call_answer^22600)' WHERE uniqueid = '1252322059.5' [2009-09-07 04:14:39.6615] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:39.6617] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:39.6620] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE channels SET bridgedto = '', accountcode = '1252322059.5', context = 'app_dial_gosub_virtual_context', exten = 's', priority = '2', application = 'AppDial', data = '(Outgoing Line)' WHERE uniqueid = '1252322059.6' [2009-09-07 04:14:39.6622] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: channels [2009-09-07 04:14:39.6626] DEBUG[26117] cdr_addon_mysql.c: Inserting a CDR record. [2009-09-07 04:14:39.6627] DEBUG[26117] 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-07 04:14:19','22609','22600','local_dial','SIP/90027-09869be0','SIP/90028-09884f08','Dial','SIP/90028,30,gtiU(agent_call_answer^22600)','20','17','ANSWERED','3','1252322059.5','1252322059.5','#call_id=1252322059.5-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-07 04:14:39.6631] DEBUG[26117] channel.c: Hanging up channel 'SIP/90028-09884f08' [2009-09-07 04:14:39.6632] DEBUG[26117] chan_sip.c: Hangup call SIP/90028-09884f08, SIP callid 2ad73517048e492839fefe3a0a97da25@192.168.1.93 [2009-09-07 04:14:39.6633] DEBUG[26117] chan_sip.c: update_call_counter(90028) - decrement call limit counter on hangup [2009-09-07 04:14:39.6637] VERBOSE[26117] chan_sip.c: Scheduling destruction of SIP dialog '2ad73517048e492839fefe3a0a97da25@192.168.1.93' in 32000 ms (Method: INVITE) [2009-09-07 04:14:39.6643] DEBUG[26117] chan_sip.c: Strict routing enforced for session 2ad73517048e492839fefe3a0a97da25@192.168.1.93 [2009-09-07 04:14:39.6644] VERBOSE[26117] chan_sip.c: set_destination: Parsing for address/port to send to [2009-09-07 04:14:39.6646] VERBOSE[26117] chan_sip.c: set_destination: set destination to 192.168.0.37, port 5060 [2009-09-07 04:14:39.6649] VERBOSE[26117] 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=z9hG4bK4b37cba5;rport Max-Forwards: 70 From: "Victor Negru" ;tag=as1e41170f To: ;tag=1c1990334361 Call-ID: 2ad73517048e492839fefe3a0a97da25@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-07 04:14:39.6653] DEBUG[26117] chan_sip.c: Trying to put 'BYE sip:90' onto UDP socket destined for 192.168.0.37:5060 [2009-09-07 04:14:39.6656] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Connection okay. [2009-09-07 04:14:39.6657] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Delete SQL: DELETE FROM channels WHERE uniqueid = '1252322059.6' [2009-09-07 04:14:39.6660] DEBUG[26117] res_config_mysql.c: MySQL RealTime: Deleted 1 rows on table: channels [2009-09-07 04:14:39.6915] VERBOSE[26070] 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=z9hG4bK4b37cba5;rport From: "Victor Negru" ;tag=as1e41170f To: ;tag=1c1990334361 Call-ID: 2ad73517048e492839fefe3a0a97da25@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-07 04:14:39.6916] VERBOSE[26070] chan_sip.c: --- (11 headers 0 lines) --- [2009-09-07 04:14:39.6918] DEBUG[26070] chan_sip.c: Stopping retransmission on '2ad73517048e492839fefe3a0a97da25@192.168.1.93' of Request 103: Match Found [2009-09-07 04:14:39.6919] VERBOSE[26070] chan_sip.c: Really destroying SIP dialog '2ad73517048e492839fefe3a0a97da25@192.168.1.93' Method: INVITE [2009-09-07 04:14:39.6948] DEBUG[26117] rtp.c: Channel '' has no RTP, not doing anything [2009-09-07 04:14:39.6949] DEBUG[26117] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2009-09-07 04:14:39.6950] DEBUG[26117] pbx.c: Spawn extension (local_dial,22600,87) exited non-zero on 'SIP/90027-09869be0' [2009-09-07 04:14:39.6951] VERBOSE[26117] pbx.c: == Spawn extension (local_dial, 22600, 87) exited non-zero on 'SIP/90027-09869be0' [2009-09-07 04:14:39.6956] DEBUG[26117] channel.c: Soft-Hanging up channel 'SIP/90027-09869be0' [2009-09-07 04:14:39.6958] DEBUG[26117] pbx.c: Expression result is '1' [2009-09-07 04:14:39.6959] DEBUG[26117] pbx.c: Launching 'GotoIf' [2009-09-07 04:14:39.6960] VERBOSE[26117] pbx.c: -- Executing [h@local_dial:1] GotoIf("SIP/90027-09869be0", "1?2:3") in new stack [2009-09-07 04:14:39.6962] VERBOSE[26117] pbx.c: -- Goto (local_dial,h,2)