[Home]

Summary:ASTERISK-19957: cdr_adaptative_odbc missing records
Reporter:Sebastian Gutierrez (sum)Labels:
Date Opened:2012-06-04 10:28:49Date Closed:2012-07-11 19:49:46
Priority:CriticalRegression?
Status:Closed/CompleteComponents:CDR/cdr_adaptive_odbc
Versions:1.8.10.1 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Centos 6.2 mysql 5.5.X freetds: Version: freetds v0.91 freetds.conf directory: /usr/local/etc MS db-lib source compatibility: yes Sybase binary compatibility: no Thread safety: yes iconv library: yes TDS version: 7.1 iODBC: no unixodbc: yes SSPI "trusted" logins: no Kerberos: no unixodbc: unixODBC 2.3.0 DRIVERS............: /usr/local/etc/odbcinst.ini SYSTEM DATA SOURCES: /usr/local/etc/odbc.ini FILE DATA SOURCES..: /usr/local/etc/ODBCDataSources USER DATA SOURCES..: /root/.odbc.ini SQLULEN Size.......: 8 SQLLEN Size........: 8 SQLSETPOSIROW Size.: 8Attachments:
Description:There are a lot of missing calls on the cdr, this is causing a huge problem.
you can see the calls on  the full log, and no errors of insertion.
Comments:By: Sebastian Gutierrez (sum) 2012-06-04 11:30:35.503-0500

theres seems to be no problem with the realtime that im using via the odbc, queue_log recorded the calls, but cdr not.
By: Rusty Newton (rnewton) 2012-06-04 19:47:44.764-0500

Thank you for taking the time to report this bug and helping to make Asterisk better. Unfortunately, we cannot work on this bug because your description did not include enough information. You may find it helpful to read the Asterisk Issue Guidelines http://www.asterisk.org/developers/bug-guidelines. We would be grateful if you would then provide a more complete description of the problem. At a minimum, we need:

1. the specific steps or actions you took that caused you to encounter the problem,
2. the behavior you expected, and
3. the behavior you actually encountered (in as much detail as possible).

This likely includes output from the console with debug level logging, a SIP trace (if this is SIP related), and configuration information such as dialplan (e.g. extensions.conf) and channel configuration (e.g. sip.conf). Thanks!


Please include the CDR related config files, and a full log with VERBOSE and DEBUG of at least level 5 showing the calls that you expected to be logged in CDR.
By: Sebastian Gutierrez (sum) 2012-06-04 22:04:13.464-0500

Im aware that I dont have enough information for this but I had to go back to cdr_mysql due to data loss, I will try to reproduce this in a test environment. to be able to give more feedback.
By: Sebastian Gutierrez (sum) 2012-06-05 08:25:14.040-0500

I´ll be addint info as soon as i can get it:

1. no specific step, asterisk connected to a MySQL 5.5 database (on other server) with adaptative_odbc, not all records are write, no erros on logs, endpoints sip calling through E1 ISDN PRI.
2. Expected all records registered, I can check the full log and see a call that is not in the cdr (this is for many)
3. Many of the calls that are needed to get the recording are not shown on cdr table, they are at the full log, luckily I use a GUID to everycall is made and that is the name of the recording, due to this I can find the missing recording and see is not in the cdr, it is on the full and the recording exists.

SIP trace needed?? works fine with cdr_mysql. SIP are realtime. extensions is the same as in this issue ASTERISK-19922

odbcinst.conf

[MYSQL]
Description     = MySQL
Driver          = /usr/lib/i386-linux-gnu/odbc/libmyodbc.so
FileUsage       = 1
Threading=2

odbc.ini

[Repo]
Driver=MYSQL
Description=Origen Data
Server=192.168.10.51
User=xxx
Password=xxx
Database=xxx
Option=3

[RESRepo]
enabled => yes
dsn => Repo
username =>xxx
password => xxx
pre-connect => yes
idlecheck => 3600

cdr_adaptative_odbc.conf

[first]
connection=RESRepo
table=cdr
alias start => calldate
By: Sebastian Gutierrez (sum) 2012-06-09 14:53:02.578-0500

could this be for   Pooled: No ?? when I check odbc show??? are this configurations ok??

By: Matt Jordan (mjordan) 2012-06-14 08:45:20.377-0500

We require a complete debug log to help triage the issue. This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

If CDR records are not being written, we should either see (a) something in the DEBUG logs illustrating that a call completed but the cdr_adaptive_odbc backend failed to pick it up, (b) the backend picked it up but failed to write it, or (c) the backend processed it normally.

If its the first two possibilities, then a DEBUG log will help us determine why.  If its the third, then its a system configuration issue or a problem on the MySQL end.
By: Sebastian Gutierrez (sum) 2012-07-11 19:49:22.133-0500

Matt please close this issue I´m not seen it happening anymore for now, I´ll reopen it if I see it again.
By: Sebastian Gutierrez (sum) 2012-07-11 19:49:46.575-0500

closed while Im not able to reproduce it again
By: Akom Benevolent (akom) 2013-03-19 09:05:54.680-0500

I'd like to reopen this as this is happening with my installation (Same version but on Ubuntu Server 32bit).
1:1.8.10.1~dfsg-1ubuntu1

I lose about 1% of all calls using cdr_adaptive_odbc (with a volume of about 200 calls per day).  This screws up a lot of things for the company.  

I always have debug enabled, and here is the log for one call that is missing from CDR.  Note that this may not be a cdr_adaptive_odbc problem since these calls are also missing from the CSV logs (I have both enabled).  Note also that there is an ODBC reconnect happening in the middle of this call (supposedly successful).   Please let me know if there is something else I can provide.

This call made it into the debug log as well as the queue_log, but not into either cdr:
1363639333|kingast2-1363639305.5530|generalq|NONE|ENTERQUEUE||732BBBBBBB|1
(Note that there is only one record - I'd expect a COMPLETE* record yet it isn't there)




--------------------------------------------------------------------------------------------
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [732AAAAAAA@external:1] Gosub("SIP/voipms-000010f8", "doAnswerDelay,~~s~~,1(732AAAAAAA)") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:1] MSet("SIP/voipms-000010f8", "LOCAL(exten)=732AAAAAAA") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:2] Set("SIP/voipms-000010f8", "CDR(did)=732AAAAAAA") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:3] Gosub("SIP/voipms-000010f8", "getTimeStatus,~~s~~,1(piscataway)") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:1] MSet("SIP/voipms-000010f8", "LOCAL(ourlocation)=piscataway") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:2] Set("SIP/voipms-000010f8", "OPTRINGGROUP=2005-2002-2004/2003/2368/2102") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:3] Set("SIP/voipms-000010f8", "DBOFFICESTATUS=1-1-0") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:4] Set("SIP/voipms-000010f8", "OFFICEOPEN=1") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:5] Set("SIP/voipms-000010f8", "CSRSTATUS=1") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:6] Set("SIP/voipms-000010f8", "CSRSTATUS2=0") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:7] GotoIf("SIP/voipms-000010f8", "1?8:9") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Goto (getTimeStatus,~~s~~,8)
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:8] Set("SIP/voipms-000010f8", "CDR(office)=open") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:9] NoOp("SIP/voipms-000010f8", "Finish if_getTimeStatus_296") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:10] GotoIf("SIP/voipms-000010f8", "1?11:12") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Goto (getTimeStatus,~~s~~,11)
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:11] Set("SIP/voipms-000010f8", "CDR(office)=cr") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:12] NoOp("SIP/voipms-000010f8", "Finish if_getTimeStatus_297") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@getTimeStatus:13] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:4] MSet("SIP/voipms-000010f8", "ANSWERDELAY=0") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:5] GotoIf("SIP/voipms-000010f8", "0?6:8") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Goto (doAnswerDelay,~~s~~,8)
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:8] NoOp("SIP/voipms-000010f8", "Finish if_doAnswerDelay_362") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:9] NoOp("SIP/voipms-000010f8", "Waiting 0 seconds") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:10] Wait("SIP/voipms-000010f8", "0") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:11] NoOp("SIP/voipms-000010f8", "------- Incoming call FOR 732AAAAAAA ---------") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:12] NoOp("SIP/voipms-000010f8", "------- Incoming call From 732BBBBBBB ---------") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:13] NoOp("SIP/voipms-000010f8", "------- Incoming call from 732BBBBBBB ---------") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:14] Set("SIP/voipms-000010f8", "LOOKEDUP_CALLERID=") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:15] GotoIf("SIP/voipms-000010f8", "0?16:17") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Goto (doAnswerDelay,~~s~~,17)
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:17] NoOp("SIP/voipms-000010f8", "Finish if_doAnswerDelay_363") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:18] Answer("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:41:45] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:19] Wait("SIP/voipms-000010f8", "1") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@doAnswerDelay:20] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [732AAAAAAA@external:2] Goto("SIP/voipms-000010f8", "mainmenu,s,1") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Goto (mainmenu,s,1)
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:1] Set("SIP/voipms-000010f8", "SEND_EMAIL_ON_HANGUP=true") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:2] Gosub("SIP/voipms-000010f8", "setCDRAccountCode,~~s~~,1(fr)") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:1] MSet("SIP/voipms-000010f8", "LOCAL(value)=fr") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:2] GotoIf("SIP/voipms-000010f8", "1?3:5") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Goto (setCDRAccountCode,~~s~~,3)
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:3] Set("SIP/voipms-000010f8", "CDR(accountcode)=fr") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:4] Goto("SIP/voipms-000010f8", "6") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Goto (setCDRAccountCode,~~s~~,6)
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:6] NoOp("SIP/voipms-000010f8", "Finish if_setCDRAccountCode_368") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:7] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:3] MSet("SIP/voipms-000010f8", "MAINMENUSTARTTIME="1363639306"") in new stack
[Mar 18 16:41:46] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:4] BackGround("SIP/voipms-000010f8", "custom/front-menu/thank-you-hi2") in new stack
[Mar 18 16:41:46] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/front-menu/thank-you-hi2.slin' (language 'en')
[Mar 18 16:41:48] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:5] BackGround("SIP/voipms-000010f8", "custom/emergency-alert-announcement-kh") in new stack
[Mar 18 16:41:48] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/emergency-alert-announcement-kh.slin' (language 'en')
[Mar 18 16:41:48] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:6] BackGround("SIP/voipms-000010f8", "custom/front-menu/front-menu-please-listen") in new stack
[Mar 18 16:41:48] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/front-menu/front-menu-please-listen.slin' (language 'en')
[Mar 18 16:41:49] VERBOSE[27071] app_queue.c:     -- SIP/2002-000010f7 answered SIP/voipms-000010f5
[Mar 18 16:41:49] VERBOSE[27071] file.c:     -- <SIP/2002-000010f7> Playing 'queue-reporthold.slin' (language 'en')
[Mar 18 16:41:50] VERBOSE[27071] file.c:     -- <SIP/2002-000010f7> Playing 'digits/6.slin' (language 'en')
[Mar 18 16:41:51] VERBOSE[27071] file.c:     -- <SIP/2002-000010f7> Playing 'queue-seconds.slin' (language 'en')
[Mar 18 16:41:52] VERBOSE[27071] res_musiconhold.c:     -- Stopped music on hold on SIP/voipms-000010f5
[Mar 18 16:41:52] VERBOSE[27082] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/voipms-000010f5
[Mar 18 16:41:52] DEBUG[27071] channel.c: setting peeraccount to fr-cr-appt for SIP/2002-000010f7 from data on channel SIP/voipms-000010f5
[Mar 18 16:41:52] DEBUG[27071] channel.c: setting peeraccount to fr-cr-appt for SIP/voipms-000010f5 from data on channel SIP/2002-000010f7
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:7] MSet("SIP/voipms-000010f8", "x=0") in new stack
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:8] GotoIf("SIP/voipms-000010f8", "1?9:16") in new stack
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Goto (mainmenu,s,9)
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:9] GotoIf("SIP/voipms-000010f8", "0?10:11") in new stack
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Goto (mainmenu,s,11)
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:11] NoOp("SIP/voipms-000010f8", "Finish if_for_mainmenu_283_284") in new stack
[Mar 18 16:41:52] VERBOSE[27074] pbx.c:     -- Executing [s@mainmenu:12] BackGround("SIP/voipms-000010f8", "custom/front-menu/front-menu-2010-04-25-8000") in new stack
[Mar 18 16:41:52] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/front-menu/front-menu-2010-04-25-8000.slin' (language 'en')
[Mar 18 16:42:01] DTMF[27074] channel.c: DTMF end '1' received on SIP/voipms-000010f8, duration 160 ms
[Mar 18 16:42:01] DTMF[27074] channel.c: DTMF end passthrough '1' on SIP/voipms-000010f8
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [1@mainmenu:1] Gosub("SIP/voipms-000010f8", "setCDRAccountCode,~~s~~,1(cr-appt)") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:1] MSet("SIP/voipms-000010f8", "LOCAL(value)=cr-appt") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:2] GotoIf("SIP/voipms-000010f8", "0?3:5") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (setCDRAccountCode,~~s~~,5)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:5] Set("SIP/voipms-000010f8", "CDR(accountcode)=fr-cr-appt") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:6] NoOp("SIP/voipms-000010f8", "Finish if_setCDRAccountCode_368") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRAccountCode:7] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [1@mainmenu:2] Gosub("SIP/voipms-000010f8", "queueSequence,~~s~~,1(l2q,generalq,0,1,1001,Q APP)") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:1] MSet("SIP/voipms-000010f8", "LOCAL(q1)=l2q") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:2] MSet("SIP/voipms-000010f8", "LOCAL(q2)=generalq") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:3] MSet("SIP/voipms-000010f8", "LOCAL(open1)=0") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:4] MSet("SIP/voipms-000010f8", "LOCAL(open2)=1") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:5] MSet("SIP/voipms-000010f8", "LOCAL(voicemailbox)=1001") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:6] MSet("SIP/voipms-000010f8", "LOCAL(cid)=Q APP") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:7] Answer("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:8] GotoIf("SIP/voipms-000010f8", "1?9:10") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (queueSequence,~~s~~,9)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:9] Set("SIP/voipms-000010f8", "CALLERID(name)=Q APP:732BBBBBBB") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:10] NoOp("SIP/voipms-000010f8", "Finish if_queueSequence_324") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:11] GotoIf("SIP/voipms-000010f8", "1?12:13") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (queueSequence,~~s~~,12)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:12] Set("SIP/voipms-000010f8", "TARGETMAILBOX=1001") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:13] NoOp("SIP/voipms-000010f8", "Finish if_queueSequence_325") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:14] MSet("SIP/voipms-000010f8", "VMOPTS=su") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:15] NoOp("SIP/voipms-000010f8", "CSRSTATUS is 1") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:16] Set("SIP/voipms-000010f8", "QUEUEHOLDBEGIN=1363639321") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:17] GotoIf("SIP/voipms-000010f8", "0?18:21") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (queueSequence,~~s~~,21)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:21] NoOp("SIP/voipms-000010f8", "Queue l2q is not open") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:22] NoOp("SIP/voipms-000010f8", "Finish if_queueSequence_326") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:23] NoOp("SIP/voipms-000010f8", "Timed out of queue l2q, trying second queue") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:24] GotoIf("SIP/voipms-000010f8", "1?25:30") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (queueSequence,~~s~~,25)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:25] GotoIf("SIP/voipms-000010f8", "1?26:28") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (queueSequence,~~s~~,26)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:26] NoOp("SIP/voipms-000010f8", "Entering second queue: l2q") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:27] Gosub("SIP/voipms-000010f8", "enterQueue,~~s~~,1(generalq,60)") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:1] MSet("SIP/voipms-000010f8", "LOCAL(queue)=generalq") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:2] MSet("SIP/voipms-000010f8", "LOCAL(timeout)=60") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:3] NoOp("SIP/voipms-000010f8", "Entered enterQueue for generalq") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:4] GotoIf("SIP/voipms-000010f8", "1?5:19") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Goto (enterQueue,~~s~~,5)
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:5] MSet("SIP/voipms-000010f8", "VMOPTS=sb") in new stack
[Mar 18 16:42:01] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:6] Playback("SIP/voipms-000010f8", "custom/allyson/this-call-may-be-monitored-or-recorded") in new stack
[Mar 18 16:42:01] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/allyson/this-call-may-be-monitored-or-recorded.gsm' (language 'en')
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:7] NoOp("SIP/voipms-000010f8", "Subdir is ''") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:8] GotoIf("SIP/voipms-000010f8", "1?9:14") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Goto (enterQueue,~~s~~,9)
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:9] Set("SIP/voipms-000010f8", "MONITOR_FILENAME=q-generalq-D20130318-T164204-732BBBBBBB") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:10] Set("SIP/voipms-000010f8", "SUBDIR=2013-03-18") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:11] Set("SIP/voipms-000010f8", "MONITOR_EXEC=/usr/local/bin/asterisk-recording-postprocess.sh "/data/MONITOR/q-generalq-D20130318-T164204-732BBBBBBB.wav" "/data/MONITOR/2013-03-18/q-generalq-D20130318-T164204-732BBBBBBB.mp3"") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:12] Set("SIP/voipms-000010f8", "ODBC_RECFILE(q-generalq-D20130318-T164204-732BBBBBBB)=kingast2-1363639305.5530") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:13] Set("SIP/voipms-000010f8", "CDR(recfile)=q-generalq-D20130318-T164204-732BBBBBBB") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:14] NoOp("SIP/voipms-000010f8", "Finish if_if_enterQueue_320_321") in new stack
[Mar 18 16:42:04] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:15] Playback("SIP/voipms-000010f8", "custom/allyson/pls-stay-on-line") in new stack
[Mar 18 16:42:04] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/allyson/pls-stay-on-line.gsm' (language 'en')
[Mar 18 16:42:09] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:16] Playback("SIP/voipms-000010f8", "custom/queue-periodic-announce") in new stack
[Mar 18 16:42:09] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'custom/queue-periodic-announce.gsm' (language 'en')
[Mar 18 16:42:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:17] Queue("SIP/voipms-000010f8", "generalq,,,,60") in new stack
[Mar 18 16:42:13] VERBOSE[27074] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/voipms-000010f8
[Mar 18 16:42:13] VERBOSE[27074] netsock2.c:   == Using SIP RTP TOS bits 184
[Mar 18 16:42:13] VERBOSE[27074] netsock2.c:   == Using SIP RTP CoS mark 5
[Mar 18 16:42:13] VERBOSE[27074] netsock2.c:   == Using SIP RTP TOS bits 184
[Mar 18 16:42:13] VERBOSE[27074] netsock2.c:   == Using SIP RTP CoS mark 5
[Mar 18 16:42:13] VERBOSE[14564] chan_iax2.c:     -- Call accepted by 192.168.123.20 (format gsm)
[Mar 18 16:42:13] VERBOSE[14564] chan_iax2.c:     -- Format for call is gsm
[Mar 18 16:42:13] VERBOSE[14570] chan_iax2.c:     -- Call accepted by 192.168.123.20 (format gsm)
[Mar 18 16:42:13] VERBOSE[14570] chan_iax2.c:     -- Format for call is gsm
[Mar 18 16:42:13] VERBOSE[27074] app_queue.c:     -- IAX2/kingast1-13572 is circuit-busy
[Mar 18 16:42:13] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 0 ms
[Mar 18 16:42:13] VERBOSE[27074] chan_iax2.c:     -- Hungup 'IAX2/kingast1-13572'
[Mar 18 16:42:13] VERBOSE[27074] app_queue.c:     -- IAX2/kingast1-2947 is circuit-busy
[Mar 18 16:42:13] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 0 ms
[Mar 18 16:42:13] VERBOSE[27074] chan_iax2.c:     -- Hungup 'IAX2/kingast1-2947'
[Mar 18 16:42:13] VERBOSE[27074] app_queue.c:     -- SIP/2002-000010fa is ringing
[Mar 18 16:42:13] VERBOSE[27074] app_queue.c:     -- SIP/2004-000010f9 is ringing
[Mar 18 16:42:50] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 35000 ms
[Mar 18 16:42:50] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 35000 ms
[Mar 18 16:42:53] VERBOSE[14547] dnsmgr.c:     -- Refreshing DNS lookups.
[Mar 18 16:43:01] VERBOSE[27074] res_musiconhold.c:     -- Stopped music on hold on SIP/voipms-000010f8
[Mar 18 16:43:01] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'queue-youarenext.slin' (language 'en')
[Mar 18 16:43:06] VERBOSE[27074] app_queue.c:     -- Told SIP/voipms-000010f8 in generalq their queue position (which was 1)
[Mar 18 16:43:06] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'queue-thankyou.slin' (language 'en')
[Mar 18 16:43:08] VERBOSE[27074] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/voipms-000010f8
[Mar 18 16:43:08] VERBOSE[27074] netsock2.c:   == Using SIP RTP TOS bits 184
[Mar 18 16:43:08] VERBOSE[27074] netsock2.c:   == Using SIP RTP CoS mark 5
[Mar 18 16:43:08] VERBOSE[27074] netsock2.c:   == Using SIP RTP TOS bits 184
[Mar 18 16:43:08] VERBOSE[27074] netsock2.c:   == Using SIP RTP CoS mark 5
[Mar 18 16:43:08] VERBOSE[14564] chan_iax2.c:     -- Call accepted by 192.168.123.20 (format gsm)
[Mar 18 16:43:08] VERBOSE[14564] chan_iax2.c:     -- Format for call is gsm
[Mar 18 16:43:08] VERBOSE[14570] chan_iax2.c:     -- Call accepted by 192.168.123.20 (format gsm)
[Mar 18 16:43:08] VERBOSE[14570] chan_iax2.c:     -- Format for call is gsm
[Mar 18 16:43:08] VERBOSE[27074] app_queue.c:     -- IAX2/kingast1-14372 is circuit-busy
[Mar 18 16:43:08] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 0 ms
[Mar 18 16:43:08] VERBOSE[27074] chan_iax2.c:     -- Hungup 'IAX2/kingast1-14372'
[Mar 18 16:43:08] VERBOSE[27074] app_queue.c:     -- IAX2/kingast1-1366 is circuit-busy
[Mar 18 16:43:08] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 0 ms
[Mar 18 16:43:08] VERBOSE[27074] chan_iax2.c:     -- Hungup 'IAX2/kingast1-1366'
[Mar 18 16:43:08] VERBOSE[27074] app_queue.c:     -- SIP/2002-000010fc is ringing
[Mar 18 16:43:08] VERBOSE[27074] app_queue.c:     -- SIP/2004-000010fb is ringing
[Mar 18 16:43:13] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 5000 ms
[Mar 18 16:43:13] VERBOSE[27074] app_queue.c:     -- Nobody picked up in 5000 ms
[Mar 18 16:43:13] VERBOSE[27074] res_musiconhold.c:     -- Stopped music on hold on SIP/voipms-000010f8
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:18] Gosub("SIP/voipms-000010f8", "setCDRUserField,~~s~~,1("q:TIMEOUT")") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:1] MSet("SIP/voipms-000010f8", "LOCAL(value)="q:TIMEOUT"") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:2] GotoIf("SIP/voipms-000010f8", "1?3:5") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Goto (setCDRUserField,~~s~~,3)
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:3] Set("SIP/voipms-000010f8", "CDR(userfield)=q:TIMEOUT") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:4] Goto("SIP/voipms-000010f8", "6") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Goto (setCDRUserField,~~s~~,6)
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:6] NoOp("SIP/voipms-000010f8", "Finish if_setCDRUserField_369") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:7] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:19] NoOp("SIP/voipms-000010f8", "Finish if_enterQueue_320") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:20] Gosub("SIP/voipms-000010f8", "updateCDRAfterQueue,~~s~~,1") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@updateCDRAfterQueue:1] Gosub("SIP/voipms-000010f8", "calculateQueueHoldTime,~~s~~,1") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@calculateQueueHoldTime:1] GotoIf("SIP/voipms-000010f8", "1?2:3") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Goto (calculateQueueHoldTime,~~s~~,2)
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@calculateQueueHoldTime:2] MSet("SIP/voipms-000010f8", "QUEUEHOLDTIME=72") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@calculateQueueHoldTime:3] NoOp("SIP/voipms-000010f8", "Finish if_calculateQueueHoldTime_329") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@calculateQueueHoldTime:4] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@updateCDRAfterQueue:2] GotoIf("SIP/voipms-000010f8", "0?3:7") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Goto (updateCDRAfterQueue,~~s~~,7)
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@updateCDRAfterQueue:7] Gosub("SIP/voipms-000010f8", "setCDRUserField,~~s~~,1("qh:"72)") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:1] MSet("SIP/voipms-000010f8", "LOCAL(value)="qh:"72") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:2] GotoIf("SIP/voipms-000010f8", "0?3:5") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Goto (setCDRUserField,~~s~~,5)
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:5] Set("SIP/voipms-000010f8", "CDR(userfield)=q:TIMEOUT-qh:72") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:6] NoOp("SIP/voipms-000010f8", "Finish if_setCDRUserField_369") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:7] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@updateCDRAfterQueue:8] Set("SIP/voipms-000010f8", "CDR(holdtime)=72") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@updateCDRAfterQueue:9] NoOp("SIP/voipms-000010f8", "Finish if_updateCDRAfterQueue_330") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@updateCDRAfterQueue:10] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@enterQueue:21] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:28] NoOp("SIP/voipms-000010f8", "Finish if_if_queueSequence_327_328") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:29] Goto("SIP/voipms-000010f8", "31") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Goto (queueSequence,~~s~~,31)
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:31] NoOp("SIP/voipms-000010f8", "Finish if_queueSequence_327") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@queueSequence:32] Gosub("SIP/voipms-000010f8", "leavevoicemail,~~s~~,1(1001,sb)") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@leavevoicemail:1] MSet("SIP/voipms-000010f8", "LOCAL(mailbox)=1001") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@leavevoicemail:2] MSet("SIP/voipms-000010f8", "LOCAL(options)=sb") in new stack
[Mar 18 16:43:13] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@leavevoicemail:3] VoiceMail("SIP/voipms-000010f8", "1001,sb") in new stack
[Mar 18 16:43:13] DEBUG[27074] res_odbc.c: Disconnected 0 from asterisk [mysql1]
[Mar 18 16:43:13] DEBUG[27074] res_odbc.c: Database handle deallocated
[Mar 18 16:43:13] NOTICE[27074] res_odbc.c: Re-connecting asterisk
[Mar 18 16:43:13] NOTICE[27074] res_odbc.c: res_odbc: Connected to asterisk [mysql1]
[Mar 18 16:43:13] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing '/var/spool/asterisk/voicemail/default/1001/busy.gsm' (language 'en')
[Mar 18 16:43:27] VERBOSE[27074] file.c:     -- <SIP/voipms-000010f8> Playing 'beep.slin' (language 'en')
[Mar 18 16:43:27] VERBOSE[27074] app_voicemail_odbcstorage.c:     -- Recording the message
[Mar 18 16:43:27] VERBOSE[27074] app.c:     -- x=0, open writing:  /var/spool/asterisk/voicemail/default/1001/tmp/T8msb1 format: wav49, 0xb6b645c8
[Mar 18 16:43:27] VERBOSE[27074] app.c:     -- x=1, open writing:  /var/spool/asterisk/voicemail/default/1001/tmp/T8msb1 format: gsm, 0xb6b50c08
[Mar 18 16:43:27] VERBOSE[27074] app.c:     -- x=2, open writing:  /var/spool/asterisk/voicemail/default/1001/tmp/T8msb1 format: wav, 0xb6bfd538
[Mar 18 16:43:38] VERBOSE[27074] app.c:     -- User hung up
[Mar 18 16:43:39] VERBOSE[27074] config.c:   == Parsing '/var/spool/asterisk/voicemail/default/1001/INBOX/msg2289.txt': [Mar 18 16:43:39] VERBOSE[27074] config.c:   == Found
[Mar 18 16:43:39] VERBOSE[27074] config.c:   == Parsing '/var/spool/asterisk/voicemail/default/1001/INBOX/msg2289.txt': [Mar 18 16:43:39] VERBOSE[27074] config.c:   == Found
[Mar 18 16:43:39] VERBOSE[27074] config.c:   == Parsing '/var/spool/asterisk/voicemail/default/1001/INBOX/msg2289.txt': [Mar 18 16:43:39] VERBOSE[27074] config.c:   == Found
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:   == Spawn extension (leavevoicemail, ~~s~~, 3) exited non-zero on 'SIP/voipms-000010f8'
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [h@leavevoicemail:1] Gosub("SIP/voipms-000010f8", "voicemailUpdateRow,~~s~~,1(1001)") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@voicemailUpdateRow:1] MSet("SIP/voipms-000010f8", "LOCAL(mailbox)=1001") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@voicemailUpdateRow:2] MSet("SIP/voipms-000010f8", "LOCAL(~~EXTEN~~)=~~s~~") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@voicemailUpdateRow:3] MSet("SIP/voipms-000010f8", "LOCAL(~~EXTEN~~)=~~s~~") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@voicemailUpdateRow:4] Goto("SIP/voipms-000010f8", "sw_355_SUCCESS,10") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Goto (voicemailUpdateRow,sw_355_SUCCESS,10)
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:10] NoOp("SIP/voipms-000010f8", "Voicemail Left Successfully, proceeding to update row") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:11] Set("SIP/voipms-000010f8", "msgid=28244") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:12] NoOp("SIP/voipms-000010f8", "Updating message id for vm: 28244") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:13] Set("SIP/voipms-000010f8", "ODBC_VMLEFT(28244)=kingast2-1363639305.5530") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:14] Gosub("SIP/voipms-000010f8", "setCDRUserField,~~s~~,1("vm:28244")") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:1] MSet("SIP/voipms-000010f8", "LOCAL(value)="vm:28244"") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:2] GotoIf("SIP/voipms-000010f8", "0?3:5") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Goto (setCDRUserField,~~s~~,5)
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:5] Set("SIP/voipms-000010f8", "CDR(userfield)=q:TIMEOUT-qh:72-vm:28244") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:6] NoOp("SIP/voipms-000010f8", "Finish if_setCDRUserField_369") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@setCDRUserField:7] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:15] Set("SIP/voipms-000010f8", "CDR(vmid)=28244") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:16] GotoIf("SIP/voipms-000010f8", "1?17:19") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Goto (voicemailUpdateRow,sw_355_SUCCESS,17)
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:17] NoOp("SIP/voipms-000010f8", "Mailbox 1001 is enabled for missed call tracking") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:18] Gosub("SIP/voipms-000010f8", "sendEmail,~~s~~,1("Voicemail for mailbox 1001")") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@sendEmail:1] MSet("SIP/voipms-000010f8", "LOCAL(message)="Voicemail for mailbox 1001"") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@sendEmail:2] MSet("SIP/voipms-000010f8", "AGISIGHUP=no") in new stack
[Mar 18 16:43:39] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@sendEmail:3] AGI("SIP/voipms-000010f8", "agi-sendemail.php,-m,Voicemail for mailbox 1001") in new stack
[Mar 18 16:43:39] VERBOSE[27074] res_agi.c:     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-sendemail.php
[Mar 18 16:43:43] VERBOSE[27074] res_agi.c:     -- <SIP/voipms-000010f8>AGI Script agi-sendemail.php completed, returning 0
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@sendEmail:4] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:19] NoOp("SIP/voipms-000010f8", "Finish if_sw_voicemailUpdateRow_SUCCESS_355_356") in new stack
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [sw_355_SUCCESS@voicemailUpdateRow:20] Goto("SIP/voipms-000010f8", "~~s~~,5") in new stack
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Goto (voicemailUpdateRow,~~s~~,5)
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@voicemailUpdateRow:5] NoOp("SIP/voipms-000010f8", "Finish switch_voicemailUpdateRow_355") in new stack
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [~~s~~@voicemailUpdateRow:6] Return("SIP/voipms-000010f8", "") in new stack
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [h@leavevoicemail:2] GotoIf("SIP/voipms-000010f8", "0?3:6") in new stack
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Goto (leavevoicemail,h,6)
[Mar 18 16:43:43] VERBOSE[27074] pbx.c:     -- Executing [h@leavevoicemail:6] NoOp("SIP/voipms-000010f8", "Finish if_catch_h_352_353") in new stack
[Mar 18 16:44:04] VERBOSE[14577] netsock2.c:   == Using SIP RTP TOS bits 184
[Mar 18 16:44:04] VERBOSE[14577] netsock2.c:   == Using SIP RTP CoS mark 5

By: Akom Benevolent (akom) 2013-03-19 09:46:18.289-0500

Update: The fix from 17776 apparently solves the issue (unanswered=true).   These lost calls must have all gone through a queue unanswered.