Script started on Wed 13 Apr 2005 11:12:45 AM CDT 0;root@test:/usr/src/cvs-debug/asterisk[root@test asterisk]# asterisk -vvvvvvr == Parsing '/etc/asterisk/asterisk.conf': Found == Parsing '/etc/asterisk/extconfig.conf': Found == Binding extensions.conf to odbc/mysql1/sd_config == Binding sip.conf to odbc/mysql1/sd_config Asterisk CVS-HEAD-04/13/05-10:45:07, Copyright (C) 1999 - 2005 Digium. Written by Mark Spencer ========================================================================= Connected to Asterisk CVS-HEAD-04/13/05-10:45:07 currently running on test (pid = 23059) VerbosityLis at least 6 -- Remote UNIX connection Ktest*CLI> sip show peer 271nv1000 test*CLI> * Name : 271nv1000 Secret : MD5Secret : Context : 271nv Language : en Accountcode : 4 AMA flags : Unknown CallingPres : Presentation Allowed, Not Screened Callgroup : Pickupgroup : Mailbox : 1000@271nv LastMsgsSent : 512 Inc. limit : 0 Outg. limit : 0 Dynamic : No Callerid : "Terry Wilson" <1000> Expire : -1 Expiry : 900 Insecure : no Nat : Always ACL : No CanReinvite : No PromiscRedir : No User=Phone : No DTMFmode : inband LastMsg : 0 ToHost : 192.168.1.165 Addr->IP : 192.168.1.165 Port 5060 Defaddr->IP : 0.0.0.0 Port 0 Def. Username: 271nv1000 Codecs : 0x4 (ulaw) Codec Order : (ulaw) Status : UNKNOWN Useragent : Reg. Contact : Ktest*CLI> sip show peer ser test*CLI> * Name : ser Secret : MD5Secret : Context : inbound Language : en AMA flags : Unknown CallingPres : Presentation Allowed, Not Screened Callgroup : Pickupgroup : Mailbox : LastMsgsSent : -1 Inc. limit : 0 Outg. limit : 0 Dynamic : No Callerid : "" <> Expire : -1 Expiry : 900 Insecure : yes Nat : RFC3581 ACL : No CanReinvite : No PromiscRedir : No User=Phone : No DTMFmode : inband LastMsg : 0 ToHost : 192.168.1.165 Addr->IP : 192.168.1.165 Port 5060 Defaddr->IP : 0.0.0.0 Port 0 Def. Username: Codecs : 0x4 (ulaw) Codec Order : (ulaw) Status : UNKNOWN Useragent : Reg. Contact : Ktest*CLI> sip debug SIPtDebugging Enabled Ktest*CLI> <-- SIP read from 192.168.1.165:5060: INVITE sip:5555551212@ser.company.com:5060;user=phone SIP/2.0 Record-Route: Via: SIP/2.0/UDP 192.168.1.165;branch=z9hG4bK30c5.2c923004.0 Via: SIP/2.0/UDP 192.168.1.72;branch=z9hG4bK7dccea2467011F2F From: "Terry Wilson" ;tag=604E65A9-8911FEBE To: CSeq: 2 INVITE Call-ID: 3eaead5d-7d2a3263-f9548d98@192.168.1.72 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.4.1 Supported: 100rel,replace Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="271nv1000", realm="company.com", nonce="425d4648769d7fe5b9fba9b19eba6737ae53d433", uri="sip:5555551212@ser.company.com:5060;user=phone", response="45478a64f93a3d53d0d0a0f93cdad36d", algorithm=MD5 Max-Forwards: 16 Content-Type: application/sdp Content-Length: 247 v=0 o=- 1113408792 1113408792 IN IP4 192.168.1.72 s=Polycom IP Phone c=IN IP4 192.168.1.72 t=0 0 a=sendrecv m=audio 2250 RTP/AVP 18 0 8 101 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 --- (17 headers 11 lines)--- Using latest request as basis request Sending to 192.168.1.165 : 5060 (non-NAT) Found RTP audio format 18 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.72:2250 Apr 13 11:13:16 DEBUG[23066]: chan_sip.c:2947 process_sdp: Peer audio RTP is at port 192.168.1.72:2250 Found description format G729 Found description format PCMU Found description format PCMA Found description format telephone-event Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Apr 13 11:13:16 DEBUG[23066]: chan_sip.c:5894 check_user_full: Setting NAT on RTP to 524288 Found user '271nv1000' Apr 13 11:13:16 DEBUG[23066]: chan_sip.c:8388 handle_request_invite: Check for res for 271nv1000 Looking for 5555551212 in 271nv Apr 13 11:13:16 DEBUG[23066]: chan_sip.c:5060 build_route: build_route: Record-Route hop: Apr 13 11:13:16 DEBUG[23066]: chan_sip.c:5085 build_route: build_route: Contact hop: list_route: hop: list_route: hop: Transmitting (NAT) to 192.168.1.165:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.165;branch=z9hG4bK30c5.2c923004.0;received=192.168.1.165;rport=5060 Via: SIP/2.0/UDP 192.168.1.72;branch=z9hG4bK7dccea2467011F2F From: "Terry Wilson" ;tag=604E65A9-8911FEBE To: Call-ID: 3eaead5d-7d2a3263-f9548d98@192.168.1.72 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 --- Ksd3--sExecuting SetCallerID("SIP/271nv1000-c582", ""TechOps"<5555551212>") in new stack Ksd3--sExecuting SetMusicOnHold("SIP/271nv1000-c582", "jazz") in new stack Ksd3--sExecuting Macro("SIP/271nv1000-c582", "outbound") in new stack Ksd3--sExecuting AppendCDRUserField("SIP/271nv1000-c582", "DNID[5555551212]") in new stack Apr313s11:13:16 DEBUG[23115]: pbx.c:1505 pbx_substitute_variables_helper_full: Expression is '0' Ksd3--sExecuting GotoIf("SIP/271nv1000-c582", "0?3:5") in new stack Ksd3--sGotoI(macro-outbound,s,5) Ksd3--sExecuting Cut("SIP/271nv1000-c582", "device=CHANNEL||1") in new stack Ksd3--sExecuting Cut("SIP/271nv1000-c582", "sipacct=device|/|2") in new stack Ksd3--sExecuting DBget("SIP/271nv1000-c582", "cid=CID/271nv1000") in new stack Ksd3--sDBget: varname=cid, family=CID, key=271nv1000 Apr313s11:13:16 DEBUG[23115]: db.c:177 ast_db_get: Unable to find key '271nv1000' in family 'CID' Ksd3--sDBget: Value not found in database. Ksd3--sExecuting Goto("SIP/271nv1000-c582", "outbound|+15555551212|1") in new stack Ksd3--sGotoI(outbound,+15555551212,1) Ks==tChannel>'SIP/271nv1000-c582' jumping out of macro 'outbound' Ksd3--sExecuting Goto("SIP/271nv1000-c582", "company-inbound|s|1") in new stack Ksd3--sGotoI(company-inbound,s,1) Ksd3--sExecuting AGI("SIP/271nv1000-c582", "targus-lookup.pl") in new stack Ksd3--sLaunched AGI Script /var/lib/asterisk/agi-bin/targus-lookup.pl Ksd3--sAGILScript targus-lookup.pl completed, returning 0 Ksd3--sExecuting Goto("SIP/271nv1000-c582", "company-attendant|s|1") in new stack Ksd3--sGotoI(company-attendant,s,1) Ksd3--sExecuting Answer("SIP/271nv1000-c582", "") in new stack We'reeat*192.168.1.187 port 11538 AnsweringCwith preferred capability 0x4 (ulaw) Reliably*Transmitting (NAT) to 192.168.1.165:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.165;branch=z9hG4bK30c5.2c923004.0;received=192.168.1.165;rport=5060 Via: SIP/2.0/UDP 192.168.1.72;branch=z9hG4bK7dccea2467011F2F Record-Route: From: "Terry Wilson" ;tag=604E65A9-8911FEBE To: ;tag=as335065d3 Call-ID: 3eaead5d-7d2a3263-f9548d98@192.168.1.72 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Type: application/sdp Content-Length: 160 v=0 o=root 23115 23115 IN IP4 192.168.1.187 s=session c=IN IP4 192.168.1.187 t=0 0 m=audio 11538 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - --- Ksd3--sExecuting SetMusicOnHold("SIP/271nv1000-c582", "jazz") in new stack Ksd3--sExecuting ResponseTimeout("SIP/271nv1000-c582", "5") in new stack Ksd3--sSetLResponse Timeout to 5 Ksd3--sExecuting Wait("SIP/271nv1000-c582", "2") in new stack Ktest*CLI> <-- SIP read from 192.168.1.165:5060: ACK sip:5555551212@192.168.1.187:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.165;branch=0 Via: SIP/2.0/UDP 192.168.1.72;branch=z9hG4bK116e84fb3E0AF9D6 From: "Terry Wilson" ;tag=604E65A9-8911FEBE To: ;tag=as335065d3 CSeq: 2 ACK Call-ID: 3eaead5d-7d2a3263-f9548d98@192.168.1.72 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.4.1 Max-Forwards: 16 Content-Length: 0 --- (12 headers 0 lines)--- Apr 13 11:13:16 DEBUG[23066]: chan_sip.c:1013 __sip_ack: Stopping retransmission on '3eaead5d-7d2a3263-f9548d98@192.168.1.72' of Response 2: Found Ksd3--sExecuting BackGround("SIP/271nv1000-c582", "company-prompts/company-greeting") in new stack Ksd3--sPlaying 'company-prompts/company-greeting' (language 'en') Apr313s11:13:22 DEBUG[23115]: chan_sip.c:2447 sip_rtp_read: * Detected inband DTMF '9' Apr313s11:13:22 DEBUG[23115]: pbx.c:2274 ast_pbx_run: Oooh, got something to jump out with ('9')! Ks==tCDR*updated on SIP/271nv1000-c582 Ksd3--sExecuting Directory("SIP/271nv1000-c582", "company") in new stack Ks==tParsing>'/etc/asterisk/voicemail.conf': Found Ksd3--sPlaying 'dir-intro' (language 'en') Apr313s11:13:27 DEBUG[23115]: chan_sip.c:2447 sip_rtp_read: * Detected inband DTMF '6' Apr313s11:13:27 DEBUG[23115]: chan_sip.c:2447 sip_rtp_read: * Detected inband DTMF '6' Apr313s11:13:28 DEBUG[23115]: chan_sip.c:2447 sip_rtp_read: * Detected inband DTMF '6' Ksd3--sPlaying '/var/spool/asterisk/voicemail/company/6716/greet' (language 'en') Ksd3--sPlaying 'dir-instr' (language 'en') Apr313s11:13:33 DEBUG[23115]: chan_sip.c:2447 sip_rtp_read: * Detected inband DTMF '1' -- Executing Macro("SIP/271nv1000-c582", "inbound-centrex||Dial|6716|25|Voicemail|6716|Voicemail|6716|jazz") in new stack -- Executing Cut("SIP/271nv1000-c582", "MAIN_CONTEXT=MACRO_CONTEXT||1") in new stack Apr 13 11:13:33 DEBUG[23115]: pbx.c:1505 pbx_substitute_variables_helper_full: Expression is '0' -- Executing GotoIf("SIP/271nv1000-c582", "0?100:3") in new stack -- Goto (macro-inbound-centrex,s,3) Apr 13 11:13:33 DEBUG[23115]: pbx.c:1505 pbx_substitute_variables_helper_full: Expression is '1' -- Executing GotoIf("SIP/271nv1000-c582", "1?200:4") in new stack -- Goto (macro-inbound-centrex,s,200) Apr 13 11:13:33 DEBUG[23115]: pbx.c:1444 pbx_substitute_variables_helper_full: Function result is '4' Apr 13 11:13:33 DEBUG[23115]: pbx.c:1505 pbx_substitute_variables_helper_full: Expression is '0' -- Executing GotoIf("SIP/271nv1000-c582", "0?201:203") in new stack -- Goto (macro-inbound-centrex,s,203) -- Executing SetMusicOnHold("SIP/271nv1000-c582", "jazz") in new stack -- Executing AGI("SIP/271nv1000-c582", "targus-lookup.pl") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/targus-lookup.pl -- AGI Script targus-lookup.pl completed, returning 0 -- Executing Dial("SIP/271nv1000-c582", "SIP/6716|25") in new stack Apr 13 11:13:33 WARNING[23115]: chan_sip.c:1542 create_addr: No such host: 6716 Destroying call '1620ea695a5bdd222a159d611609f646@192.168.1.187' Apr 13 11:13:33 NOTICE[23115]: app_dial.c:969 dial_exec_full: Unable to create channel of type 'SIP' (cause 3) == Everyone is busy/congested at this time (1:0/1/0) Apr 13 11:13:33 DEBUG[23115]: app_dial.c:1346 dial_exec_full: Exiting with DIALSTATUS=CONGESTION. -- Executing Goto("SIP/271nv1000-c582", "s-CONGESTION|1") in new stack -- Goto (macro-inbound-centrex,s-CONGESTION,1) -- Executing Goto("SIP/271nv1000-c582", "s-CHANUNAVAIL|1") in new stack -- Goto (macro-inbound-centrex,s-CHANUNAVAIL,1) Apr 13 11:13:33 DEBUG[23115]: pbx.c:1444 pbx_substitute_variables_helper_full: Function result is '0' Apr 13 11:13:33 DEBUG[23115]: pbx.c:1505 pbx_substitute_variables_helper_full: Expression is '1' -- Executing GotoIf("SIP/271nv1000-c582", "1?s-NOANSWER|1:100") in new stack -- Goto (macro-inbound-centrex,s-NOANSWER,1) Apr 13 11:13:33 DEBUG[23115]: pbx.c:1505 pbx_substitute_variables_helper_full: Expression is '1' -- Executing GotoIf("SIP/271nv1000-c582", "1?100:2") in new stack -- Goto (macro-inbound-centrex,s-NOANSWER,100) -- Executing VoiceMail("SIP/271nv1000-c582", "u6716@company") in new stack Ksd3--sPlaying '/var/spool/asterisk/voicemail/company/6716/unavail' (language 'en') Apr313s11:13:38 DEBUG[23115]: sched.c:221 sched_settime: Request to schedule in the past?!?! Ksd3--sPlaying 'vm-intro' (language 'en') Ktest*CLI> <-- SIP read from 192.168.1.165:5060: BYE sip:5555551212@192.168.1.187:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.165;branch=z9hG4bK40c5.f25b07a5.0 Via: SIP/2.0/UDP 192.168.1.72;branch=z9hG4bK30d9e1413A2D3E3C From: "Terry Wilson" ;tag=604E65A9-8911FEBE To: ;tag=as335065d3 CSeq: 3 BYE Call-ID: 3eaead5d-7d2a3263-f9548d98@192.168.1.72 Contact: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.4.1 Proxy-Authorization: Digest username="271nv1000", realm="company.com", nonce="425d4648769d7fe5b9fba9b19eba6737ae53d433", uri="sip:5555551212@ser.company.com:5060;user=phone", response="45478a64f93a3d53d0d0a0f93cdad36d", algorithm=MD5 Max-Forwards: 16 Content-Length: 0 --- (12 headers 0 lines)--- Sending to 192.168.1.165 : 5060 (NAT) Transmitting (NAT) to 192.168.1.165:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.165;branch=z9hG4bK40c5.f25b07a5.0;received=192.168.1.165;rport=5060 Via: SIP/2.0/UDP 192.168.1.72;branch=z9hG4bK30d9e1413A2D3E3C From: "Terry Wilson" ;tag=604E65A9-8911FEBE To: ;tag=as335065d3 Call-ID: 3eaead5d-7d2a3263-f9548d98@192.168.1.72 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 --- Apr313s11:13:39 WARNING[23115]: file.c:564 ast_readaudio_callback: Failed to write frame == Spawn extension (macro-inbound-centrex, s-NOANSWER, 100) exited non-zero on 'SIP/271nv1000-c582' in macro 'inbound-centrex' == Spawn extension (company, 6716, 1) exited non-zero on 'SIP/271nv1000-c582' Apr313s11:13:39 DEBUG[23115]: chan_sip.c:1913 sip_hangup: update_user_counter(271nv1000) - decrement inUse counter DestroyingLcall '3eaead5d-7d2a3263-f9548d98@192.168.1.72' Ktest*CLI> quit Executing last minute cleanups 0;root@test:/usr/src/cvs-debug/asterisk[root@test asterisk]# Script done on Wed 13 Apr 2005 11:13:50 AM CDT