<--- SIP read from 192.168.254.100:5060 ---> REGISTER sip:pbx.rplaw:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bKb513517aEB6CD8ED From: "Chip (Flagstaff)" ;tag=CB36B93D-662A9AB4 To: CSeq: 123 REGISTER Call-ID: 35b6b2f0-40eeebab-ad01dd0a@192.168.254.100 Contact: ;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER" User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Authorization: Digest username="307", realm="asterisk", nonce="02fe34ce", uri="sip:pbx.rplaw:5060", response="eff67ffe3b64a91a7214a8f3193e634e", algorithm=MD5 Max-Forwards: 70 Expires: 3600 Content-Length: 0 <-------------> [Nov 16 14:51:17] VERBOSE[3200] logger.c: --- (12 headers 0 lines) --- [Nov 16 14:51:17] VERBOSE[3200] logger.c: Using latest REGISTER request as basis request [Nov 16 14:51:17] VERBOSE[3200] logger.c: Sending to 192.168.254.100 : 5060 (no NAT) [Nov 16 14:51:17] VERBOSE[3200] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bKb513517aEB6CD8ED;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=CB36B93D-662A9AB4 To: Call-ID: 35b6b2f0-40eeebab-ad01dd0a@192.168.254.100 CSeq: 123 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 14:51:17] VERBOSE[3200] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bKb513517aEB6CD8ED;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=CB36B93D-662A9AB4 To: ;tag=as784e5d2d Call-ID: 35b6b2f0-40eeebab-ad01dd0a@192.168.254.100 CSeq: 123 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="22f65f6e" Content-Length: 0 <------------> [Nov 16 14:51:17] VERBOSE[3200] logger.c: Scheduling destruction of SIP dialog '35b6b2f0-40eeebab-ad01dd0a@192.168.254.100' in 32000 ms (Method: REGISTER) [Nov 16 14:51:17] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> REGISTER sip:pbx.rplaw:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bKcf1bb4a41C7464F From: "Chip (Flagstaff)" ;tag=CB36B93D-662A9AB4 To: CSeq: 124 REGISTER Call-ID: 35b6b2f0-40eeebab-ad01dd0a@192.168.254.100 Contact: ;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER" User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Authorization: Digest username="307", realm="asterisk", nonce="22f65f6e", uri="sip:pbx.rplaw:5060", response="02f92131dd898d755d82d62dc429bc90", algorithm=MD5 Max-Forwards: 70 Expires: 3600 Content-Length: 0 <-------------> [Nov 16 14:51:17] VERBOSE[3200] logger.c: --- (12 headers 0 lines) --- [Nov 16 14:51:17] VERBOSE[3200] logger.c: Using latest REGISTER request as basis request [Nov 16 14:51:17] VERBOSE[3200] logger.c: Sending to 192.168.254.100 : 5060 (no NAT) [Nov 16 14:51:17] VERBOSE[3200] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bKcf1bb4a41C7464F;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=CB36B93D-662A9AB4 To: Call-ID: 35b6b2f0-40eeebab-ad01dd0a@192.168.254.100 CSeq: 124 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 14:51:17] VERBOSE[3200] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bKcf1bb4a41C7464F;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=CB36B93D-662A9AB4 To: ;tag=as784e5d2d Call-ID: 35b6b2f0-40eeebab-ad01dd0a@192.168.254.100 CSeq: 124 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 3600 Contact: ;expires=3600 Date: Sun, 16 Nov 2008 21:51:17 GMT Content-Length: 0 <------------> [Nov 16 14:51:17] VERBOSE[3200] logger.c: Scheduling destruction of SIP dialog '35b6b2f0-40eeebab-ad01dd0a@192.168.254.100' in 32000 ms (Method: REGISTER) [Nov 16 14:51:21] VERBOSE[3200] logger.c: Scheduling destruction of SIP dialog '637933a10ea57f5a29d7c39435f41a92@192.168.255.2' in 6400 ms (Method: NOTIFY) [Nov 16 14:51:21] VERBOSE[3200] logger.c: Reliably Transmitting (no NAT) to 192.168.254.100:5060: NOTIFY sip:307@192.168.254.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK1b94df98;rport From: "Unknown" ;tag=as480173b2 To: Contact: Call-ID: 637933a10ea57f5a29d7c39435f41a92@192.168.255.2 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 93 Messages-Waiting: no Message-Account: sip:asterisk@192.168.255.2 Voice-Message: 0/0 (0/0) --- [Nov 16 14:51:21] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK1b94df98;rport From: "Unknown" ;tag=as480173b2 To: ;tag=6A6C41DE-5EAA3081 CSeq: 102 NOTIFY Call-ID: 637933a10ea57f5a29d7c39435f41a92@192.168.255.2 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Content-Length: 0 <-------------> [Nov 16 14:51:21] VERBOSE[3200] logger.c: --- (10 headers 0 lines) --- [Nov 16 14:51:21] VERBOSE[3200] logger.c: Really destroying SIP dialog '637933a10ea57f5a29d7c39435f41a92@192.168.255.2' Method: NOTIFY [Nov 16 14:51:30] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> INVITE sip:8913738@pbx.rplaw:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK9a87f7a8AC2A1403 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: CSeq: 1 INVITE Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 255 v=0 o=- 1226871209 1226871209 IN IP4 192.168.254.100 s=Polycom IP Phone c=IN IP4 192.168.254.100 t=0 0 m=audio 2236 RTP/AVP 18 0 8 101 a=sendrecv a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Nov 16 14:51:30] VERBOSE[3200] logger.c: --- (14 headers 11 lines) --- [Nov 16 14:51:30] VERBOSE[3200] logger.c: Sending to 192.168.254.100 : 5060 (no NAT) [Nov 16 14:51:30] VERBOSE[3200] logger.c: Using INVITE request as basis request - 40137882-903b4155-5a49aaec@192.168.254.100 [Nov 16 14:51:30] VERBOSE[3200] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK9a87f7a8AC2A1403;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: ;tag=as44f1cbf5 Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2373f9f2" Content-Length: 0 <------------> [Nov 16 14:51:30] VERBOSE[3200] logger.c: Scheduling destruction of SIP dialog '40137882-903b4155-5a49aaec@192.168.254.100' in 32000 ms (Method: INVITE) [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found user '307' [Nov 16 14:51:30] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> ACK sip:8913738@pbx.rplaw:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK9a87f7a8AC2A1403 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: ;tag=as44f1cbf5 CSeq: 1 ACK Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Max-Forwards: 70 Content-Length: 0 <-------------> [Nov 16 14:51:30] VERBOSE[3200] logger.c: --- (11 headers 0 lines) --- [Nov 16 14:51:30] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> INVITE sip:8913738@pbx.rplaw:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK813f9f6990CBD270 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: CSeq: 2 INVITE Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="307", realm="asterisk", nonce="2373f9f2", uri="sip:8913738@pbx.rplaw:5060;user=phone", response="b5544359370b7f304967b7a896c091d6", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 255 v=0 o=- 1226871209 1226871209 IN IP4 192.168.254.100 s=Polycom IP Phone c=IN IP4 192.168.254.100 t=0 0 m=audio 2236 RTP/AVP 18 0 8 101 a=sendrecv a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Nov 16 14:51:30] VERBOSE[3200] logger.c: --- (15 headers 11 lines) --- [Nov 16 14:51:30] VERBOSE[3200] logger.c: Sending to 192.168.254.100 : 5060 (no NAT) [Nov 16 14:51:30] VERBOSE[3200] logger.c: Using INVITE request as basis request - 40137882-903b4155-5a49aaec@192.168.254.100 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found user '307' [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found RTP audio format 18 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found RTP audio format 0 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found RTP audio format 8 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found RTP audio format 101 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Peer audio RTP is at port 192.168.254.100:2236 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found description format G729 for ID 18 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found description format PCMU for ID 0 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found description format PCMA for ID 8 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Found description format telephone-event for ID 101 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Capabilities: us - 0x100 (g729), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x100 (g729) [Nov 16 14:51:30] VERBOSE[3200] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 16 14:51:30] VERBOSE[3200] logger.c: Peer audio RTP is at port 192.168.254.100:2236 [Nov 16 14:51:30] DEBUG[3200] chan_sip.c: Call from peer '307' is 1 out of 50 [Nov 16 14:51:30] VERBOSE[3200] logger.c: Looking for 8913738 in from-internal (domain pbx.rplaw) [Nov 16 14:51:30] VERBOSE[3200] logger.c: list_route: hop: [Nov 16 14:51:30] VERBOSE[3200] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK813f9f6990CBD270;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 317 [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [8913738@from-internal:1] Macro("SIP/307-b856ca90", "dialout-trunk|1|8913738||") in new stack [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 303 [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/307-b856ca90", "DIAL_TRUNK=1") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:2] Set("SIP/307-b856ca90", "DIAL_NUMBER=8913738") in new stack [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 316 [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:3] Set("SIP/307-b856ca90", "ROUTE_PASSWD=") in new stack [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 301 [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 306 [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:4] GotoIf("SIP/307-b856ca90", "1?noauth") in new stack [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Goto (macro-dialout-trunk,s,6) [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 308 [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:6] GotoIf("SIP/307-b856ca90", "0?disabletrunk|1") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:7] Set("SIP/307-b856ca90", "_NODEST=") in new stack [Nov 16 14:51:30] VERBOSE[3134] logger.c: Extension Changed 307 new state InUse for Notify User 323 [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:8] Set("SIP/307-b856ca90", "DIAL_TRUNK_OPTIONS=trw") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:9] Set("SIP/307-b856ca90", "GROUP()=OUT_1") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:10] Macro("SIP/307-b856ca90", "user-callerid|SKIPTTL") in new stack [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:1] NoOp("SIP/307-b856ca90", "user-callerid: device 307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Noop [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:2] Set("SIP/307-b856ca90", "AMPUSER=307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/307-b856ca90", "0?report") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:4] GotoIf("SIP/307-b856ca90", "0?start") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/307-b856ca90", "REALCALLERIDNUM=307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:6] NoOp("SIP/307-b856ca90", "REALCALLERIDNUM is 307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: NoOp [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/307-b856ca90", "AMPUSER=307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/307-b856ca90", "AMPUSERCIDNAME=Chip (Flagstaff)") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/307-b856ca90", "0?report") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:10] Set("SIP/307-b856ca90", "AMPUSERCID=307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:11] Set("SIP/307-b856ca90", "CALLERID(all)="Chip (Flagstaff)" <307>") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:12] Set("SIP/307-b856ca90", "REALCALLERIDNUM=307") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:13] NoOp("SIP/307-b856ca90", "TTL: ARG1: SKIPTTL") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Noop [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:14] GotoIf("SIP/307-b856ca90", "1?continue") in new stack [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Goto (macro-user-callerid,s,23) [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-user-callerid:23] NoOp("SIP/307-b856ca90", "Using CallerID "Chip (Flagstaff)" <307>") in new stack [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: NoOp [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: Macro [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/307-b856ca90", "record-enable|307|OUT") in new stack [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/307-b856ca90", "0?2:4") in new stack [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Goto (macro-record-enable,s,4) [Nov 16 14:51:30] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/307-b856ca90", "recordingcheck|20081116-145130|1226872290.542") in new stack [Nov 16 14:51:30] VERBOSE[12687] logger.c: -- Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck [Nov 16 14:51:31] VERBOSE[12687] logger.c: recordingcheck|20081116-145130|1226872290.542: Outbound recording not enabled [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- AGI Script recordingcheck completed, returning 0 [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: AGI [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-record-enable:5] NoOp("SIP/307-b856ca90", "No recording needed") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Noop [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Macro [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:12] GotoIf("SIP/307-b856ca90", "0?skipoutcid") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/307-b856ca90", "DIAL_TRUNK_OPTIONS=W") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:14] Macro("SIP/307-b856ca90", "outbound-callerid|1") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:1] GotoIf("SIP/307-b856ca90", "1?start") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Goto (macro-outbound-callerid,s,3) [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:3] NoOp("SIP/307-b856ca90", "REALCALLERIDNUM is 307") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: NoOp [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:4] GotoIf("SIP/307-b856ca90", "1?normcid") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Goto (macro-outbound-callerid,s,9) [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:9] Set("SIP/307-b856ca90", "USEROUTCID=") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] DEBUG[12687] db.c: Unable to find key '307/emergency_cid' in family 'DEVICE' [Nov 16 14:51:31] DEBUG[12687] func_db.c: DB: DEVICE/307/emergency_cid not found in database. [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:10] Set("SIP/307-b856ca90", "EMERGENCYCID=") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:11] Set("SIP/307-b856ca90", "TRUNKOUTCID=<5208886740>") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:12] GotoIf("SIP/307-b856ca90", "1?trunkcid") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Goto (macro-outbound-callerid,s,16) [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:16] GotoIf("SIP/307-b856ca90", "0?usercid") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:17] Set("SIP/307-b856ca90", "CALLERID(all)=<5208886740>") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:18] GotoIf("SIP/307-b856ca90", "1?report") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Goto (macro-outbound-callerid,s,22) [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-outbound-callerid:22] NoOp("SIP/307-b856ca90", "CallerID set to "" <5208886740>") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: NoOp [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Macro [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:15] GotoIf("SIP/307-b856ca90", "0?nomax") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:16] GotoIf("SIP/307-b856ca90", "0?chanfull") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:17] AGI("SIP/307-b856ca90", "fixlocalprefix") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Launched AGI Script /usr/share/asterisk/agi-bin/fixlocalprefix [Nov 16 14:51:31] VERBOSE[12687] logger.c: > fixlocalprefix: Using pattern 520+NXXXXXX [Nov 16 14:51:31] VERBOSE[12687] logger.c: == fixlocalprefix: Dialpattern 520+NXXXXXX matched. 8913738 -> 5208913738 [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- AGI Script fixlocalprefix completed, returning 0 [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: AGI [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:18] Set("SIP/307-b856ca90", "OUTNUM=5208913738") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:19] Set("SIP/307-b856ca90", "custom=ZAP/g0") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Set [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:20] GotoIf("SIP/307-b856ca90", "1?gocall") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Goto (macro-dialout-trunk,s,22) [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:22] Macro("SIP/307-b856ca90", "dialout-trunk-predial-hook") in new stack [Nov 16 14:51:31] WARNING[12687] app_macro.c: Context 'macro-dialout-trunk-predial-hook' for macro 'dialout-trunk-predial-hook' lacks 's' extension, priority 1 [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: Macro [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:23] GotoIf("SIP/307-b856ca90", "0?bypass|1") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/307-b856ca90", "0?customtrunk") in new stack [Nov 16 14:51:31] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Executing [s@macro-dialout-trunk:25] Dial("SIP/307-b856ca90", "ZAP/g0/5208913738|300|W") in new stack [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Requested transfer capability: 0x00 - SPEECH [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Called g0/5208913738 [Nov 16 14:51:31] VERBOSE[12687] logger.c: Audio is at 192.168.255.2 port 18226 [Nov 16 14:51:31] VERBOSE[12687] logger.c: Adding codec 0x100 (g729) to SDP [Nov 16 14:51:31] VERBOSE[12687] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 16 14:51:31] VERBOSE[12687] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK813f9f6990CBD270;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: ;tag=as74cc641c Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 263 v=0 o=root 3126 3126 IN IP4 192.168.255.2 s=session c=IN IP4 192.168.255.2 t=0 0 m=audio 18226 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 16 14:51:31] DEBUG[3183] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1 [Nov 16 14:51:31] VERBOSE[12687] logger.c: -- Zap/1-1 is proceeding passing it to SIP/307-b856ca90 [Nov 16 14:51:33] DEBUG[3183] chan_zap.c: Enabled echo cancellation on channel 1 [Nov 16 14:51:33] VERBOSE[12687] logger.c: -- Zap/1-1 is ringing [Nov 16 14:51:33] VERBOSE[12687] logger.c: <--- Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK813f9f6990CBD270;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: ;tag=as74cc641c Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 14:51:38] DEBUG[3183] chan_zap.c: Echo cancellation already on [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Zap/1-1 answered SIP/307-b856ca90 [Nov 16 14:51:38] WARNING[12687] channel.c: No path to translate from SIP/307-b856ca90(256) to Zap/1-1(68) [Nov 16 14:51:38] WARNING[12687] app_dial.c: Had to drop call because I couldn't make SIP/307-b856ca90 compatible with Zap/1-1 [Nov 16 14:51:38] DEBUG[12687] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1 [Nov 16 14:51:38] DEBUG[12687] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call [Nov 16 14:51:38] DEBUG[12687] chan_zap.c: disabled echo cancellation on channel 1 [Nov 16 14:51:38] DEBUG[12687] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1 [Nov 16 14:51:38] DEBUG[12687] chan_zap.c: disabled echo cancellation on channel 1 [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Hungup 'Zap/1-1' [Nov 16 14:51:38] VERBOSE[12687] logger.c: == Spawn extension (macro-dialout-trunk, s, 25) exited non-zero on 'SIP/307-b856ca90' in macro 'dialout-trunk' [Nov 16 14:51:38] VERBOSE[12687] logger.c: == Spawn extension (macro-dialout-trunk, s, 25) exited non-zero on 'SIP/307-b856ca90' [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [h@macro-dialout-trunk:1] Macro("SIP/307-b856ca90", "hangupcall") in new stack [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/307-b856ca90", "w") in new stack [Nov 16 14:51:38] DEBUG[12687] app_macro.c: Executed application: ResetCDR [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [s@macro-hangupcall:2] NoCDR("SIP/307-b856ca90", "") in new stack [Nov 16 14:51:38] DEBUG[12687] app_macro.c: Executed application: NoCDR [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [s@macro-hangupcall:3] GotoIf("SIP/307-b856ca90", "1?skiprg") in new stack [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Goto (macro-hangupcall,s,6) [Nov 16 14:51:38] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [s@macro-hangupcall:6] GotoIf("SIP/307-b856ca90", "1?skipblkvm") in new stack [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Goto (macro-hangupcall,s,9) [Nov 16 14:51:38] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [s@macro-hangupcall:9] GotoIf("SIP/307-b856ca90", "1?theend") in new stack [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Goto (macro-hangupcall,s,11) [Nov 16 14:51:38] DEBUG[12687] app_macro.c: Executed application: GotoIf [Nov 16 14:51:38] VERBOSE[12687] logger.c: -- Executing [s@macro-hangupcall:11] Hangup("SIP/307-b856ca90", "") in new stack [Nov 16 14:51:38] VERBOSE[12687] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/307-b856ca90' in macro 'hangupcall' [Nov 16 14:51:38] VERBOSE[12687] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/307-b856ca90' [Nov 16 14:51:38] DEBUG[12687] chan_sip.c: Call from peer '307' removed from call limit 50 [Nov 16 14:51:38] VERBOSE[12687] logger.c: Scheduling destruction of SIP dialog '40137882-903b4155-5a49aaec@192.168.254.100' in 32000 ms (Method: INVITE) [Nov 16 14:51:38] VERBOSE[12687] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.254.100:5060 ---> SIP/2.0 603 Declined Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK813f9f6990CBD270;received=192.168.254.100 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: ;tag=as74cc641c Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 317 [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 303 [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 316 [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 301 [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 306 [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 308 [Nov 16 14:51:38] VERBOSE[3134] logger.c: Extension Changed 307 new state Idle for Notify User 323 [Nov 16 14:51:38] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> ACK sip:8913738@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.254.100;branch=z9hG4bK813f9f6990CBD270 From: "Chip (Flagstaff)" ;tag=3121FCF7-AAE15966 To: ;tag=as74cc641c CSeq: 2 ACK Call-ID: 40137882-903b4155-5a49aaec@192.168.254.100 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Proxy-Authorization: Digest username="307", realm="asterisk", nonce="2373f9f2", uri="sip:8913738@pbx.rplaw:5060;user=phone", response="b5544359370b7f304967b7a896c091d6", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Nov 16 14:51:38] VERBOSE[3200] logger.c: --- (12 headers 0 lines) --- [Nov 16 14:51:48] VERBOSE[3200] logger.c: Reliably Transmitting (no NAT) to 192.168.254.100:5060: OPTIONS sip:307@192.168.254.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK65f3a86f;rport From: "Unknown" ;tag=as783c72ba To: Contact: Call-ID: 1bb5e242062188de7835c2b1542877ad@192.168.255.2 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Sun, 16 Nov 2008 21:51:48 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Nov 16 14:51:48] VERBOSE[3200] logger.c: <--- SIP read from 192.168.254.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK65f3a86f;rport From: "Unknown" ;tag=as783c72ba To: ;tag=DED2D351-1672CE38 CSeq: 102 OPTIONS Call-ID: 1bb5e242062188de7835c2b1542877ad@192.168.255.2 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.2.2.0084 Content-Length: 0 <-------------> [Nov 16 14:51:48] VERBOSE[3200] logger.c: --- (10 headers 0 lines) --- [Nov 16 14:51:48] VERBOSE[3200] logger.c: Really destroying SIP dialog '1bb5e242062188de7835c2b1542877ad@192.168.255.2' Method: OPTIONS