---
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Macro("SIP/201-0899c6d8", "exten-vm|novm|288") in new stack
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Macro("SIP/201-0899c6d8", "user-callerid") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is 'device'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing NoOp("SIP/201-0899c6d8", "user-callerid: device 201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Noop
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '1'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "AMPUSER=201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "0?report") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Not taking any branch
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "0?start") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Not taking any branch
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "REALCALLERIDNUM=201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing NoOp("SIP/201-0899c6d8", "REALCALLERIDNUM is 201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: NoOp
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "AMPUSER=201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is 'Office'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "AMPUSERCIDNAME=Office") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "0?report") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Not taking any branch
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '1'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '1'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "AMPUSERCID=201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "CALLERID(all)="Office" <201>") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "REALCALLERIDNUM=201") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing NoOp("SIP/201-0899c6d8", "TTL: ARG1: novm") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Noop
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "0?continue") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Not taking any branch
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '1'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '-1'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '64'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "__TTL=64") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '1'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "1?continue") in new stack
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Goto (macro-user-callerid,s,23)
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '"Office" <201>'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing NoOp("SIP/201-0899c6d8", "Using CallerID "Office" <201>") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: NoOp
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Macro
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "FROMCONTEXT=exten-vm") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "VMBOX=novm") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "EXTTOCALL=288") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] db.c: Unable to find key '288' in family 'CFU'
Feb 1 12:19:19 DEBUG[4444] func_db.c: DB: CFU/288 not found in database.
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is ''
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "CFUEXT=") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] db.c: Unable to find key '288' in family 'CFB'
Feb 1 12:19:19 DEBUG[4444] func_db.c: DB: CFB/288 not found in database.
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is ''
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "CFBEXT=") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is ''
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "RT=") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Macro("SIP/201-0899c6d8", "record-enable|288|IN") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '0'
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "0?2:4") in new stack
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Goto (macro-record-enable,s,4)
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 DEBUG[4444] pbx.c: Function result is '20080201-121919'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing AGI("SIP/201-0899c6d8", "recordingcheck|20080201-121919|1201897159.14") in new stack
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Feb 1 12:19:19 VERBOSE[4444] logger.c: recordingcheck|20080201-121919|1201897159.14: Inbound recording not enabled
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- AGI Script recordingcheck completed, returning 0
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: AGI
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing NoOp("SIP/201-0899c6d8", "No recording needed") in new stack
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Noop
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: Macro
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Macro("SIP/201-0899c6d8", "dial||tr|288") in new stack
Feb 1 12:19:19 DEBUG[4444] pbx.c: Expression result is '1'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "1?dial") in new stack
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Goto (macro-dial,s,3)
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing AGI("SIP/201-0899c6d8", "dialparties.agi") in new stack
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Feb 1 12:19:19 VERBOSE[4444] logger.c: dialparties.agi: Starting New Dialparties.agi
Feb 1 12:19:19 DEBUG[4448] manager.c: Manager received command 'login'
Feb 1 12:19:19 VERBOSE[4448] logger.c: == Parsing '/etc/asterisk/manager.conf': Feb 1 12:19:19 VERBOSE[4448] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Feb 1 12:19:19 VERBOSE[4448] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': Feb 1 12:19:19 VERBOSE[4448] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': Found
Feb 1 12:19:19 VERBOSE[4448] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Feb 1 12:19:19 VERBOSE[4448] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Feb 1 12:19:19 DEBUG[4448] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Feb 1 12:19:19 DEBUG[4448] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Feb 1 12:19:19 DEBUG[4448] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Feb 1 12:19:19 DEBUG[4448] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Feb 1 12:19:19 VERBOSE[4448] logger.c: == Manager 'admin' logged on from 127.0.0.1
Feb 1 12:19:19 VERBOSE[4444] logger.c: dialparties.agi: Caller ID name is 'Office' number is '201'
Feb 1 12:19:19 VERBOSE[4444] logger.c: dialparties.agi: Methodology of ring is 'none'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- dialparties.agi: Added extension 288 to extension map
Feb 1 12:19:19 DEBUG[4444] db.c: Unable to find key '288' in family 'CF'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- dialparties.agi: Extension 288 cf is disabled
Feb 1 12:19:19 DEBUG[4444] db.c: Unable to find key '288' in family 'DND'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- dialparties.agi: Extension 288 do not disturb is disabled
Feb 1 12:19:19 DEBUG[4444] db.c: Unable to find key '288' in family 'CFB'
Feb 1 12:19:19 DEBUG[4444] db.c: Unable to find key '288' in family 'CFU'
Feb 1 12:19:19 DEBUG[4448] manager.c: Manager received command 'ExtensionState'
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- dialparties.agi: dbset CALLTRACE/288 to 201
Feb 1 12:19:19 DEBUG[4448] manager.c: Manager received command 'Logoff'
Feb 1 12:19:19 VERBOSE[4448] logger.c: == Manager 'admin' logged off from 127.0.0.1
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- AGI Script dialparties.agi completed, returning 0
Feb 1 12:19:19 DEBUG[4444] app_macro.c: Executed application: AGI
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Executing Dial("SIP/201-0899c6d8", "sip/philippe@sip.espressofountain.com||tr") in new stack
Feb 1 12:19:19 DEBUG[4444] acl.c: ##### Testing 71.112.18.6 with 192.168.2.0
Feb 1 12:19:19 DEBUG[4444] chan_sip.c: Target address 71.112.18.6 is not local, substituting externip
Feb 1 12:19:19 DEBUG[4444] chan_sip.c: Outgoing Call for philippe
Feb 1 12:19:19 VERBOSE[4444] logger.c: We're at 75.148.48.213 port 10134
Feb 1 12:19:19 VERBOSE[4444] logger.c: Adding codec 0x4 (ulaw) to SDP
Feb 1 12:19:19 VERBOSE[4444] logger.c: Adding codec 0x8 (alaw) to SDP
Feb 1 12:19:19 VERBOSE[4444] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
Feb 1 12:19:19 VERBOSE[4444] logger.c: 13 headers, 11 lines
Feb 1 12:19:19 VERBOSE[4444] logger.c: Reliably Transmitting (no NAT) to 71.112.18.6:5060:
INVITE sip:philippe@sip.espressofountain.com SIP/2.0
Via: SIP/2.0/UDP 75.148.48.213:5060;branch=z9hG4bK2fefb19d;rport
From: "Office" ;tag=as078007e0
To:
Contact:
Call-ID: 1f4df7950a246cd81b93527f0bc2854f@75.148.48.213
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Fri, 01 Feb 2008 20:19:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 2936 2936 IN IP4 75.148.48.213
s=session
c=IN IP4 75.148.48.213
t=0 0
m=audio 10134 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 - - - -

---
Feb 1 12:19:19 VERBOSE[4444] logger.c: -- Called philippe@sip.espressofountain.com
Feb 1 12:19:19 VERBOSE[4444] logger.c: Transmitting (NAT) to 192.168.2.199:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.2.199;branch=z9hG4bK46c2ae393A25B600;received=192.168.2.199
From: "device" ;tag=68F2B1AA-4FB7FE93
To: ;tag=as74abdf4a
Call-ID: c9ba7e9e-3ea62134-907d83cd@192.168.2.199
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact:
Content-Length: 0


---
Feb 1 12:19:20 VERBOSE[4250] logger.c:
<-- SIP read from 71.112.18.6:5060:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 75.148.48.213:5060;branch=z9hG4bK2fefb19d;received=75.148.48.213;rport=5060
From: "Office" ;tag=as078007e0
To: ;tag=as7fa94ac1
Call-ID: 1f4df7950a246cd81b93527f0bc2854f@75.148.48.213
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact:
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2eb04bb7"
Content-Length: 0


Feb 1 12:19:20 VERBOSE[4250] logger.c: --- (11 headers 0 lines) ---
Feb 1 12:19:20 DEBUG[4250] chan_sip.c: Acked pending invite 102
Feb 1 12:19:20 DEBUG[4250] chan_sip.c: Stopping retransmission on '1f4df7950a246cd81b93527f0bc2854f@75.148.48.213' of Request 102: Match Found
Feb 1 12:19:20 VERBOSE[4250] logger.c: Transmitting (no NAT) to 71.112.18.6:5060:
ACK sip:philippe@sip.espressofountain.com SIP/2.0
Via: SIP/2.0/UDP 75.148.48.213:5060;branch=z9hG4bK2fefb19d;rport
From: "Office" ;tag=as078007e0
To: ;tag=as7fa94ac1
Contact:
Call-ID: 1f4df7950a246cd81b93527f0bc2854f@75.148.48.213
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
Feb 1 12:19:20 NOTICE[4250] chan_sip.c: Failed to authenticate on INVITE to '"Office" ;tag=as078007e0'
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- SIP/sip.espressofountain.com-0897f5f0 is circuit-busy
Feb 1 12:19:20 DEBUG[4444] chan_sip.c: update_call_counter(philippe) - decrement call limit counter
Feb 1 12:19:20 VERBOSE[4444] logger.c: == Everyone is busy/congested at this time (1:0/1/0)
Feb 1 12:19:20 DEBUG[4444] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: Dial
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Function result is 'CONGESTION'
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "DIALSTATUS=CONGESTION") in new stack
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: Macro
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "SV_DIALSTATUS=CONGESTION") in new stack
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing GosubIf("SIP/201-0899c6d8", "0?docfu|1") in new stack
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: GosubIf
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing GosubIf("SIP/201-0899c6d8", "0?docfb|1") in new stack
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: GosubIf
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '0'
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing Set("SIP/201-0899c6d8", "DIALSTATUS=CONGESTION") in new stack
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: Set
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing NoOp("SIP/201-0899c6d8", "Voicemail is novm") in new stack
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: NoOp
Feb 1 12:19:20 DEBUG[4444] pbx.c: Expression result is '1'
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing GotoIf("SIP/201-0899c6d8", "1?s-CONGESTION|1") in new stack
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Goto (macro-exten-vm,s-CONGESTION,1)
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: GotoIf
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing PlayTones("SIP/201-0899c6d8", "congestion") in new stack
Feb 1 12:19:20 DEBUG[4444] channel.c: Prodding channel 'SIP/201-0899c6d8'
Feb 1 12:19:20 VERBOSE[4444] logger.c: We're at 192.168.2.12 port 10160
Feb 1 12:19:20 VERBOSE[4444] logger.c: Adding codec 0x4 (ulaw) to SDP
Feb 1 12:19:20 VERBOSE[4444] logger.c: Adding codec 0x8 (alaw) to SDP
Feb 1 12:19:20 VERBOSE[4444] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
Feb 1 12:19:20 VERBOSE[4444] logger.c: Transmitting (NAT) to 192.168.2.199:5060:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.2.199;branch=z9hG4bK46c2ae393A25B600;received=192.168.2.199
From: "device" ;tag=68F2B1AA-4FB7FE93
To: ;tag=as74abdf4a
Call-ID: c9ba7e9e-3ea62134-907d83cd@192.168.2.199
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact:
Content-Type: application/sdp
Content-Length: 238

v=0
o=root 2936 2936 IN IP4 192.168.2.12
s=session
c=IN IP4 192.168.2.12
t=0 0
m=audio 10160 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 - - - -

---
Feb 1 12:19:20 DEBUG[4444] channel.c: Scheduling timer at 160 sample intervals
Feb 1 12:19:20 DEBUG[4444] app_macro.c: Executed application: Playtones
Feb 1 12:19:20 VERBOSE[4444] logger.c: -- Executing Congestion("SIP/201-0899c6d8", "10") in new stack
Feb 1 12:19:20 VERBOSE[4444] logger.c: Transmitting (NAT) to 192.168.2.199:5060:
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 192.168.2.199;branch=z9hG4bK46c2ae393A25B600;received=192.168.2.199
From: "device" ;tag=68F2B1AA-4FB7FE93
To: ;tag=as74abdf4a
Call-ID: c9ba7e9e-3ea62134-907d83cd@192.168.2.199
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact:
Content-Length: 0
X-Asterisk-HangupCause: Normal Clearing


---
Feb 1 12:19:20 DEBUG[4444] channel.c: Scheduling timer at 0 sample intervals
Feb 1 12:19:20 VERBOSE[4444] logger.c: == Spawn extension (macro-exten-vm, s-CONGESTION, 2) exited non-zero on 'SIP/201-0899c6d8' in macro 'exten-vm'
Feb 1 12:19:20 VERBOSE[4444] logger.c: == Spawn extension (macro-exten-vm, s-CONGESTION, 2) exited non-zero on 'SIP/201-0899c6d8'
Feb 1 12:19:20 DEBUG[4444] chan_sip.c: update_call_counter(201) - decrement call limit counter
Feb 1 12:19:20 DEBUG[4444] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Feb 1 12:19:20 DEBUG[4444] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2008-02-01 12:19:19','\"Office\" <201>','201','288','from-internal', 'SIP/201-0899c6d8','SIP/sip.espressofountain.com-0897f5f0','Congestion','10',1,0,'FAILED',3,'','1201897159.14')
Feb 1 12:19:20 VERBOSE[4250] logger.c:
<-- SIP read from 74.95.44.189:5004:
REGISTER sip:gw-ansi.dyndns.org SIP/2.0
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER"
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
Max-Forwards: 70
Contact: "$USER" ;expires=3600
User-Agent: Linksys/SPA942-5.1.10
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces


Feb 1 12:19:20 VERBOSE[4250] logger.c: --- (12 headers 0 lines) ---
Feb 1 12:19:20 VERBOSE[4250] logger.c: Using latest REGISTER request as basis request
Feb 1 12:19:20 VERBOSE[4250] logger.c: Sending to 192.168.3.200 : 5004 (non-NAT)
Feb 1 12:19:20 VERBOSE[4250] logger.c: Transmitting (no NAT) to 192.168.3.200:5004:
SIP/2.0 404 Not found
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56;received=74.95.44.189
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER" ;tag=as0dce93c9
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


---
Feb 1 12:19:20 NOTICE[4250] chan_sip.c: Registration from '"$USER" ' failed for '74.95.44.189' - ACL error (permit/deny)
Feb 1 12:19:20 VERBOSE[4250] logger.c: Scheduling destruction of call '585562f1-b3e945e3@192.168.3.200' in 15000 ms
Feb 1 12:19:20 VERBOSE[4250] logger.c: Destroying call '1f4df7950a246cd81b93527f0bc2854f@75.148.48.213'
Feb 1 12:19:20 VERBOSE[4250] logger.c: Destroying call 'c9ba7e9e-3ea62134-907d83cd@192.168.2.199'
Feb 1 12:19:20 VERBOSE[4250] logger.c:
<-- SIP read from 192.168.2.199:5060:
ACK sip:288@192.168.2.12 SIP/2.0
Via: SIP/2.0/UDP 192.168.2.199;branch=z9hG4bK46c2ae393A25B600
From: "device" ;tag=68F2B1AA-4FB7FE93
To: ;tag=as74abdf4a
CSeq: 2 ACK
Call-ID: c9ba7e9e-3ea62134-907d83cd@192.168.2.199
Contact:
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.0.1.0291
Proxy-Authorization: Digest username="201", realm="asterisk", nonce="4f980003", uri="sip:288@192.168.2.12;user=phone", response="ae50a8cca48b165a113c63f63e3c2fa5", algorithm=MD5
Max-Forwards: 70
Content-Length: 0


Feb 1 12:19:20 VERBOSE[4250] logger.c: --- (12 headers 0 lines) ---
Feb 1 12:19:22 DEBUG[4250] chan_sip.c: Auto destroying call '6cc98810300b29ac1e00ab323f375230@127.0.0.1'
Feb 1 12:19:22 VERBOSE[4250] logger.c: Destroying call '6cc98810300b29ac1e00ab323f375230@127.0.0.1'
Feb 1 12:19:24 VERBOSE[4250] logger.c:
<-- SIP read from 74.95.44.189:5004:
REGISTER sip:gw-ansi.dyndns.org SIP/2.0
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER"
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
Max-Forwards: 70
Contact: "$USER" ;expires=3600
User-Agent: Linksys/SPA942-5.1.10
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces


Feb 1 12:19:24 VERBOSE[4250] logger.c: --- (12 headers 0 lines) ---
Feb 1 12:19:24 VERBOSE[4250] logger.c: Using latest REGISTER request as basis request
Feb 1 12:19:24 VERBOSE[4250] logger.c: Sending to 192.168.3.200 : 5004 (non-NAT)
Feb 1 12:19:24 VERBOSE[4250] logger.c: Transmitting (no NAT) to 192.168.3.200:5004:
SIP/2.0 404 Not found
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56;received=74.95.44.189
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER" ;tag=as0dce93c9
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


---
Feb 1 12:19:24 NOTICE[4250] chan_sip.c: Registration from '"$USER" ' failed for '74.95.44.189' - ACL error (permit/deny)
Feb 1 12:19:24 VERBOSE[4250] logger.c: Scheduling destruction of call '585562f1-b3e945e3@192.168.3.200' in 15000 ms
Feb 1 12:19:26 VERBOSE[4250] logger.c:
<-- SIP read from 74.95.44.189:5004:
NOTIFY sip:gw-ansi.dyndns.org SIP/2.0
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-56ceec4e
From: "$USER" ;tag=b8db68487663b441o1
To:
Call-ID: 8401a32c-dab616ad@192.168.3.200
CSeq: 160587 NOTIFY
Max-Forwards: 70
Event: keep-alive
User-Agent: Linksys/SPA942-5.1.10
Content-Length: 0


Feb 1 12:19:26 VERBOSE[4250] logger.c: --- (10 headers 0 lines) ---
Feb 1 12:19:26 DEBUG[4250] acl.c: ##### Testing 74.95.44.189 with 192.168.2.0
Feb 1 12:19:26 DEBUG[4250] chan_sip.c: Target address 74.95.44.189 is not local, substituting externip
Feb 1 12:19:26 VERBOSE[4250] logger.c: Transmitting (no NAT) to 74.95.44.189:5004:
SIP/2.0 603 Declined (no dialog)
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-56ceec4e;received=74.95.44.189
From: "$USER" ;tag=b8db68487663b441o1
To: ;tag=as52fa176d
Call-ID: 8401a32c-dab616ad@192.168.3.200
CSeq: 160587 NOTIFY
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


---
Feb 1 12:19:28 VERBOSE[4250] logger.c:
<-- SIP read from 74.95.44.189:5004:
REGISTER sip:gw-ansi.dyndns.org SIP/2.0
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER"
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
Max-Forwards: 70
Contact: "$USER" ;expires=3600
User-Agent: Linksys/SPA942-5.1.10
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces


Feb 1 12:19:28 VERBOSE[4250] logger.c: --- (12 headers 0 lines) ---
Feb 1 12:19:28 VERBOSE[4250] logger.c: Using latest REGISTER request as basis request
Feb 1 12:19:28 VERBOSE[4250] logger.c: Sending to 192.168.3.200 : 5004 (non-NAT)
Feb 1 12:19:28 VERBOSE[4250] logger.c: Transmitting (no NAT) to 192.168.3.200:5004:
SIP/2.0 404 Not found
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56;received=74.95.44.189
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER" ;tag=as0dce93c9
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


---
Feb 1 12:19:28 NOTICE[4250] chan_sip.c: Registration from '"$USER" ' failed for '74.95.44.189' - ACL error (permit/deny)
Feb 1 12:19:28 VERBOSE[4250] logger.c: Scheduling destruction of call '585562f1-b3e945e3@192.168.3.200' in 15000 ms
Feb 1 12:19:32 VERBOSE[4250] logger.c:
<-- SIP read from 74.95.44.189:5004:
REGISTER sip:gw-ansi.dyndns.org SIP/2.0
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER"
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
Max-Forwards: 70
Contact: "$USER" ;expires=3600
User-Agent: Linksys/SPA942-5.1.10
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces


Feb 1 12:19:32 VERBOSE[4250] logger.c: --- (12 headers 0 lines) ---
Feb 1 12:19:32 VERBOSE[4250] logger.c: Using latest REGISTER request as basis request
Feb 1 12:19:32 VERBOSE[4250] logger.c: Sending to 192.168.3.200 : 5004 (non-NAT)
Feb 1 12:19:32 VERBOSE[4250] logger.c: Transmitting (no NAT) to 192.168.3.200:5004:
SIP/2.0 404 Not found
Via: SIP/2.0/UDP 192.168.3.200:5004;branch=z9hG4bK-eac09b56;received=74.95.44.189
From: "$USER" ;tag=b8db68487663b441o1
To: "$USER" ;tag=as0dce93c9
Call-ID: 585562f1-b3e945e3@192.168.3.200
CSeq: 133614 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


---
Feb 1 12:19:32 NOTICE[4250] chan_sip.c: Registration from '"$USER" ' failed for '74.95.44.189' - ACL error (permit/deny)
Feb 1 12:19:32 VERBOSE[4250] logger.c: Scheduling destruction of call '585562f1-b3e945e3@192.168.3.200' in 15000 ms
Feb 1 12:19:35 DEBUG[4250] acl.c: ##### Testing 64.2.142.31 with 192.168.2.0
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: Target address 64.2.142.31 is not local, substituting externip
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: Scheduled a registration timeout for inbound5.vitelity.net id #2888
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6cc98810300b29ac1e00ab323f375230@127.0.0.1' Request 160: Found
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: Stopping retransmission on '6cc98810300b29ac1e00ab323f375230@127.0.0.1' of Request 160: Match Found
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6cc98810300b29ac1e00ab323f375230@127.0.0.1' Request 161: Found
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: Stopping retransmission on '6cc98810300b29ac1e00ab323f375230@127.0.0.1' of Request 161: Match Found
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: Registration successful
Feb 1 12:19:35 DEBUG[4250] chan_sip.c: Cancelling timeout 2888
Feb 1 12:19:36 DEBUG[4452] manager.c: Manager received command 'login'
Feb 1 12:19:36 VERBOSE[4452] logger.c: == Parsing '/etc/asterisk/manager.conf': Feb 1 12:19:36 VERBOSE[4452] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Feb 1 12:19:36 VERBOSE[4452] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': Feb 1 12:19:36 VERBOSE[4452] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': Found
Feb 1 12:19:36 VERBOSE[4452] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Feb 1 12:19:36 VERBOSE[4452] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Feb 1 12:19:36 DEBUG[4452] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Feb 1 12:19:36 DEBUG[4452] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Feb 1 12:19:36 DEBUG[4452] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Feb 1 12:19:36 DEBUG[4452] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Feb 1 12:19:36 VERBOSE[4452] logger.c: == Manager 'admin' logged on from 127.0.0.1
Feb 1 12:19:36 VERBOSE[4452] logger.c: == Manager 'admin' logged on from 127.0.0.1