[Feb  3 13:05:21] DEBUG[20748] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb  3 13:05:21] DEBUG[20748] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb  3 13:05:21] VERBOSE[20748] chan_dahdi.c:     -- Accepting overlap call from 'XXXXXXXXXX' to 'XXXX143' on channel 0/5, span 1
[Feb  3 13:05:21] VERBOSE[8041] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/5-1'
[Feb  3 13:05:24] DEBUG[8041] chan_dahdi.c: Enabled echo cancellation on channel 5
[Feb  3 13:05:24] DEBUG[8041] pbx.c: Launching 'Macro'
[Feb  3 13:05:24] VERBOSE[8041] pbx.c:     -- Executing [XXXX143@default:1] Macro("DAHDI/5-1", "vm,143") in new stack
[Feb  3 13:05:24] DEBUG[8041] pbx.c: Launching 'Dial'
[Feb  3 13:05:24] VERBOSE[8041] pbx.c:     -- Executing [s@macro-vm:1] Dial("DAHDI/5-1", "SIP/143,15,tTkK") in new stack
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Feb  3 13:05:24] VERBOSE[8041] netsock.c:   == Using SIP RTP CoS mark 5
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: Allocating new SIP dialog for 28a3245c12ab137f32055efc2b7d0918@XXX.XXX.XXX.XXX - INVITE (With RTP)
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: Setting NAT on RTP to Off
[Feb  3 13:05:24] DEBUG[8041] rtp.c: Channel 'DAHDI/5-1' has no RTP, not doing anything
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable DIALEDTIME.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable ANSWEREDTIME.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable DIALEDPEERNAME.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable DIALEDPEERNUMBER.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable DIALSTATUS.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable MACRO_DEPTH.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable ARG1.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable MACRO_PRIORITY.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable MACRO_CONTEXT.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable MACRO_EXTEN.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable CALLEDTON.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable ANI2.
[Feb  3 13:05:24] DEBUG[8041] channel.c: Not copying variable TRANSFERCAPABILITY.
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: Outgoing Call for 143
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) 
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: Initializing initreq for method INVITE - callid 133f5e9e4534d68063119a7c566fde1d@192.168.1.100
[Feb  3 13:05:24] DEBUG[8041] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:24] VERBOSE[8041] app_dial.c:     -- Called 143
[Feb  3 13:05:24] VERBOSE[8041] app_dial.c:     -- SIP/143-00000139 is ringing
[Feb  3 13:05:24] DEBUG[8041] chan_dahdi.c: Requested indication 3 on channel DAHDI/5-1
[Feb  3 13:05:25] VERBOSE[8041] app_dial.c:     -- SIP/143-00000139 answered DAHDI/5-1
[Feb  3 13:05:25] DEBUG[8041] channel.c: Driver for channel 'SIP/143-00000139' does not support indication 3, emulating it
[Feb  3 13:05:25] DEBUG[8041] channel.c: Set channel SIP/143-00000139 to write format slin
[Feb  3 13:05:25] DEBUG[8041] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb  3 13:05:25] DEBUG[8041] chan_dahdi.c: Requested indication -1 on channel DAHDI/5-1
[Feb  3 13:05:25] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:25] DEBUG[8041] channel.c: Set channel SIP/143-00000139 to write format ulaw
[Feb  3 13:05:25] DEBUG[8041] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:25] DEBUG[8041] rtp.c: Ooh, format changed from unknown to ulaw
[Feb  3 13:05:25] DEBUG[8041] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Feb  3 13:05:28] DEBUG[8041] chan_dahdi.c: Requested indication 16 on channel DAHDI/5-1
[Feb  3 13:05:28] VERBOSE[8041] res_musiconhold.c:     -- Started music on hold, class 'default', on DAHDI/5-1
[Feb  3 13:05:28] DEBUG[8041] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb  3 13:05:28] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:28] DEBUG[8041] channel.c: Generator got voice, switching to phase locked mode
[Feb  3 13:05:28] DEBUG[8041] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:28] DEBUG[8041] channel.c: Set channel DAHDI/5-1 to write format slin
[Feb  3 13:05:28] DEBUG[8041] res_musiconhold.c: DAHDI/5-1 Opened file 1 '/var/lib/asterisk/mohmp3/fpm-sunshine'
[Feb  3 13:05:29] DEBUG[8041] channel.c: Got DTMF begin on channel (DAHDI/5-1)
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: DTMF digit: 1 on DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Got DTMF end on channel (DAHDI/5-1)
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:29] DEBUG[20788] chan_dahdi.c: DTMF digit: 7 on DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Got DTMF begin on channel (DAHDI/5-1)
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Got DTMF end on channel (DAHDI/5-1)
[Feb  3 13:05:29] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:29] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:29] DEBUG[20788] chan_dahdi.c: DTMF digit: 8 on DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Got DTMF begin on channel (DAHDI/5-1)
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] VERBOSE[20725] netsock.c:   == Using SIP RTP CoS mark 5
[Feb  3 13:05:30] DEBUG[20725] chan_sip.c: Setting NAT on RTP to Off
[Feb  3 13:05:30] DEBUG[20725] chan_sip.c: Allocating new SIP dialog for 001a2fcb-80b00052-3d237e98-7a2bd5eb@192.168.1.2 - INVITE (With RTP)
[Feb  3 13:05:30] DEBUG[20725] chan_sip.c: Setting NAT on RTP to Off
[Feb  3 13:05:30] DEBUG[20725] chan_sip.c: Checking SIP call limits for device 143
[Feb  3 13:05:30] DEBUG[20725] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:30] DEBUG[8044] pbx.c: Launching 'Macro'
[Feb  3 13:05:30] VERBOSE[8044] pbx.c:     -- Executing [178@default:1] Macro("SIP/143-0000013a", "vm,178") in new stack
[Feb  3 13:05:30] DEBUG[8044] pbx.c: Launching 'Dial'
[Feb  3 13:05:30] VERBOSE[8044] pbx.c:     -- Executing [s@macro-vm:1] Dial("SIP/143-0000013a", "SIP/178,15,tTkK") in new stack
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Feb  3 13:05:30] VERBOSE[8044] netsock.c:   == Using SIP RTP CoS mark 5
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Allocating new SIP dialog for 2d0079d03007c97a26bd803d44ccc9a8@XXX.XXX.XXX.XXX - INVITE (With RTP)
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Setting NAT on RTP to Off
[Feb  3 13:05:30] DEBUG[8044] rtp.c: Seeded SDP of 'SIP/178-0000013b' with that of 'SIP/143-0000013a'
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable DIALEDTIME.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable ANSWEREDTIME.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable DIALEDPEERNAME.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable DIALEDPEERNUMBER.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable DIALSTATUS.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable MACRO_DEPTH.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable ARG1.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable MACRO_PRIORITY.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable MACRO_CONTEXT.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable MACRO_EXTEN.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable SIPCALLID.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable SIPDOMAIN.
[Feb  3 13:05:30] DEBUG[8044] channel.c: Not copying variable SIPURI.
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Outgoing Call for 178
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) 
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Initializing initreq for method INVITE - callid 7090a5946d7c4a9069d3ad58663a1caa@192.168.1.100
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.5:5060
[Feb  3 13:05:30] VERBOSE[8044] app_dial.c:     -- Called 178
[Feb  3 13:05:30] DEBUG[8041] channel.c: Got DTMF end on channel (DAHDI/5-1)
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:30] DEBUG[20788] chan_dahdi.c: DTMF digit: # on DAHDI/5-1
[Feb  3 13:05:30] VERBOSE[8044] app_dial.c:     -- SIP/178-0000013b is ringing
[Feb  3 13:05:30] DEBUG[8044] rtp.c: Setting early bridge SDP of 'SIP/143-0000013a' with that of 'SIP/178-0000013b'
[Feb  3 13:05:30] DEBUG[8044] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Got DTMF begin on channel (DAHDI/5-1)
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Got DTMF end on channel (DAHDI/5-1)
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:30] DEBUG[8041] channel.c: Bridge stops bridging channels DAHDI/5-1 and SIP/143-00000139
[Feb  3 13:05:30] DEBUG[8041] chan_dahdi.c: Requested indication 20 on channel DAHDI/5-1
[Feb  3 13:05:31] DEBUG[20725] chan_sip.c: Trying to put 'SIP/2.0 202' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:31] VERBOSE[20725] res_musiconhold.c:     -- Stopped music on hold on DAHDI/5-1
[Feb  3 13:05:31] DEBUG[20725] channel.c: Set channel DAHDI/5-1 to write format ulaw
[Feb  3 13:05:31] DEBUG[20725] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:31] DEBUG[20725] channel.c: Planning to masquerade channel DAHDI/5-1 into the structure of SIP/143-0000013a
[Feb  3 13:05:31] DEBUG[20725] channel.c: Done planning to masquerade channel DAHDI/5-1 into the structure of SIP/143-0000013a
[Feb  3 13:05:31] DEBUG[20725] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:31] DEBUG[20725] chan_sip.c: SIP attended transfer: Unlocking channel SIP/143-0000013a
[Feb  3 13:05:31] DEBUG[8041] chan_dahdi.c: Requested indication 17 on channel DAHDI/5-1
[Feb  3 13:05:31] DEBUG[8044] chan_sip.c: Hangup call DAHDI/5-1<MASQ>, SIP callid 001a2fcb-80b00052-3d237e98-7a2bd5eb@192.168.1.2
[Feb  3 13:05:31] DEBUG[8044] chan_sip.c: AST hangup cause 16 (no match found in SIP)
[Feb  3 13:05:31] DEBUG[8044] chan_sip.c: Trying to put 'SIP/2.0 603' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:31] DEBUG[8044] channel.c: Putting channel DAHDI/5-1 in 4/4 formats
[Feb  3 13:05:31] DEBUG[8044] chan_dahdi.c: New owner for channel 5 is DAHDI/5-1
[Feb  3 13:05:31] DEBUG[8044] chan_dahdi.c: Updated conferencing on 5, with 0 conference users
[Feb  3 13:05:31] DEBUG[8044] chan_dahdi.c: Updated conferencing on 5, with 0 conference users
[Feb  3 13:05:31] DEBUG[8044] chan_dahdi.c: Requested indication 3 on channel DAHDI/5-1
[Feb  3 13:05:31] DEBUG[8044] channel.c: Released clone lock on 'SIP/143-0000013a<ZOMBIE>'
[Feb  3 13:05:31] DEBUG[8044] channel.c: Done Masquerading DAHDI/5-1 (6)
[Feb  3 13:05:31] DEBUG[8041] channel.c: Didn't get a frame from channel: SIP/143-0000013a<ZOMBIE>
[Feb  3 13:05:31] DEBUG[8041] channel.c: Bridge stops bridging channels SIP/143-0000013a<ZOMBIE> and SIP/143-00000139
[Feb  3 13:05:31] DEBUG[8041] channel.c: Hanging up channel 'SIP/143-00000139'
[Feb  3 13:05:31] DEBUG[8041] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Feb  3 13:05:31] DEBUG[8041] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Feb  3 13:05:31] VERBOSE[8041] app_macro.c:   == Spawn extension (macro-vm, s, 1) exited non-zero on 'SIP/143-0000013a<ZOMBIE>' in macro 'vm'
[Feb  3 13:05:31] DEBUG[8041] pbx.c: Spawn extension (default,XXXX143,1) exited non-zero on 'SIP/143-0000013a<ZOMBIE>'
[Feb  3 13:05:31] VERBOSE[8041] pbx.c:   == Spawn extension (default, XXXX143, 1) exited non-zero on 'SIP/143-0000013a<ZOMBIE>'
[Feb  3 13:05:31] DEBUG[8041] channel.c: Soft-Hanging up channel 'SIP/143-0000013a<ZOMBIE>'
[Feb  3 13:05:31] DEBUG[8041] channel.c: Hanging up zombie 'SIP/143-0000013a<ZOMBIE>'
[Feb  3 13:05:32] DEBUG[20725] chan_sip.c: Stopping retransmission on '133f5e9e4534d68063119a7c566fde1d@192.168.1.100' of Request 103: Match Found
[Feb  3 13:05:32] DEBUG[20725] chan_sip.c: Stopping retransmission on '001a2fcb-80b00052-3d237e98-7a2bd5eb@192.168.1.2' of Response 101: Match Found
[Feb  3 13:05:32] DEBUG[20725] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:45] VERBOSE[8044] app_dial.c:     -- Nobody picked up in 15000 ms
[Feb  3 13:05:45] DEBUG[8044] channel.c: Hanging up channel 'SIP/178-0000013b'
[Feb  3 13:05:45] DEBUG[8044] chan_sip.c: Hangup call SIP/178-0000013b, SIP callid 7090a5946d7c4a9069d3ad58663a1caa@192.168.1.100
[Feb  3 13:05:45] DEBUG[8044] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7090a5946d7c4a9069d3ad58663a1caa@192.168.1.100' Request 102: Found
[Feb  3 13:05:45] DEBUG[8044] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for 192.168.1.5:5060
[Feb  3 13:05:45] DEBUG[8044] app_dial.c: Exiting with DIALSTATUS=NOANSWER.
[Feb  3 13:05:45] DEBUG[8044] app_macro.c: Executed application: Dial
[Feb  3 13:05:45] DEBUG[8044] pbx.c: Launching 'Goto'
[Feb  3 13:05:45] VERBOSE[8044] pbx.c:     -- Executing [s@macro-vm:2] Goto("DAHDI/5-1", "s-NOANSWER,1") in new stack
[Feb  3 13:05:45] VERBOSE[8044] pbx.c:     -- Goto (macro-vm,s-NOANSWER,1)
[Feb  3 13:05:45] DEBUG[8044] app_macro.c: Executed application: Goto
[Feb  3 13:05:45] DEBUG[8044] pbx.c: Launching 'VoiceMail'
[Feb  3 13:05:45] VERBOSE[8044] pbx.c:     -- Executing [s-NOANSWER@macro-vm:1] VoiceMail("DAHDI/5-1", "143,su") in new stack
[Feb  3 13:05:45] DEBUG[8044] channel.c: Set channel DAHDI/5-1 to write format slin
[Feb  3 13:05:45] DEBUG[8044] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb  3 13:05:45] VERBOSE[8044] file.c:     -- <DAHDI/5-1> Playing '/var/spool/asterisk/voicemail/default/143/unavail.slin' (language 'en')
[Feb  3 13:05:45] DEBUG[20725] chan_sip.c: Acked pending invite 102
[Feb  3 13:05:45] DEBUG[20725] chan_sip.c: Stopping retransmission on '7090a5946d7c4a9069d3ad58663a1caa@192.168.1.100' of Request 102: Match Found
[Feb  3 13:05:45] DEBUG[20725] chan_sip.c: Stopping retransmission on '7090a5946d7c4a9069d3ad58663a1caa@192.168.1.100' of Request 102: Match Found
[Feb  3 13:05:45] DEBUG[20725] chan_sip.c: Trying to put 'ACK sip:178' onto UDP socket destined for 192.168.1.5:5060
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (58 requested / 58 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Set channel DAHDI/5-1 to write format ulaw
[Feb  3 13:05:52] DEBUG[8044] app.c: Locked path '/var/spool/asterisk/voicemail/default/143/INBOX'
[Feb  3 13:05:52] DEBUG[8044] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/143/INBOX'
[Feb  3 13:05:52] DEBUG[8044] channel.c: Set channel DAHDI/5-1 to write format gsm
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb  3 13:05:52] VERBOSE[8044] file.c:     -- <DAHDI/5-1> Playing 'beep.gsm' (language 'en')
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb  3 13:05:52] DEBUG[8044] channel.c: Set channel DAHDI/5-1 to write format ulaw
[Feb  3 13:05:52] VERBOSE[8044] app_voicemail.c:     -- Recording the message
[Feb  3 13:05:52] DEBUG[8044] app.c: play_and_record: <None>, /var/spool/asterisk/voicemail/default/143/tmp/iy2c0w, 'wav49|gsm'
[Feb  3 13:05:52] DEBUG[8044] app.c: Recording Formats: sfmts=wav49
[Feb  3 13:05:52] VERBOSE[8044] app.c:     -- x=0, open writing:  /var/spool/asterisk/voicemail/default/143/tmp/iy2c0w format: wav49, 0x824a6e8
[Feb  3 13:05:52] VERBOSE[8044] app.c:     -- x=1, open writing:  /var/spool/asterisk/voicemail/default/143/tmp/iy2c0w format: gsm, 0x81f9ac8
[Feb  3 13:05:52] DEBUG[8044] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb  3 13:05:52] DEBUG[8044] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb  3 13:05:52] DEBUG[8044] channel.c: Set channel DAHDI/5-1 to read format slin
[Feb  3 13:05:52] DEBUG[8044] chan_dahdi.c: Requested indication 18 on channel DAHDI/5-1
[Feb  3 13:05:54] VERBOSE[20748] chan_dahdi.c:     -- Channel 0/5, span 1 got hangup request, cause 16
[Feb  3 13:05:54] VERBOSE[8044] app.c:     -- User hung up
[Feb  3 13:05:54] DEBUG[8044] channel.c: Set channel DAHDI/5-1 to read format ulaw
[Feb  3 13:05:54] DEBUG[8044] app.c: Locked path '/var/spool/asterisk/voicemail/default/143/INBOX'
[Feb  3 13:05:54] DEBUG[8044] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/143/INBOX'
[Feb  3 13:05:54] DEBUG[8044] app_voicemail.c: Sent mail to herb@cfht.hawaii.edu with command '/usr/sbin/sendmail -t'
[Feb  3 13:05:54] DEBUG[20716] chan_sip.c: Allocating new SIP dialog for 387ff58c74ca9d8154b2ffc80aff9998@XXX.XXX.XXX.XXX - NOTIFY (No RTP)
[Feb  3 13:05:54] VERBOSE[8044] app_macro.c:   == Spawn extension (macro-vm, s-NOANSWER, 1) exited non-zero on 'DAHDI/5-1' in macro 'vm'
[Feb  3 13:05:54] DEBUG[20716] chan_sip.c: Initializing initreq for method NOTIFY - callid 3c41be2c30048f374845bd86474bceaa@192.168.1.100
[Feb  3 13:05:54] DEBUG[8044] pbx.c: Spawn extension (default,178,1) exited non-zero on 'DAHDI/5-1'
[Feb  3 13:05:54] VERBOSE[8044] pbx.c:   == Spawn extension (default, 178, 1) exited non-zero on 'DAHDI/5-1'
[Feb  3 13:05:54] DEBUG[20716] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.1.2:5060
[Feb  3 13:05:54] DEBUG[8044] channel.c: Soft-Hanging up channel 'DAHDI/5-1'
[Feb  3 13:05:54] DEBUG[8044] channel.c: Hanging up channel 'DAHDI/5-1'
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: dahdi_hangup(DAHDI/5-1)
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/5-1
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Hangup: channel: 5 index = 0, normal = 23, callwait = -1, thirdcall = -1
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Disabled echo cancellation on channel 5
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/5-1
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Updated conferencing on 5, with 0 conference users
[Feb  3 13:05:54] DEBUG[8044] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/5-1
[Feb  3 13:05:54] VERBOSE[8044] chan_dahdi.c:     -- Hungup 'DAHDI/5-1'