[2009-06-24 17:19:11] VERBOSE[4130] logger.c: Asterisk Event Logger restarted [2009-06-24 17:19:11] VERBOSE[4130] logger.c: Asterisk Queue Logger restarted [2009-06-24 17:19:19] VERBOSE[3193] logger.c: <--- SIP read from 192.168.1.50:5060 ---> <-------------> [2009-06-24 17:19:25] VERBOSE[3183] logger.c: -- Accepting AUTHENTICATED call from 192.168.1.1: > requested format = gsm, > requested prefs = (), > actual format = ulaw, > host prefs = (ulaw|alaw|gsm), > priority = mine [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [90544111111@from-internal:1] Macro("IAX2/2303-11693", "user-callerid|SKIPTTL|") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:1] Set("IAX2/2303-11693", "AMPUSER=2303") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("IAX2/2303-11693", "0?report") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("IAX2/2303-11693", "0|Set|REALCALLERIDNUM=2303") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:4] Set("IAX2/2303-11693", "AMPUSER=2303") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:5] Set("IAX2/2303-11693", "AMPUSERCIDNAME=Rrrr") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("IAX2/2303-11693", "0?report") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:7] Set("IAX2/2303-11693", "AMPUSERCID=2303") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:8] Set("IAX2/2303-11693", "CALLERID(all)="Rrrr" <2303>") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:9] Set("IAX2/2303-11693", "REALCALLERIDNUM=2303") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:10] ExecIf("IAX2/2303-11693", "0|Set|CHANNEL(language)=") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:11] GotoIf("IAX2/2303-11693", "1?continue") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Goto (macro-user-callerid,s,20) [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-user-callerid:20] NoOp("IAX2/2303-11693", "Using CallerID "Rrrr" <2303>") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Noop [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [90544111111@from-internal:2] Set("IAX2/2303-11693", "_NODEST=") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [90544111111@from-internal:3] Macro("IAX2/2303-11693", "record-enable|2303|OUT|") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("IAX2/2303-11693", "1?check") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Goto (macro-record-enable,s,4) [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-record-enable:4] AGI("IAX2/2303-11693", "recordingcheck|20090624-171925|1245853165.99") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck [2009-06-24 17:19:25] VERBOSE[4305] logger.c: recordingcheck|20090624-171925|1245853165.99: Outbound recording not enabled [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- AGI Script recordingcheck completed, returning 0 [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: AGI [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("IAX2/2303-11693", "") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [90544111111@from-internal:4] Macro("IAX2/2303-11693", "dialout-trunk|8|544111111|0|") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("IAX2/2303-11693", "DIAL_TRUNK=8") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:25] DEBUG[4305] func_db.c: DB: AMPUSER/2303/pinless not found in database. [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("IAX2/2303-11693", "1?sub-pincheck|s|1") in new stack [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Executed application: GosubIf [2009-06-24 17:19:25] DEBUG[4305] func_db.c: DB: AMPUSER/2303/pinless not found in database. [2009-06-24 17:19:25] DEBUG[4305] app_macro.c: Incrementing gosub_level [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Executing [s@sub-pincheck:1] Authenticate("IAX2/2303-11693", "0|") in new stack [2009-06-24 17:19:25] VERBOSE[4305] logger.c: -- Playing 'agent-pass' (language 'en') [2009-06-24 17:19:27] VERBOSE[4305] logger.c: -- Playing 'auth-thankyou' (language 'en') [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Authenticate [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@sub-pincheck:2] ResetCDR("IAX2/2303-11693", "") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ResetCDR [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@sub-pincheck:3] Return("IAX2/2303-11693", "") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Return [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Decrementing gosub_level [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("IAX2/2303-11693", "0?disabletrunk|1") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("IAX2/2303-11693", "DIAL_NUMBER=544111111") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("IAX2/2303-11693", "DIAL_TRUNK_OPTIONS=tr") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("IAX2/2303-11693", "OUTBOUND_GROUP=OUT_8") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("IAX2/2303-11693", "0?nomax") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("IAX2/2303-11693", "0?chanfull") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("IAX2/2303-11693", "0?skipoutcid") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:10] Set("IAX2/2303-11693", "DIAL_TRUNK_OPTIONS=") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:11] Macro("IAX2/2303-11693", "outbound-callerid|8") in new stack [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("IAX2/2303-11693", "0|SetCallerPres|") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("IAX2/2303-11693", "0|Set|REALCALLERIDNUM=2303") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("IAX2/2303-11693", "1?normcid") in new stack [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Goto (macro-outbound-callerid,s,6) [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:6] Set("IAX2/2303-11693", "USEROUTCID=") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] DEBUG[4305] func_db.c: DB: DEVICE/2303/emergency_cid not found in database. [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:7] Set("IAX2/2303-11693", "EMERGENCYCID=") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:8] Set("IAX2/2303-11693", "TRUNKOUTCID=8881111111") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("IAX2/2303-11693", "1?trunkcid") in new stack [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Goto (macro-outbound-callerid,s,12) [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("IAX2/2303-11693", "1|Set|CALLERID(all)=8881111111") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Last app: Set|CALLERID(all)=8881111111 [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("IAX2/2303-11693", "0|Set|CALLERID(all)=") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("IAX2/2303-11693", "0|SetCallerPres|prohib_passed_screen") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Macro [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("IAX2/2303-11693", "1|AGI|fixlocalprefix") in new stack [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix [2009-06-24 17:19:28] VERBOSE[4305] logger.c: == fixlocalprefix: Dialpattern 972+NXXXXXXXX matched. 544111111 -> 972544111111 [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- AGI Script fixlocalprefix completed, returning 0 [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Last app: AGI|fixlocalprefix [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("IAX2/2303-11693", "OUTNUM=972544111111") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("IAX2/2303-11693", "custom=SIP/ip2ISR") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Set [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("IAX2/2303-11693", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: ExecIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("IAX2/2303-11693", "dialout-trunk-predial-hook|") in new stack [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("IAX2/2303-11693", "") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: Macro [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("IAX2/2303-11693", "0?bypass|1") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("IAX2/2303-11693", "0?customtrunk") in new stack [2009-06-24 17:19:28] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("IAX2/2303-11693", "SIP/ip2ISR/972544111111|300|") in new stack [2009-06-24 17:19:28] VERBOSE[4305] logger.c: Audio is at 5.6.7.8 port 14914 [2009-06-24 17:19:28] VERBOSE[4305] logger.c: Adding codec 0x4 (ulaw) to SDP [2009-06-24 17:19:28] VERBOSE[4305] logger.c: Adding codec 0x8 (alaw) to SDP [2009-06-24 17:19:28] VERBOSE[4305] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [2009-06-24 17:19:28] VERBOSE[4305] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: INVITE sip:972544111111@sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK43a2e089;rport From: "8881111111" ;tag=as2f6af2c6 To: Contact: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 102 INVITE User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:28 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 260 v=0 o=root 3165 3165 IN IP4 5.6.7.8 s=session c=IN IP4 5.6.7.8 t=0 0 m=audio 14914 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [2009-06-24 17:19:28] VERBOSE[4305] logger.c: -- Called ip2ISR/972544111111 [2009-06-24 17:19:28] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK43a2e089;rport=38089;received=1.2.3.4 From: "8881111111" ;tag=as2f6af2c6 To: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 102 INVITE Server: Sip EXpress router (0.9.6 (i386/freebsd)) Content-Length: 0 <-------------> [2009-06-24 17:19:28] VERBOSE[3193] logger.c: --- (8 headers 0 lines) --- [2009-06-24 17:19:28] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK43a2e089;rport=38089 Record-Route: From: 8881111111 ;tag=as2f6af2c6 To: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 102 INVITE Server: Sippy WWW-Authenticate: Digest realm="208.1.2.3",nonce="e5ddb9d9890d532511889dccfc2324ef40de" <-------------> [2009-06-24 17:19:28] VERBOSE[3193] logger.c: --- (9 headers 0 lines) --- [2009-06-24 17:19:28] VERBOSE[3193] logger.c: Transmitting (NAT) to 208.1.2.3:5060: ACK sip:972544111111@sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK43a2e089;rport From: "8881111111" ;tag=as2f6af2c6 To: Contact: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 102 ACK User-Agent: PiaF Max-Forwards: 70 Content-Length: 0 --- [2009-06-24 17:19:28] VERBOSE[3193] logger.c: Audio is at 5.6.7.8 port 14914 [2009-06-24 17:19:28] VERBOSE[3193] logger.c: Adding codec 0x4 (ulaw) to SDP [2009-06-24 17:19:28] VERBOSE[3193] logger.c: Adding codec 0x8 (alaw) to SDP [2009-06-24 17:19:28] VERBOSE[3193] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [2009-06-24 17:19:28] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: INVITE sip:972544111111@sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK0162a7b0;rport From: "8881111111" ;tag=as2f6af2c6 To: Contact: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 103 INVITE User-Agent: PiaF Max-Forwards: 70 Authorization: Digest username="8881111111", realm="208.1.2.3", algorithm=MD5, uri="sip:972544111111@sip.ip2phone.la", nonce="e5ddb9d9890d532511889dccfc2324ef40de", response="cba9b69c1eebd70b486a711474bb7330" Date: Wed, 24 Jun 2009 14:19:28 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 260 v=0 o=root 3165 3166 IN IP4 5.6.7.8 s=session c=IN IP4 5.6.7.8 t=0 0 m=audio 14914 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [2009-06-24 17:19:29] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK43a2e089;rport=38089 Record-Route: From: 8881111111 ;tag=as2f6af2c6 To: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 102 INVITE Server: Sippy WWW-Authenticate: Digest realm="208.1.2.3",nonce="e5ddb9d9890d532511889dccfc2324ef40de" <-------------> [2009-06-24 17:19:29] VERBOSE[3193] logger.c: --- (9 headers 0 lines) --- [2009-06-24 17:19:29] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK0162a7b0;rport=38089;received=1.2.3.4 From: "8881111111" ;tag=as2f6af2c6 To: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 103 INVITE Server: Sip EXpress router (0.9.6 (i386/freebsd)) Content-Length: 0 <-------------> [2009-06-24 17:19:29] VERBOSE[3193] logger.c: --- (8 headers 0 lines) --- [2009-06-24 17:19:31] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK0162a7b0;rport=38089 Record-Route: From: 8881111111 ;tag=as2f6af2c6 To: ;tag=78ddbc975ca9f67a672e993a4f5f38c0 Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 103 INVITE Server: Sippy Content-Length: 171 Content-Type: application/sdp v=0 o=Sippy 696673548 1 IN IP4 208.1.2.3 s=sip call t=0 0 m=audio 27924 RTP/AVP 0 101 c=IN IP4 208.1.2.3 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [2009-06-24 17:19:31] VERBOSE[3193] logger.c: --- (10 headers 8 lines) --- [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Found RTP audio format 0 [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Found RTP audio format 101 [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Peer audio RTP is at port 208.1.2.3:27924 [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Found audio description format telephone-event for ID 101 [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2009-06-24 17:19:31] VERBOSE[3193] logger.c: Peer audio RTP is at port 208.1.2.3:27924 [2009-06-24 17:19:31] VERBOSE[4305] logger.c: -- SIP/ip2ISR-0850a238 is making progress passing it to IAX2/2303-11693 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: <--- SIP read from 192.168.1.1:38105 ---> <-------------> [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: OPTIONS sip:sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK38d123fc;rport From: "Unknown" ;tag=as02da5d52 To: Contact: Call-ID: 20d4ab702b155fef507c36943547f1f5@5.6.7.8 CSeq: 102 OPTIONS User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: OPTIONS sip:sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK03293afa;rport From: "Unknown" ;tag=as1445b626 To: Contact: Call-ID: 5008ee8e26ebd55d41717eab2e3a8794@5.6.7.8 CSeq: 102 OPTIONS User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 501 Not Implemented Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK38d123fc;rport=38089 From: Unknown ;tag=as02da5d52 To: Call-ID: 20d4ab702b155fef507c36943547f1f5@5.6.7.8 CSeq: 102 OPTIONS Server: Sippy <-------------> [2009-06-24 17:19:36] VERBOSE[3193] logger.c: --- (7 headers 0 lines) --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Really destroying SIP dialog '20d4ab702b155fef507c36943547f1f5@5.6.7.8' Method: OPTIONS [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: OPTIONS sip:sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK4011fbd1;rport From: "Unknown" ;tag=as74c00c9c To: Contact: Call-ID: 76ee383a42e608d64b79f96008a91c1e@5.6.7.8 CSeq: 102 OPTIONS User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK0162a7b0;rport=38089 Record-Route: From: 8881111111 ;tag=as2f6af2c6 To: ;tag=78ddbc975ca9f67a672e993a4f5f38c0 Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 103 INVITE Server: Sippy Contact: Anonymous Content-Length: 171 Content-Type: application/sdp v=0 o=Sippy 696673548 2 IN IP4 208.1.2.3 s=sip call t=0 0 m=audio 27924 RTP/AVP 0 101 c=IN IP4 216.49.201.24 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [2009-06-24 17:19:36] VERBOSE[3193] logger.c: --- (11 headers 8 lines) --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Found RTP audio format 0 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Found RTP audio format 101 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Peer audio RTP is at port 216.49.201.24:27924 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Found audio description format telephone-event for ID 101 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Peer audio RTP is at port 216.49.201.24:27924 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: list_route: hop: [2009-06-24 17:19:36] VERBOSE[3193] logger.c: set_destination: Parsing for address/port to send to [2009-06-24 17:19:36] VERBOSE[3193] logger.c: set_destination: set destination to 208.1.2.3, port 5060 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Transmitting (NAT) to 208.1.2.3:5060: ACK sip:208.1.2.3:5061 SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK35e803e7;rport Route: From: "8881111111" ;tag=as2f6af2c6 To: ;tag=78ddbc975ca9f67a672e993a4f5f38c0 Contact: Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 103 ACK User-Agent: PiaF Max-Forwards: 70 Content-Length: 0 --- [2009-06-24 17:19:36] VERBOSE[4305] logger.c: -- SIP/ip2ISR-0850a238 answered IAX2/2303-11693 [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 192.168.1.50:5060: OPTIONS sip:2506@192.168.1.50:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.39:5060;branch=z9hG4bK5e7f7447;rport From: "Unknown" ;tag=as52ba73a3 To: Contact: Call-ID: 49f2d6ef12d65b5a31ecff811f586a90@192.168.1.39 CSeq: 102 OPTIONS User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: <--- SIP read from 192.168.1.50:5060 ---> SIP/2.0 200 OK To: ;tag=33a9ce1fd1fd25f4i0 From: "Unknown" ;tag=as52ba73a3 Call-ID: 49f2d6ef12d65b5a31ecff811f586a90@192.168.1.39 CSeq: 102 OPTIONS Via: SIP/2.0/UDP 192.168.1.39:5060;branch=z9hG4bK5e7f7447 Server: Sipura/SPA1000-2.0.11(g) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura <-------------> [2009-06-24 17:19:36] VERBOSE[3193] logger.c: --- (10 headers 0 lines) --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 501 Not Implemented Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK03293afa;rport=38089 From: Unknown ;tag=as1445b626 To: Call-ID: 5008ee8e26ebd55d41717eab2e3a8794@5.6.7.8 CSeq: 102 OPTIONS Server: Sippy <-------------> [2009-06-24 17:19:36] VERBOSE[3193] logger.c: --- (7 headers 0 lines) --- [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Really destroying SIP dialog '49f2d6ef12d65b5a31ecff811f586a90@192.168.1.39' Method: OPTIONS [2009-06-24 17:19:36] VERBOSE[3193] logger.c: Really destroying SIP dialog '5008ee8e26ebd55d41717eab2e3a8794@5.6.7.8' Method: OPTIONS [2009-06-24 17:19:37] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 501 Not Implemented Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK4011fbd1;rport=38089 From: Unknown ;tag=as74c00c9c To: Call-ID: 76ee383a42e608d64b79f96008a91c1e@5.6.7.8 CSeq: 102 OPTIONS Server: Sippy <-------------> [2009-06-24 17:19:37] VERBOSE[3193] logger.c: --- (7 headers 0 lines) --- [2009-06-24 17:19:37] VERBOSE[3193] logger.c: Really destroying SIP dialog '76ee383a42e608d64b79f96008a91c1e@5.6.7.8' Method: OPTIONS [2009-06-24 17:19:37] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 192.168.1.1:38105: OPTIONS sip:2701@192.168.1.1:38105;rinstance=9cc596c2758f12a8;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.39:5060;branch=z9hG4bK44940387;rport From: "Unknown" ;tag=as1c95c73e To: Contact: Call-ID: 4490ac6b0ce16f09794e963f44912457@192.168.1.39 CSeq: 102 OPTIONS User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [2009-06-24 17:19:37] VERBOSE[3193] logger.c: <--- SIP read from 192.168.1.1:38105 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.39;branch=z9hG4bK44940387;rport=5060 Contact: To: ;tag=d23ebc68 From: "Unknown";tag=as1c95c73e Call-ID: 4490ac6b0ce16f09794e963f44912457@192.168.1.39 CSeq: 102 OPTIONS Accept: application/sdp, application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Zoiper rev.4186 Allow-Events: message-summary, dialog Content-Length: 0 <-------------> [2009-06-24 17:19:37] VERBOSE[3193] logger.c: --- (13 headers 0 lines) --- [2009-06-24 17:19:37] VERBOSE[3193] logger.c: Really destroying SIP dialog '4490ac6b0ce16f09794e963f44912457@192.168.1.39' Method: OPTIONS [2009-06-24 17:19:37] VERBOSE[3193] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: OPTIONS sip:sip.ip2phone.la SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK5c61760e;rport From: "Unknown" ;tag=as340e1a0e To: Contact: Call-ID: 3f9a45485824fa1578f9a585240f0575@5.6.7.8 CSeq: 102 OPTIONS User-Agent: PiaF Max-Forwards: 70 Date: Wed, 24 Jun 2009 14:19:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [2009-06-24 17:19:37] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 501 Not Implemented Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK5c61760e;rport=38089 From: Unknown ;tag=as340e1a0e To: Call-ID: 3f9a45485824fa1578f9a585240f0575@5.6.7.8 CSeq: 102 OPTIONS Server: Sippy <-------------> [2009-06-24 17:19:37] VERBOSE[3193] logger.c: --- (7 headers 0 lines) --- [2009-06-24 17:19:37] VERBOSE[3193] logger.c: Really destroying SIP dialog '3f9a45485824fa1578f9a585240f0575@5.6.7.8' Method: OPTIONS [2009-06-24 17:19:38] VERBOSE[4305] logger.c: Scheduling destruction of SIP dialog '48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8' in 20160 ms (Method: INVITE) [2009-06-24 17:19:38] VERBOSE[4305] logger.c: set_destination: Parsing for address/port to send to [2009-06-24 17:19:38] VERBOSE[4305] logger.c: set_destination: set destination to 208.1.2.3, port 5060 [2009-06-24 17:19:38] VERBOSE[4305] logger.c: Reliably Transmitting (NAT) to 208.1.2.3:5060: BYE sip:208.1.2.3:5061 SIP/2.0 Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK06ea5659;rport Route: From: "8881111111" ;tag=as2f6af2c6 To: ;tag=78ddbc975ca9f67a672e993a4f5f38c0 Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 104 BYE User-Agent: PiaF Max-Forwards: 70 Authorization: Digest username="8881111111", realm="208.1.2.3", algorithm=MD5, uri="sip:208.1.2.3:5061", nonce="e5ddb9d9890d532511889dccfc2324ef40de", response="418a75995ab720fb5a5afb2c1107e723" Content-Length: 0 --- [2009-06-24 17:19:38] VERBOSE[4305] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'IAX2/2303-11693' in macro 'dialout-trunk' [2009-06-24 17:19:38] VERBOSE[4305] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'IAX2/2303-11693' [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [h@macro-dialout-trunk:1] Macro("IAX2/2303-11693", "hangupcall|") in new stack [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [s@macro-hangupcall:1] ResetCDR("IAX2/2303-11693", "vw") in new stack [2009-06-24 17:19:38] DEBUG[4305] app_macro.c: Executed application: ResetCDR [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [s@macro-hangupcall:2] NoCDR("IAX2/2303-11693", "") in new stack [2009-06-24 17:19:38] DEBUG[4305] app_macro.c: Executed application: NoCDR [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [s@macro-hangupcall:3] GotoIf("IAX2/2303-11693", "1?skiprg") in new stack [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Goto (macro-hangupcall,s,6) [2009-06-24 17:19:38] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [s@macro-hangupcall:6] GotoIf("IAX2/2303-11693", "1?skipblkvm") in new stack [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Goto (macro-hangupcall,s,9) [2009-06-24 17:19:38] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [s@macro-hangupcall:9] GotoIf("IAX2/2303-11693", "1?theend") in new stack [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Goto (macro-hangupcall,s,11) [2009-06-24 17:19:38] DEBUG[4305] app_macro.c: Executed application: GotoIf [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Executing [s@macro-hangupcall:11] Hangup("IAX2/2303-11693", "") in new stack [2009-06-24 17:19:38] VERBOSE[4305] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'IAX2/2303-11693' in macro 'hangupcall' [2009-06-24 17:19:38] VERBOSE[4305] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'IAX2/2303-11693' [2009-06-24 17:19:38] VERBOSE[4305] logger.c: -- Hungup 'IAX2/2303-11693' [2009-06-24 17:19:38] VERBOSE[3193] logger.c: <--- SIP read from 208.1.2.3:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 5.6.7.8:5060;received=1.2.3.4;branch=z9hG4bK06ea5659;rport=38089 From: 8881111111 ;tag=as2f6af2c6 To: ;tag=78ddbc975ca9f67a672e993a4f5f38c0 Call-ID: 48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8 CSeq: 104 BYE Server: Sippy <-------------> [2009-06-24 17:19:38] VERBOSE[3193] logger.c: --- (7 headers 0 lines) --- [2009-06-24 17:19:38] VERBOSE[3193] logger.c: Really destroying SIP dialog '48e3846a1f16a4276d6b6b0f3336dbbc@5.6.7.8' Method: INVITE [2009-06-24 17:19:39] VERBOSE[3193] logger.c: <--- SIP read from 192.168.1.50:5060 ---> <------------->