[Dec 7 17:02:32] VERBOSE[29977] logger.c: -- Playing 'vm-newuser' (language 'en') [Dec 7 17:02:32] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:32] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:36] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #1636)) [Dec 7 17:02:37] DEBUG[29977] channel.c: Scheduling timer at 156 sample intervals [Dec 7 17:02:37] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:37] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:37] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:37] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:37] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:37] VERBOSE[29977] logger.c: -- Playing 'vm-newpassword' (language 'en') [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:38] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:38] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:38] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:38] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:38] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:39] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:39] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:39] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:39] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[25871] chan_sip.c: Auto destroying SIP dialog '78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228' [Dec 7 17:02:39] DEBUG[25871] chan_sip.c: Destroying SIP dialog 78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 [Dec 7 17:02:39] VERBOSE[25871] logger.c: Really destroying SIP dialog '78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228' Method: REGISTER [Dec 7 17:02:39] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:39] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:39] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:40] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #1636)) [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as78bf3f4a [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: = No match Their Call ID: C5AC9AE2-1DD1-11B2-BD6F-94A99868518F@172.16.0.195 Their Tag 15819837861481008869 Our tag: as5da2b540 [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: = Found Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: Auto destroying SIP dialog 'C5AC9AE2-1DD1-11B2-BD6F-94A99868518F@172.16.0.195' [Dec 7 17:02:40] DEBUG[25871] chan_sip.c: Destroying SIP dialog C5AC9AE2-1DD1-11B2-BD6F-94A99868518F@172.16.0.195 [Dec 7 17:02:40] VERBOSE[25871] logger.c: Really destroying SIP dialog 'C5AC9AE2-1DD1-11B2-BD6F-94A99868518F@172.16.0.195' Method: REGISTER [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:02:40] DTMF[29977] channel.c: DTMF begin '#' received on SIP/5050-a660c380 [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:02:40] DTMF[29977] channel.c: DTMF end '#' received on SIP/5050-a660c380 [Dec 7 17:02:40] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:40] DEBUG[29977] rtp.c: Difference is 12776, ms is 1617 [Dec 7 17:02:40] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:40] VERBOSE[29977] logger.c: -- Playing 'vm-reenterpassword' (language 'en') [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:40] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:41] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:41] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:41] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:41] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:41] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:41] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:41] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:42] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:42] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:42] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:42] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:42] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:02:43] DTMF[29977] channel.c: DTMF begin '#' received on SIP/5050-a660c380 [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:02:43] DTMF[29977] channel.c: DTMF end '#' received on SIP/5050-a660c380 [Dec 7 17:02:43] DEBUG[29977] app_voicemail.c: User 5050 set password to 1111 of length 4 [Dec 7 17:02:43] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:43] DEBUG[29977] rtp.c: Difference is 12000, ms is 1520 [Dec 7 17:02:43] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:43] VERBOSE[29977] logger.c: -- Playing 'vm-passchanged' (language 'en') [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:43] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:44] NOTICE[25871] chan_sip.c: -- Registration for 'helder@172.16.0.221' timed out, trying again (Attempt #150) [Dec 7 17:02:44] DEBUG[25871] chan_sip.c: Stopping retransmission on '7b80ea187575bed22fe6f1b628c23db2@172.16.0.187' of Request 251: Match Not Found [Dec 7 17:02:44] DEBUG[25871] chan_sip.c: Allocating new SIP dialog for 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 - REGISTER (No RTP) [Dec 7 17:02:44] DEBUG[25871] chan_sip.c: Scheduled a registration timeout for 172.16.0.221 id #1640 [Dec 7 17:02:44] VERBOSE[25871] logger.c: REGISTER attempt 151 to helder@172.16.0.221 [Dec 7 17:02:44] VERBOSE[25871] logger.c: Really destroying SIP dialog '7b80ea187575bed22fe6f1b628c23db2@172.16.0.187' Method: REGISTER [Dec 7 17:02:44] DEBUG[29977] channel.c: Scheduling timer at 12 sample intervals [Dec 7 17:02:44] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:44] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:44] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:44] VERBOSE[29977] logger.c: -- Recording the message [Dec 7 17:02:44] DEBUG[29977] app.c: play_and_record: vm-rec-name, /var/spool/asterisk/voicemail/default/5050/greet, 'wav49' [Dec 7 17:02:44] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:44] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:44] VERBOSE[29977] logger.c: -- Playing 'vm-rec-name' (language 'en') [Dec 7 17:02:45] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #1641)) [Dec 7 17:02:46] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #1641)) [Dec 7 17:02:47] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as04e15767 [Dec 7 17:02:47] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:02:47] DEBUG[25871] chan_sip.c: = Found Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:02:47] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:02:48] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #1641)) [Dec 7 17:02:48] DEBUG[29977] channel.c: Scheduling timer at 119 sample intervals [Dec 7 17:02:48] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:48] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:48] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:48] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:48] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:48] VERBOSE[29977] logger.c: -- Playing 'beep' (language 'en') [Dec 7 17:02:49] DEBUG[29977] channel.c: Scheduling timer at 138 sample intervals [Dec 7 17:02:49] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:49] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:49] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:49] DEBUG[29977] app.c: Recording Formats: sfmts=wav49 [Dec 7 17:02:49] VERBOSE[29977] logger.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/5050/greet format: wav49, 0x82226c0 [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:02:50] DTMF[29977] channel.c: DTMF begin '#' received on SIP/5050-a660c380 [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:02:50] DTMF[29977] channel.c: DTMF end '#' received on SIP/5050-a660c380 [Dec 7 17:02:50] VERBOSE[29977] logger.c: -- User ended message by pressing # [Dec 7 17:02:50] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:50] DEBUG[29977] rtp.c: Difference is 10424, ms is 1323 [Dec 7 17:02:50] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:50] VERBOSE[29977] logger.c: -- Playing 'auth-thankyou' (language 'en') [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:50] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:51] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] channel.c: Scheduling timer at 149 sample intervals [Dec 7 17:02:51] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:51] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:51] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:51] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:51] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:51] VERBOSE[29977] logger.c: -- Playing 'vm-review' (language 'en') [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:02:51] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:02:51] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:51] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:51] VERBOSE[29977] logger.c: -- Saving message as is [Dec 7 17:02:51] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:51] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:51] VERBOSE[29977] logger.c: -- Playing 'vm-msgsaved' (language 'en') [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:51] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #1641)) [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as04e15767 [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: = No match Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: = Found Their Call ID: D1927BB0-1DD1-11B2-BD6F-94A99868518F@172.16.0.195 Their Tag 1577972176927128936 Our tag: as5b32c79f [Dec 7 17:02:52] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:02:53] DEBUG[29977] channel.c: Scheduling timer at 33 sample intervals [Dec 7 17:02:53] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:53] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:53] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:53] WARNING[29977] app_voicemail.c: SQL Execute error! [DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?] [Dec 7 17:02:53] VERBOSE[29977] logger.c: -- Recording the message [Dec 7 17:02:53] DEBUG[29977] app.c: play_and_record: vm-rec-unv, /var/spool/asterisk/voicemail/default/5050/unavail, 'wav49' [Dec 7 17:02:53] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:53] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:53] VERBOSE[29977] logger.c: -- Playing 'vm-rec-unv' (language 'en') [Dec 7 17:02:56] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #1641)) [Dec 7 17:02:58] DEBUG[29977] channel.c: Scheduling timer at 154 sample intervals [Dec 7 17:02:58] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:58] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:58] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:58] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:02:58] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:02:58] VERBOSE[29977] logger.c: -- Playing 'beep' (language 'en') [Dec 7 17:02:59] DEBUG[29977] channel.c: Scheduling timer at 138 sample intervals [Dec 7 17:02:59] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:59] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:02:59] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:02:59] DEBUG[29977] app.c: Recording Formats: sfmts=wav49 [Dec 7 17:02:59] VERBOSE[29977] logger.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/5050/unavail format: wav49, 0x82226c0 [Dec 7 17:03:00] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #1641)) [Dec 7 17:03:00] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as04e15767 [Dec 7 17:03:00] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:00] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:00] DEBUG[25871] chan_sip.c: = Found Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:03:00] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:03:00] DTMF[29977] channel.c: DTMF begin '#' received on SIP/5050-a660c380 [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:03:00] DTMF[29977] channel.c: DTMF end '#' received on SIP/5050-a660c380 [Dec 7 17:03:00] VERBOSE[29977] logger.c: -- User ended message by pressing # [Dec 7 17:03:00] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:00] DEBUG[29977] rtp.c: Difference is 13960, ms is 1765 [Dec 7 17:03:00] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:00] VERBOSE[29977] logger.c: -- Playing 'auth-thankyou' (language 'en') [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:00] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:01] DEBUG[29977] channel.c: Scheduling timer at 149 sample intervals [Dec 7 17:03:01] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:01] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:01] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:01] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:01] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:01] VERBOSE[29977] logger.c: -- Playing 'vm-review' (language 'en') [Dec 7 17:03:01] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:01] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:03:01] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:03:01] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:01] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:01] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:01] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:01] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:02] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:02] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:02] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:03:02] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:03:02] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:02] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:02] VERBOSE[29977] logger.c: -- Saving message as is [Dec 7 17:03:02] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:02] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:02] VERBOSE[29977] logger.c: -- Playing 'vm-msgsaved' (language 'en') [Dec 7 17:03:02] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:02] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:04] DEBUG[29977] channel.c: Scheduling timer at 33 sample intervals [Dec 7 17:03:04] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:04] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:04] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:04] WARNING[29977] app_voicemail.c: SQL Execute error! [DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?] [Dec 7 17:03:04] VERBOSE[29977] logger.c: -- Recording the message [Dec 7 17:03:04] DEBUG[29977] app.c: play_and_record: vm-rec-busy, /var/spool/asterisk/voicemail/default/5050/busy, 'wav49' [Dec 7 17:03:04] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:04] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:04] VERBOSE[29977] logger.c: -- Playing 'vm-rec-busy' (language 'en') [Dec 7 17:03:04] NOTICE[25871] chan_sip.c: -- Registration for 'helder@172.16.0.221' timed out, trying again (Attempt #151) [Dec 7 17:03:04] DEBUG[25871] chan_sip.c: Stopping retransmission on '7b80ea187575bed22fe6f1b628c23db2@172.16.0.187' of Request 252: Match Not Found [Dec 7 17:03:04] DEBUG[25871] chan_sip.c: Allocating new SIP dialog for 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 - REGISTER (No RTP) [Dec 7 17:03:04] DEBUG[25871] chan_sip.c: Scheduled a registration timeout for 172.16.0.221 id #1645 [Dec 7 17:03:04] VERBOSE[25871] logger.c: REGISTER attempt 152 to helder@172.16.0.221 [Dec 7 17:03:04] VERBOSE[25871] logger.c: Really destroying SIP dialog '7b80ea187575bed22fe6f1b628c23db2@172.16.0.187' Method: REGISTER [Dec 7 17:03:05] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #1646)) [Dec 7 17:03:06] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #1646)) [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as69a318c3 [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = Found Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as69a318c3 [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: = No match Their Call ID: D1927BB0-1DD1-11B2-BD6F-94A99868518F@172.16.0.195 Their Tag 1577972176927128936 Our tag: as5b32c79f [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: Allocating new SIP dialog for 78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 - REGISTER (No RTP) [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 7 17:03:07] DEBUG[25871] chan_sip.c: SIP REGISTER attempt failed for (null) : Peer not found [Dec 7 17:03:07] NOTICE[25871] chan_sip.c: Registration from '' failed for '172.16.0.228' - No matching peer found [Dec 7 17:03:08] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #1646)) [Dec 7 17:03:08] DEBUG[29977] channel.c: Scheduling timer at 56 sample intervals [Dec 7 17:03:08] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:08] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:08] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:08] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:08] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:08] VERBOSE[29977] logger.c: -- Playing 'beep' (language 'en') [Dec 7 17:03:09] DEBUG[29977] channel.c: Scheduling timer at 138 sample intervals [Dec 7 17:03:09] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:09] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:09] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:09] DEBUG[29977] app.c: Recording Formats: sfmts=wav49 [Dec 7 17:03:09] VERBOSE[29977] logger.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/5050/busy format: wav49, 0x82226c0 [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:03:10] DTMF[29977] channel.c: DTMF begin '#' received on SIP/5050-a660c380 [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: Sending dtmf: 35 (#), at 172.16.0.195 [Dec 7 17:03:10] DTMF[29977] channel.c: DTMF end '#' received on SIP/5050-a660c380 [Dec 7 17:03:10] VERBOSE[29977] logger.c: -- User ended message by pressing # [Dec 7 17:03:10] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:10] DEBUG[29977] rtp.c: Difference is 11664, ms is 1478 [Dec 7 17:03:10] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:10] VERBOSE[29977] logger.c: -- Playing 'auth-thankyou' (language 'en') [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:10] DEBUG[29977] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Dec 7 17:03:11] DEBUG[29977] channel.c: Scheduling timer at 149 sample intervals [Dec 7 17:03:11] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:11] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:11] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:11] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:11] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:11] VERBOSE[29977] logger.c: -- Playing 'vm-review' (language 'en') [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #1646)) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:03:12] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: = No match Their Call ID: 78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 15783099182083829499 Our tag: as2e89b41c [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as69a318c3 [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: = No match Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: = Found Their Call ID: D1927BB0-1DD1-11B2-BD6F-94A99868518F@172.16.0.195 Their Tag 1577972176927128936 Our tag: as5b32c79f [Dec 7 17:03:12] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:03:12] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:03:12] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:12] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:12] VERBOSE[29977] logger.c: -- Saving message as is [Dec 7 17:03:12] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:12] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:12] VERBOSE[29977] logger.c: -- Playing 'vm-msgsaved' (language 'en') [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:12] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:14] DEBUG[29977] channel.c: Scheduling timer at 33 sample intervals [Dec 7 17:03:14] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:14] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:14] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:14] WARNING[29977] app_voicemail.c: SQL Execute error! [DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?] [Dec 7 17:03:14] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:14] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:14] VERBOSE[29977] logger.c: -- Playing 'vm-youhave' (language 'en') [Dec 7 17:03:15] DEBUG[29977] channel.c: Scheduling timer at 159 sample intervals [Dec 7 17:03:15] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:15] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:15] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:15] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:15] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:15] VERBOSE[29977] logger.c: -- Playing 'digits/1' (language 'en') [Dec 7 17:03:16] DEBUG[29977] channel.c: Scheduling timer at 108 sample intervals [Dec 7 17:03:16] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:16] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:16] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:16] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:16] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:16] VERBOSE[29977] logger.c: -- Playing 'vm-INBOX' (language 'en') [Dec 7 17:03:16] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #1646)) [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 115 sample intervals [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:17] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:17] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:17] VERBOSE[29977] logger.c: -- Playing 'vm-message' (language 'en') [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 112 sample intervals [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:17] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:17] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:17] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:17] VERBOSE[29977] logger.c: -- Playing 'vm-onefor' (language 'en') [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:03:19] DTMF[29977] channel.c: DTMF begin '1' received on SIP/5050-a660c380 [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: Sending dtmf: 49 (1), at 172.16.0.195 [Dec 7 17:03:19] DTMF[29977] channel.c: DTMF end '1' received on SIP/5050-a660c380 [Dec 7 17:03:19] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:19] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:19] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:19] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:19] VERBOSE[29977] logger.c: -- Playing 'vm-first' (language 'en') [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:19] DEBUG[29977] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 7 17:03:20] DEBUG[29977] channel.c: Scheduling timer at 31 sample intervals [Dec 7 17:03:20] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:20] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:20] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:20] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:20] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:20] VERBOSE[29977] logger.c: -- Playing 'vm-message' (language 'en') [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #1646)) [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: = No match Their Call ID: 78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 15783099182083829499 Our tag: as2e89b41c [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as69a318c3 [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: = Found Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:03:20] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:03:21] DEBUG[29977] channel.c: Scheduling timer at 112 sample intervals [Dec 7 17:03:21] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:21] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:21] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:21] WARNING[29977] app_voicemail.c: SQL Get Data error! [SELECT * FROM tb_voicemail_messages WHERE dir=? AND msgnum=?] [Dec 7 17:03:21] VERBOSE[29977] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/5050/INBOX/msg0000.txt': [Dec 7 17:03:21] DEBUG[29977] config.c: Parsing /var/spool/asterisk/voicemail/default/5050/INBOX/msg0000.txt [Dec 7 17:03:21] VERBOSE[29977] logger.c: Found [Dec 7 17:03:21] DEBUG[29977] say.c: Parsing ' (offset 0) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:21] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:21] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:21] VERBOSE[29977] logger.c: -- Playing 'vm-received' (language 'en') [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 76 sample intervals [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:22] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:22] DEBUG[29977] say.c: Parsing (offset 13) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:22] DEBUG[29977] say.c: Parsing q (offset 14) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:22] DEBUG[29977] say.c: Parsing (offset 15) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:22] DEBUG[29977] say.c: Parsing ' (offset 16) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:22] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:22] VERBOSE[29977] logger.c: -- Playing 'digits/at' (language 'en') [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 134 sample intervals [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:22] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:22] DEBUG[29977] say.c: Parsing (offset 27) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:22] DEBUG[29977] say.c: Parsing I (offset 28) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:22] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:22] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:22] VERBOSE[29977] logger.c: -- Playing 'digits/6' (language 'en') [Dec 7 17:03:23] DEBUG[29977] channel.c: Scheduling timer at 26 sample intervals [Dec 7 17:03:23] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:23] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:23] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:23] DEBUG[29977] say.c: Parsing M (offset 29) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:23] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:23] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:23] VERBOSE[29977] logger.c: -- Playing 'digits/13' (language 'en') [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 79 sample intervals [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:24] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:24] DEBUG[29977] say.c: Parsing p (offset 30) in 'vm-received' q 'digits/at' IMp [Dec 7 17:03:24] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:24] VERBOSE[29977] logger.c: -- Playing 'digits/p-m' (language 'en') [Dec 7 17:03:24] NOTICE[25871] chan_sip.c: -- Registration for 'helder@172.16.0.221' timed out, trying again (Attempt #152) [Dec 7 17:03:24] DEBUG[25871] chan_sip.c: Stopping retransmission on '7b80ea187575bed22fe6f1b628c23db2@172.16.0.187' of Request 253: Match Not Found [Dec 7 17:03:24] DEBUG[25871] chan_sip.c: Allocating new SIP dialog for 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 - REGISTER (No RTP) [Dec 7 17:03:24] DEBUG[25871] chan_sip.c: Scheduled a registration timeout for 172.16.0.221 id #1651 [Dec 7 17:03:24] VERBOSE[25871] logger.c: REGISTER attempt 153 to helder@172.16.0.221 [Dec 7 17:03:24] VERBOSE[25871] logger.c: Really destroying SIP dialog '7b80ea187575bed22fe6f1b628c23db2@172.16.0.187' Method: REGISTER [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 151 sample intervals [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:24] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: composite caller ID received: "Helder Sato" <7777>, context: voicemail [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: comparing internalcontext: [Dec 7 17:03:24] DEBUG[29977] app_voicemail.c: VM-CID: Numeric caller id: (7777) [Dec 7 17:03:24] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:24] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:24] VERBOSE[29977] logger.c: -- Playing 'vm-from-phonenumber' (language 'en') [Dec 7 17:03:25] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #1652)) [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #1652)) [Dec 7 17:03:26] DEBUG[29977] channel.c: Scheduling timer at 159 sample intervals [Dec 7 17:03:26] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:26] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:26] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:26] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:26] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:26] VERBOSE[29977] logger.c: -- Playing 'digits/7' (language 'en') [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as0068efd8 [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = No match Their Call ID: 78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 15783099182083829499 Our tag: as2e89b41c [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = No match Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = No match Their Call ID: 83F54A3E-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 1574246523965285762 Our tag: as1cf5cb23 [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = No match Their Call ID: D1927BB0-1DD1-11B2-BD6F-94A99868518F@172.16.0.195 Their Tag 1577972176927128936 Our tag: as5b32c79f [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: Allocating new SIP dialog for 9F89B2C2-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 - REGISTER (No RTP) [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: = Found Their Call ID: 9F89B2C2-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1582066507629833819 Our tag: as5965de65 [Dec 7 17:03:26] DEBUG[25871] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 7 17:03:26] DEBUG[25871] devicestate.c: Notification of state change to be queued on device/channel SIP/7777 [Dec 7 17:03:26] DEBUG[25861] devicestate.c: No provider found, checking channel drivers for SIP - 7777 [Dec 7 17:03:26] DEBUG[25861] chan_sip.c: Checking device state for peer 7777 [Dec 7 17:03:26] DEBUG[25861] devicestate.c: Changing state for SIP/7777 - state 1 (Not in use) [Dec 7 17:03:26] DEBUG[29981] app_queue.c: Device 'SIP/7777' changed to state '1' (Not in use) [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 56 sample intervals [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:27] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:27] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:27] VERBOSE[29977] logger.c: -- Playing 'digits/7' (language 'en') [Dec 7 17:03:27] DEBUG[25871] chan_sip.c: = No match Their Call ID: 9F89B2C2-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1582066507629833819 Our tag: as5965de65 [Dec 7 17:03:27] DEBUG[25871] chan_sip.c: = No match Their Call ID: 7b80ea187575bed22fe6f1b628c23db2@172.16.0.187 Their Tag Our tag: as0068efd8 [Dec 7 17:03:27] DEBUG[25871] chan_sip.c: = No match Their Call ID: 78098CEE-1DD2-11B2-80D5-82BAC5D31393@172.16.0.228 Their Tag 15783099182083829499 Our tag: as2e89b41c [Dec 7 17:03:27] DEBUG[25871] chan_sip.c: = No match Their Call ID: 6E4AA6CC-1DD2-11B2-BD7B-94A99868518F@172.16.0.195 Their Tag 15819887711554447440 Our tag: as3fa3ad4f [Dec 7 17:03:27] DEBUG[25871] chan_sip.c: = Found Their Call ID: B1FC2796-1DD1-11B2-8EEF-FD9FD113014A@172.16.0.237 Their Tag 1580536708454935997 Our tag: as240c2b5b [Dec 7 17:03:27] DEBUG[25871] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 56 sample intervals [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:27] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:27] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:27] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:27] VERBOSE[29977] logger.c: -- Playing 'digits/7' (language 'en') [Dec 7 17:03:28] DEBUG[25871] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #1652)) [Dec 7 17:03:28] DEBUG[29977] channel.c: Scheduling timer at 56 sample intervals [Dec 7 17:03:28] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:28] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:28] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:28] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format slin [Dec 7 17:03:28] DEBUG[29977] channel.c: Scheduling timer at 160 sample intervals [Dec 7 17:03:28] VERBOSE[29977] logger.c: -- Playing 'digits/7' (language 'en') [Dec 7 17:03:29] DEBUG[29977] channel.c: Scheduling timer at 56 sample intervals [Dec 7 17:03:29] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:29] DEBUG[29977] channel.c: Scheduling timer at 0 sample intervals [Dec 7 17:03:29] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format ulaw [Dec 7 17:03:29] DEBUG[29977] channel.c: Set channel SIP/5050-a660c380 to write format gsm [Dec 7 17:03:29] WARNING[29977] format_wav_gsm.c: Does not begin with RIFF [Dec 7 17:03:29] WARNING[29977] file.c: Unable to open format wav49 [Dec 7 17:03:29] WARNING[29977] format_wav_gsm.c: Does not begin with RIFF [Dec 7 17:03:29] WARNING[29977] file.c: Unable to open format wav49 [Dec 7 17:03:29] WARNING[29977] file.c: Unable to open /var/spool/asterisk/voicemail/default/5050/INBOX/msg0000 (format 0x4 (ulaw)): No such file or directory [Dec 7 17:03:29] DEBUG[29977] app.c: Locked path '/var/spool/asterisk/voicemail/default/5050/INBOX' [Dec 7 17:03:29] DEBUG[29977] app.c: Locked path '/var/spool/asterisk/voicemail/default/5050/Old' [Dec 7 17:03:29] WARNING[29977] app_voicemail.c: SQL Execute error! [DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?] [Dec 7 17:03:29] DEBUG[29977] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/5050/Old' [Dec 7 17:03:29] DEBUG[29977] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/5050/INBOX' [Dec 7 17:03:29] DEBUG[29977] pbx.c: Spawn extension (extensions,*98,2) exited non-zero on 'SIP/5050-a660c380' [Dec 7 17:03:29] VERBOSE[29977] logger.c: == Spawn extension (extensions, *98, 2) exited non-zero on 'SIP/5050-a660c380' [Dec 7 17:03:29] DEBUG[29977] pbx.c: Launching 'Goto' [Dec 7 17:03:29] VERBOSE[29977] logger.c: -- Executing [h@extensions:1] Goto("SIP/5050-a660c380", "hangupcall|s|1") in new stack [Dec 7 17:03:29] VERBOSE[29977] logger.c: -- Goto (hangupcall,s,1) [Dec 7 17:03:29] DEBUG[29977] pbx.c: Launching 'ResetCDR'