rendered paste body[Oct 29 13:05:45] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'vm-first' (language 'en')
[Oct 29 13:05:45] DEBUG[3956]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Oct 29 13:05:45] DEBUG[3956]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Oct 29 13:05:46] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:46] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:46] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format ulaw
[Oct 29 13:05:46] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format gsm
[Oct 29 13:05:46] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'vm-message' (language 'en')
[Oct 29 13:05:46] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:46] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:46] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format ulaw
== Parsing '/var/spool/asterisk/voicemail/g2g/503/Old/msg0000.txt': [Oct 29 13:05:46] DEBUG[3956]: config.c:846 config_text_file_load: Parsing /var/spool/asterisk/voicemail/g2g/503/Old/msg0000.txt
Found
[Oct 29 13:05:46] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing ' (offset 0) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:46] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format gsm
[Oct 29 13:05:46] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'vm-received' (language 'en')
[Oct 29 13:05:46] DEBUG[3916]: rtp.c:879 ast_rtcp_read: Got RTCP report of 72 bytes
[Oct 29 13:05:47] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:47] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:47] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format ulaw
[Oct 29 13:05:47] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing (offset 13) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:47] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing q (offset 14) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:47] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing A (offset 0) in ABd
[Oct 29 13:05:47] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/day-3' (language 'en')
[Oct 29 13:05:48] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 112 sample intervals
[Oct 29 13:05:48] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:48] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:48] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing B (offset 1) in ABd
[Oct 29 13:05:48] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/mon-9' (language 'en')
[Oct 29 13:05:49] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 62 sample intervals
[Oct 29 13:05:49] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:49] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:49] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing d (offset 2) in ABd
[Oct 29 13:05:49] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/h-17' (language 'en')
[Oct 29 13:05:49] DEBUG[3956]: rtp.c:879 ast_rtcp_read: Got RTCP report of 92 bytes
[Oct 29 13:05:50] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 68 sample intervals
[Oct 29 13:05:50] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:50] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:50] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing (offset 15) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:50] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing ' (offset 16) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:50] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/at' (language 'en')
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 73 sample intervals
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:51] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing (offset 27) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:51] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing I (offset 28) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/1' (language 'en')
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 36 sample intervals
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:51] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing M (offset 29) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:51] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/20' (language 'en')
[Oct 29 13:05:51] DEBUG[3916]: rtp.c:879 ast_rtcp_read: Got RTCP report of 72 bytes
[Oct 29 13:05:52] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:52] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:52] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/2' (language 'en')
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 8 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: say.c:3010 ast_say_date_with_format_en: Parsing p (offset 30) in 'vm-received' q 'digits/at' IMp
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 160 sample intervals
-- <SIP/503-08b89420> Playing 'digits/p-m' (language 'en')
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 46 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: app_voicemail.c:4353 play_message_duration: VM-Duration: duration is: 4 seconds converted to: 0 minutes
[Oct 29 13:05:53] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format gsm
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
-- <SIP/503-08b89420> Playing '/var/spool/asterisk/voicemail/g2g/503/Old/msg0000' (language 'en')
[Oct 29 13:05:53] DEBUG[3956]: channel.c:2070 ast_settimeout: Scheduling timer at 0 sample intervals
[Oct 29 13:05:53] DEBUG[3956]: channel.c:3053 set_format: Set channel SIP/503-08b89420 to write format ulaw
[Oct 29 13:05:53] DEBUG[3956]: app.c:1003 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/g2g/503/Old'
[Oct 29 13:05:53] DEBUG[3956]: app.c:1024 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/g2g/503/Old'
[Oct 29 13:05:53] DEBUG[3956]: pbx.c:2407 __ast_pbx_run: Spawn extension (e_internal,*97,4) exited non-zero on 'SIP/503-08b89420'
== Spawn extension (e_internal, *97, 4) exited non-zero on 'SIP/503-08b89420'
[Oct 29 13:05:53] DEBUG[3956]: channel.c:1545 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/503-08b89420'
[Oct 29 13:05:53] DEBUG[3956]: channel.c:1762 ast_hangup: Hanging up channel 'SIP/503-08b89420'
[Oct 29 13:05:53] DEBUG[3956]: chan_sip.c:3445 sip_hangup: Hangup call SIP/503-08b89420, SIP callid b1a7d6ff-1ff5b631-fc9d0576@192.168.100.167)
[Oct 29 13:05:53] DEBUG[3956]: chan_sip.c:3454 sip_hangup: update_call_counter(503) - decrement call limit counter on hangup
[Oct 29 13:05:53] DEBUG[3956]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call
[Oct 29 13:05:53] DEBUG[3956]: chan_sip.c:3184 update_call_counter: Call from user '503' removed from call limit 10
Scheduling destruction of SIP dialog 'b1a7d6ff-1ff5b631-fc9d0576@192.168.100.167' in 32000 ms (Method: ACK)
[Oct 29 13:05:53] DEBUG[3956]: chan_sip.c:5792 reqprep: Strict routing enforced for session b1a7d6ff-1ff5b631-fc9d0576@192.168.100.167
set_destination: Parsing <sip:503@192.168.100.167> for address/port to send to
set_destination: set destination to 192.168.100.167, port 5060
Reliably Transmitting (no NAT) to 192.168.100.167:5060:
BYE sip:503@192.168.100.167 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.50:5060;branch=z9hG4bK66cd3662;rport
From: <sip:*97@192.168.100.50>;tag=as26a73338
To: "503" <sip:503@192.168.100.50>;tag=23CD0073-A7090BA0
Call-ID: b1a7d6ff-1ff5b631-fc9d0576@192.168.100.167
CSeq: 102 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0
---
[Oct 29 13:05:53] DEBUG[3956]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Oct 29 13:05:53] DEBUG[3956]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #24377
[Oct 29 13:05:53] DEBUG[3956]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/503-08b89420
[Oct 29 13:05:53] DEBUG[8121]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 503
[Oct 29 13:05:53] DEBUG[8121]: chan_sip.c:15593 sip_devicestate: Checking device state for peer 503
[Oct 29 13:05:53] DEBUG[8121]: devicestate.c:287 do_state_change: Changing state for SIP/503 - state 1 (Not in use)
[Oct 29 13:05:53] DEBUG[8121]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 503
[Oct 29 13:05:53] DEBUG[8121]: chan_sip.c:15593 sip_devicestate: Checking device state for peer 503
[Oct 29 13:05:53] DEBUG[3960]: app_queue.c:566 changethread: Device 'SIP/503' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
localhost*CLI>
<--- SIP read from 192.168.100.167:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.50:5060;branch=z9hG4bK66cd3662;rport
From: <sip:*97@192.168.100.50>;tag=as26a73338
To: "503" <sip:503@192.168.100.50>;tag=23CD0073-A7090BA0
CSeq: 102 BYE
Call-ID: b1a7d6ff-1ff5b631-fc9d0576@192.168.100.167
Contact: <sip:503@192.168.100.167>
User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708
Content-Length: 0
<------------->