Charged for call, no CDR, where to troubleshoot?

Sorry if this is the wrong place to ask, but I have a problem troubleshooting a call which I did not answer, but got charged $4.47 for a duration of 2:28:08 by my trunk.

It was an incoming call from 18173113365; I saw it on my desk phone. There was no voicemail left. The phone’s log sees it as unanswered. Asterisk (asterisk13-13.9.1-1.shmz65.1.115.x86_64) has no CDR at all for it, as though the call never came in! Anveo (the trunk) says the problem is on my end so they will not refund me for the call.

Here is the problem - what the hell happened? Are there logs somewhere in Asterisk that I can look in to troubleshoot? How do I even begin? If this keeps happening I’ll have to forget about VoIP altogether because at least the analog carriers didn’t charge me for calls I didn’t answer!

You can turn on the channel technology driver debugging to get details of the protocol exchanges over the trunk.

As you say VoIP, we can rule out DAHDI. My best guess for failed to specify the technology is cha_sip, in which case you need to use sip set debug on. Then reproduce the issue.

Thanks for the reply. It is chan_sip. I used the command “sip set debug peer anveo”.

It looks like the debug info is going to the asterisk console as well as /var/log/asterisk/full. Is this correct?

I’m unsure how to do this, as it’s never happened before with any other call, just this one. Any suggestions? Is there a log file I’m missing? Why is there no CDR for this call even though my phone has a log of it?

SHMZ? Is this a FreePBX box? If so, usually all FreePBX base box answer by deafult the calls. If you have the history of full log try a grep with the number and find the ID of that call then trace if was answered or not.

Yes.

It routed the call to my extension, where I saw it ringing. After 3 rings, it goes to voicemail, but there was no message.

[2016-09-08 13:18:51] VERBOSE[30048][C-00000000] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/anveo-00000000”, “11?Set(FROMEXTEN=18173113365)”) in new stack
:[2016-09-08 13:18:51] VERBOSE[30048][C-00000000] pbx.c: Executing [18889985236@from-trunk:6] ExecIf(“SIP/anveo-00000000”, “0 ?Set(CALLERID(name)=18173113365)”) in new stack
[2016-09-08 13:18:52] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/anveo-00000000”, “AMPUSER=18173113365”) in new stack
[2016-09-08 13:18:52] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/anveo-00000000”, “1?Set(REALCALLERIDNUM=18173113365)”) in new stack
[2016-09-08 13:18:52] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:30] Set(“SIP/anveo-00000000”, “CALLERID(number)=18173113365”) in new stack
[2016-09-08 13:18:52] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:32] Set(“SIP/anveo-00000000”, “CDR(cnum)=18173113365”) in new stack
[2016-09-08 13:18:52] VERBOSE[30048][C-00000000] pbx.c: Executing [exten@sub-record-check:1] NoOp(“SIP/anveo-00000000”, “Exten Recording Check between 18173113365 and 100”) in new stack
[2016-09-08 13:18:52] VERBOSE[30048][C-00000000] pbx.c: Executing [ctset@macro-dial-one:1] Set(“SIP/anveo-00000000”, “DB(CALLTRACE/100)=18173113365”) in new stack
[2016-09-08 13:19:07] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/anveo-00000000”, “AMPUSER=18173113365”) in new stack
[2016-09-08 13:19:07] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/anveo-00000000”, “0?Set(REALCALLERIDNUM=18173113365)”) in new stack
[2016-09-08 13:19:07] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:30] Set(“SIP/anveo-00000000”, “CALLERID(number)=18173113365”) in new stack
[2016-09-08 13:19:07] VERBOSE[30048][C-00000000] pbx.c: Executing [s@macro-user-callerid:32] Set(“SIP/anveo-00000000”, “CDR(cnum)=18173113365”) in new stack

Is 30048 the ID of the session? If so, the last entries are:

[2016-09-08 13:19:08] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘vm-theperson.ulaw’ (language ‘en’)
[2016-09-08 13:19:10] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘digits/1.ulaw’ (language ‘en’)
[2016-09-08 13:19:10] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘digits/0.ulaw’ (language ‘en’)
[2016-09-08 13:19:11] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘digits/0.ulaw’ (language ‘en’)
[2016-09-08 13:19:12] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘vm-isunavail.ulaw’ (language ‘en’)
[2016-09-08 13:19:13] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘vm-intro.ulaw’ (language ‘en’)
[2016-09-08 13:19:19] VERBOSE[30048][C-00000000] file.c: <SIP/anveo-00000000> Playing ‘beep.ulaw’ (language ‘en’)
[2016-09-08 13:19:19] VERBOSE[30048][C-00000000] app_voicemail.c: Recording the message
[2016-09-08 13:19:19] VERBOSE[30048][C-00000000] app.c: x=0, open writing: /var/spool/asterisk/voicemail/default/100/tmp/Vsak0S format: wav, 0x21d7698

There is a file /var/spool/asterisk/voicemail/default/100/tmp/Vsak0S.wav which is 131Mb, 2:22:29 long, and is silent. I don’t see any entries where the call stops recording and hangs up. How would I find those?

Yes that is your ID to search, you will need to check the complete output in the full log. And most important if the “Playing -soundhere-” was called by the Playback application then your call was ansewered unless the cmd has explicity the noanswer option in it.

If you think the channel is still running then try in the cli the command: ‘core show channels verbose’

The time that your provider charged match with the lenght of your voicemail.

OK thanks. So the last lines for that session are above. This means we have an issue where if the other party doesn’t hang up (or maybe it has, but the call stayed recording anyway?) it’ll record and then just stop on its own without bothering to even leave a log entry or CDR. Not good!

I always knew the call was routed somewhere. When I said it wasn’t answered, I meant it wasn’t answered by me.

0 active channels
0 active calls

[quote=“navaismo, post:6, topic:68039”]The time that your provider charged match with the lenght of your voicemail.
[/quote]
It’s actually longer by 6 minutes. Thanks for your help. It looks like I’m going to have to figure out how to prevent this kind of crap from happening because it could cost me a whole bunch of money really quickly! Any ideas? Maybe a detect silence rule when recording a message?

You need to enable the SIP debug i order to check if you are receiving the BYE to hangup the sip session. That will be a little hard if you have a lot of calls. You can do it also with a tcpdump capture if you dont want to fill the logs with a bunch of sip output.

Since you are using freepbx you need to check your version and update if apply. Also check if editing the dialplan to change all the explicit answers to progress make a difference. And finally check the values for the voicemail configuration since you can set the maxsilence timeout and the maxmessage which is the duration time: http://www.voip-info.org/wiki/view/Asterisk+config+voicemail.conf

Terrific help! Thanks so much.