[Mar  8 15:54:41] DEBUG[8861][C-000336fd] pbx.c: Launching 'VoiceMailMain'
[Mar  8 15:54:41] VERBOSE[8861][C-000336fd] pbx.c: Executing [did1001@opensips_incoming:1] VoiceMailMain("SIP/class4-00033736", "1001") in new stack
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] app_voicemail.c: Before ast_answer
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: SIP answering channel: SIP/class4-00033736
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP setting the marker bit due to a source update
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) DTLS - ast_rtp_activate rtp=0x7f305000e7f0 - setup and perform DTLS'
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f305000e7f0) DTLS perform handshake - ssl = (nil), setup = 0
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f305000e7f0) DTLS perform handshake - ssl = (nil), setup = 0
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: ** Our capability: (alaw|ulaw|g729) Video flag: True Text flag: True
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: ** Our prefcodec: (nothing)
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: -- Done with adding codecs to SDP
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: Setting framing on incoming call: 0
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw|g729)
[Mar  8 15:54:41] DEBUG[8861][C-000336fd] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 188.118.2.22:5060
[Mar  8 15:54:41] DEBUG[19070][C-000336fd] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Mar  8 15:54:41] DEBUG[19070][C-000336fd] chan_sip.c: Stopping retransmission on '2e3a5ef86c3109f94d0b24c514a955f0@198.211.9.9:5060' of Response 102: Match Found
[Mar  8 15:54:42] VERBOSE[8861][C-000336fd] res_rtp_asterisk.c: 0x7f305000e7f0 -- Strict RTP switching to RTP target address 198.211.9.9:13994 as source
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] chan_sip.c: Oooh, format changed to ulaw
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] channel_internal_api.c:  SIP/class4-00033736: Formats: (ulaw)
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] channel_internal_api.c:  New topology set
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting read format path: ulaw -> alaw
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_odbc.c: Reusing ODBC handle 0x7f30a80019e0 from class 'realtimedbodbc'
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM voicemail WHERE mailbox = ? AND context = ?
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_config_odbc.c: Parameter 1 ('mailbox') = '1001'
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_config_odbc.c: Parameter 2 ('context') = 'default'
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_odbc.c: Releasing ODBC handle 0x7f30a80019e0 into pool
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] app_voicemail.c: Before find user for mailbox 1001
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_odbc.c: Reusing ODBC handle 0x7f30a80019e0 from class 'realtimedbodbc'
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM voicemail WHERE mailbox = ? AND context = ?
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_config_odbc.c: Parameter 1 ('mailbox') = '1001'
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_config_odbc.c: Parameter 2 ('context') = 'default'
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_odbc.c: Releasing ODBC handle 0x7f30a80019e0 into pool
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP ooh, format changed from none to ulaw
[Mar  8 15:54:42] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:42] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-password.ulaw' (language 'en')
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (229 requested / 229 actual) timer ticks per second
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: slin -> ulaw
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] channel.c: Started silence generator on 'SIP/class4-00033736'
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 57 (9), at 198.211.9.9:13994
[Mar  8 15:54:43] DTMF[8861][C-000336fd] channel.c: DTMF begin '9' received on SIP/class4-00033736
[Mar  8 15:54:43] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '9' on SIP/class4-00033736
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 57 (9), at 198.211.9.9:13994
[Mar  8 15:54:43] DTMF[8861][C-000336fd] channel.c: DTMF end '9' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:43] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '9' on SIP/class4-00033736
[Mar  8 15:54:43] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 56 (8), at 198.211.9.9:13994
[Mar  8 15:54:43] DTMF[8861][C-000336fd] channel.c: DTMF begin '8' received on SIP/class4-00033736
[Mar  8 15:54:43] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '8' on SIP/class4-00033736
[Mar  8 15:54:44] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 56 (8), at 198.211.9.9:13994
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF end '8' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '8' on SIP/class4-00033736
[Mar  8 15:54:44] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 55 (7), at 198.211.9.9:13994
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF begin '7' received on SIP/class4-00033736
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '7' on SIP/class4-00033736
[Mar  8 15:54:44] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 55 (7), at 198.211.9.9:13994
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF end '7' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '7' on SIP/class4-00033736
[Mar  8 15:54:44] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 54 (6), at 198.211.9.9:13994
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF begin '6' received on SIP/class4-00033736
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '6' on SIP/class4-00033736
[Mar  8 15:54:44] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 54 (6), at 198.211.9.9:13994
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF end '6' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:44] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '6' on SIP/class4-00033736
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 35 (#), at 198.211.9.9:13994
[Mar  8 15:54:45] DTMF[8861][C-000336fd] channel.c: DTMF begin '#' received on SIP/class4-00033736
[Mar  8 15:54:45] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '#' on SIP/class4-00033736
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 35 (#), at 198.211.9.9:13994
[Mar  8 15:54:45] DTMF[8861][C-000336fd] channel.c: DTMF end '#' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:45] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '#' on SIP/class4-00033736
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] channel.c: Stopped silence generator on 'SIP/class4-00033736'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: After vm_authenticate
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: Before open_mailbox
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[1] = 1, count = 1
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[0] = 1, count = 2
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[2] = 1, count = 3
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: Number of old messages: 3
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/INBOX'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/INBOX'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/INBOX'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/INBOX'
[Mar  8 15:54:45] DEBUG[8861][C-000336fd] app_voicemail.c: Number of new messages: 0
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Urgent'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Urgent'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Urgent'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Urgent'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app_voicemail.c: Number of urgent messages: 0
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[1] = 1, count = 1
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[0] = 1, count = 2
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[2] = 1, count = 3
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP audio difference is 10192, ms is 1294
[Mar  8 15:54:46] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:46] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-youhave.ulaw' (language 'en')
[Mar  8 15:54:46] VERBOSE[8861][C-000336fd] res_rtp_asterisk.c: 0x7f305000e7f0 -- Strict RTP learning complete - Locking on source address 198.211.9.9:13994
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTCP got report of 100 bytes from 198.211.9.9:13995
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (151 requested / 151 actual) timer ticks per second
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] app_playback.c: string <num:3> depth <0>
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] app_playback.c: try <num:3> in <en>
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] app_playback.c: value is <3>
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] pbx_variables.c: Result of 'SAY' is '3'
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] app_playback.c: doing [digits/3]
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:47] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:47] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/3.ulaw' (language 'en')
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 49 (1), at 198.211.9.9:13994
[Mar  8 15:54:48] DTMF[8861][C-000336fd] channel.c: DTMF begin '1' received on SIP/class4-00033736
[Mar  8 15:54:48] DTMF[8861][C-000336fd] channel.c: DTMF begin '1' received on SIP/class4-00033736
[Mar  8 15:54:48] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '1' on SIP/class4-00033736
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 49 (1), at 198.211.9.9:13994
[Mar  8 15:54:48] DTMF[8861][C-000336fd] channel.c: DTMF end '1' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:48] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '1' on SIP/class4-00033736
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:48] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-first.ulaw' (language 'en')
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (119 requested / 119 actual) timer ticks per second
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] config.c: Parsing /var/spool/asterisk/voicemail/default/1001/Old/msg0000.txt
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:48] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:48] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-message.ulaw' (language 'en')
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 51 (3), at 198.211.9.9:13994
[Mar  8 15:54:49] DTMF[8861][C-000336fd] channel.c: DTMF begin '3' received on SIP/class4-00033736
[Mar  8 15:54:49] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '3' on SIP/class4-00033736
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 51 (3), at 198.211.9.9:13994
[Mar  8 15:54:49] DTMF[8861][C-000336fd] channel.c: DTMF end '3' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:49] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '3' on SIP/class4-00033736
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:49] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:49] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-toreply.ulaw' (language 'en')
[Mar  8 15:54:50] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating BEGIN DTMF Frame: 51 (3), at 198.211.9.9:13994
[Mar  8 15:54:50] DTMF[8861][C-000336fd] channel.c: DTMF begin '3' received on SIP/class4-00033736
[Mar  8 15:54:50] DTMF[8861][C-000336fd] channel.c: DTMF begin ignored '3' on SIP/class4-00033736
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTP creating END DTMF Frame: 51 (3), at 198.211.9.9:13994
[Mar  8 15:54:51] DTMF[8861][C-000336fd] channel.c: DTMF end '3' received on SIP/class4-00033736, duration 160 ms
[Mar  8 15:54:51] DTMF[8861][C-000336fd] channel.c: DTMF end passthrough '3' on SIP/class4-00033736
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] config.c: Parsing /var/spool/asterisk/voicemail/default/1001/Old/msg0000.txt
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_playback.c: string <datetime:'vm-received' Q 'digits/at' IMp:202012220513.47-2-356> depth <0>
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_playback.c: try <datetime:'vm-received' Q 'digits/at' IMp:202012220513.47-2-356> in <en>
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: composite caller ID received: "Scot" <+19173985000>, context: sub_dialing_smart
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: comparing internalcontext:
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] app_voicemail.c: VM-CID: Numeric caller id: (+19173985000)
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:51] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:51] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-from-phonenumber.ulaw' (language 'en')
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTCP got report of 100 bytes from 198.211.9.9:13995
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (163 requested / 163 actual) timer ticks per second
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:52] WARNING[8861][C-000336fd] file.c: File  does not exist in any format
[Mar  8 15:54:52] WARNING[8861][C-000336fd] file.c: Unable to open  (format (ulaw)): No such file or directory
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:52] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:52] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/1.ulaw' (language 'en')
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (89 requested / 89 actual) timer ticks per second
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:53] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:53] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/9.ulaw' (language 'en')
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (53 requested / 53 actual) timer ticks per second
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:54] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:54] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/1.ulaw' (language 'en')
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (89 requested / 89 actual) timer ticks per second
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:55] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:55] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/7.ulaw' (language 'en')
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (8000 requested / 1000 actual) timer ticks per second
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:56] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:56] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/3.ulaw' (language 'en')
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTCP got report of 100 bytes from 198.211.9.9:13995
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (55 requested / 55 actual) timer ticks per second
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:57] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:57] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/9.ulaw' (language 'en')
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (53 requested / 53 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:58] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/8.ulaw' (language 'en')
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (80 requested / 80 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:58] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:58] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/5.ulaw' (language 'en')
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (8000 requested / 1000 actual) timer ticks per second
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:54:59] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:54:59] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/0.ulaw' (language 'en')
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (68 requested / 68 actual) timer ticks per second
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:55:00] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:55:00] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/0.ulaw' (language 'en')
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (68 requested / 68 actual) timer ticks per second
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:55:01] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:55:01] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'digits/0.ulaw' (language 'en')
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) RTCP got report of 100 bytes from 198.211.9.9:13995
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (68 requested / 68 actual) timer ticks per second
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: ulaw -> ulaw
[Mar  8 15:55:02] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar  8 15:55:02] VERBOSE[8861][C-000336fd] file.c: <SIP/class4-00033736> Playing 'vm-advopts.ulaw' (language 'en')
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] netsock2.c: Splitting '188.118.2.22:5060' into...
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] netsock2.c: ...host '188.118.2.22' and port '5060'.
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2e3a5ef86c3109f94d0b24c514a955f0@198.211.9.9:5060
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) DTLS srtp - stopped timeout timer'
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) DTLS srtp - stopped timeout timer'
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] chan_sip.c: Received bye, issuing owner hangup
[Mar  8 15:55:04] DEBUG[19070][C-000336fd] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 188.118.2.22:5060
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel.c: Channel SIP/class4-00033736 setting write format path: alaw -> ulaw
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] app.c: Locked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[1] = 1, count = 1
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[0] = 1, count = 2
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] app_voicemail.c: /var/spool/asterisk/voicemail/default/1001/Old map[2] = 1, count = 3
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/1001/Old'
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] app_voicemail.c: Queueing event for mailbox 1001@default  New: 0   Old: 3
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] pbx.c: Spawn extension (opensips_incoming,did1001,1) exited non-zero on 'SIP/class4-00033736'
[Mar  8 15:55:04] VERBOSE[8861][C-000336fd] pbx.c: Spawn extension (opensips_incoming, did1001, 1) exited non-zero on 'SIP/class4-00033736'
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel.c: Soft-Hanging (0x10) up channel 'SIP/class4-00033736'
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel.c: Channel 0x7f30500325d0 'SIP/class4-00033736' hanging up.  Refs: 2
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] chan_sip.c: Hangup call SIP/class4-00033736, SIP callid 2e3a5ef86c3109f94d0b24c514a955f0@198.211.9.9:5060
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) DTLS srtp - stopped timeout timer'
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] res_rtp_asterisk.c: (0x7f3050000980) DTLS srtp - stopped timeout timer'
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel.c: Channel 0x7f30500325d0 'SIP/class4-00033736' destroying
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] stasis.c: Destroying topic. name: channel:1646754881.211028, detail:
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] stasis.c: Topic 'channel:1646754881.211028': 0x7f3050023f40 destroyed
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel_internal_api.c:  <initializing>: Formats: (nothing)
[Mar  8 15:55:04] DEBUG[8861][C-000336fd] channel_internal_api.c:  Channel is being initialized or destroyed