[Home]

Summary:ASTERISK-12994: Missing CallerID in CDR when last app is voicemail
Reporter:Steve Suehring (ssuehring)Labels:
Date Opened:2008-10-30 15:54:41Date Closed:2008-12-04 17:41:31.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Hello,

I believe this to be a bug but I haven't had any luck combing the code for where it might be happening.  I have a dialplan (included in this ticket) that ends with a call to VoiceMail.  However, whenever this happens the CDR record contains no callerid information, neither number nor name.  The CDR record is indeed produced but the callerid info is empty.  This is true regardless of the method for CDR, of which I'm using cdr-csv, cdr_custom, and cdr-mysql.  None of them contain callerid info when the last app is voicemail.

Here's a CDR record for a voicemail-answered call:
"","","s","dp-incoming","","DAHDI/3-1","SIP/gxp2000-081ebaa8","VoiceMail","110@default","2008-10-30 15:29:09","2008-10-30 15:29:36","2008-10-30 15:29:48",39
,12,"ANSWERED","DOCUMENTATION","1225398549.14",""

Here's a CDR record for a person-answered call (using X's to replace the phone number):
"","71534XXXXX","s","dp-open","""UW STE"" <71534XXXXX>","DAHDI/3-1","SI
P/spa31-b7a4ae38","Dial","SIP/spa31&SIP/gxpste1&SIP/gxp2000,25","2008-1
0-30 15:08:25","2008-10-30 15:08:35","2008-10-30 15:09:18",53,43,"ANSWERED","DOC
UMENTATION","1225397305.11",""

This occurs regardless of whether the person leaves a voicemail or not.  I did a NoOp and the callerid is sent to the messages log just fine for either type of call.

Here's the dialplan:
[dp-incoming]
exten => s,1,Gosub(checkid,s,1)
exten => s,n,GotoIfTime(08:00-17:00,*,*,*?dp-open,s,1)
exten => s,n,GotoIfTime(17:01-07:59,*,*,*?dp-closed,s,1)
exten => s,n,Goto(dp-closed,s,1)

[dp-open]
exten => s,1,Dial(SIP/spa31&SIP/gxpste1&SIP/gxp2000,25)
exten => s,n,Answer
exten => s,n,Wait(2)
exten => s,n,VoiceMail(110@default)
exten => t,1,Playback(vm-goodbye)
exten => t,2,Hangup()

Please let me know if I can provide any additional details.

Steve


Comments:By: Terry Wilson (twilson) 2008-10-30 16:57:21

For me this happens if I exit out of voicemail hitting '#', but not if I just hangup the channel (I'm using console dial), is this the same for you?
By: Steve Suehring (ssuehring) 2008-10-30 20:07:37

This happens on hangup, no # pressed.  I didn't think the people calling were all hitting # to end the call but I just called and reproduced it by leaving a voicemail and then simply hanging up.  I got a CDR entry but no callerid in the record.

Steve
By: Steve Suehring (ssuehring) 2008-10-30 20:16:53

Note that after leaving the voicemail the channel falls through to a NOANSWER state.  As I type this I'm realizing it's probably not relevant since I'm getting the CDR entry just no callerid.

[Oct 30 20:15:43] VERBOSE[3715] logger.c:     -- Recording automatically stopped
after a silence of 3 seconds
[Oct 30 20:15:43] VERBOSE[3715] logger.c:     -- <DAHDI/3-1> Playing 'auth-thank
you.gsm' (language 'en')
[Oct 30 20:15:44] VERBOSE[3715] logger.c:     -- Auto fallthrough, channel 'DAHD
I/3-1' status is 'NOANSWER'
[Oct 30 20:15:44] VERBOSE[3715] logger.c:     -- Hungup 'DAHDI/3-1'
By: Steve Suehring (ssuehring) 2008-10-31 08:46:56

Some debug info.  Looks like pbx.c calls the VoiceMail app but when processing comes back to pbx.c the callerid is cleared.  There's a ton of callerid related things going on in app_voicemail.c, so maybe one of them is clearing the variable.  Interesting to note that the callerid number is in the e-mail I receive with the voicemail.

[Oct 30 21:16:33] DEBUG[4355] pbx.c: Launching 'VoiceMail'
[Oct 30 21:16:33] VERBOSE[4355] logger.c:     -- Executing [s@dp-open:4] VoiceMail("DAHDI/3-1", "110@default") in new stack
[Oct 30 21:16:33] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to write format gsm
[Oct 30 21:16:33] DEBUG[4355] channel.c: Scheduling timer at 160 sample intervals
[Oct 30 21:16:33] VERBOSE[4355] logger.c:     -- <DAHDI/3-1> Playing 'vm-intro.gsm' (language 'en')
[Oct 30 21:16:38] DEBUG[4355] channel.c: Scheduling timer at 0 sample intervals
[Oct 30 21:16:38] DEBUG[4355] channel.c: Scheduling timer at 0 sample intervals
[Oct 30 21:16:38] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to write format ulaw
[Oct 30 21:16:38] DEBUG[4355] app.c: Locked path '/var/spool/asterisk/voicemail/default/110/INBOX'
[Oct 30 21:16:38] DEBUG[4355] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/110/INBOX'
[Oct 30 21:16:38] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to write format gsm
[Oct 30 21:16:38] DEBUG[4355] channel.c: Scheduling timer at 160 sample intervals
[Oct 30 21:16:38] VERBOSE[4355] logger.c:     -- <DAHDI/3-1> Playing 'beep.gsm' (language 'en')
[Oct 30 21:16:39] DEBUG[4355] channel.c: Scheduling timer at 0 sample intervals
[Oct 30 21:16:39] DEBUG[4355] channel.c: Scheduling timer at 0 sample intervals
[Oct 30 21:16:39] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to write format ulaw
[Oct 30 21:16:39] VERBOSE[4355] logger.c:     -- Recording the message
[Oct 30 21:16:39] DEBUG[4355] app.c: play_and_record: <None>, /var/spool/asterisk/voicemail/default/110/tmp/dRRyLw,
'wav49|gsm|wav'
[Oct 30 21:16:39] DEBUG[4355] app.c: Recording Formats: sfmts=wav49
[Oct 30 21:16:39] VERBOSE[4355] logger.c:     -- x=0, open writing:  /var/spool/asterisk/voicemail/default/110/tmp/dRRyLw format: wav49, 0xb7a9fbd0
[Oct 30 21:16:39] VERBOSE[4355] logger.c:     -- x=1, open writing:  /var/spool/asterisk/voicemail/default/110/tmp/dRRyLw format: gsm, 0xb7a745a0
[Oct 30 21:16:39] VERBOSE[4355] logger.c:     -- x=2, open writing:  /var/spool/asterisk/voicemail/default/110/tmp/dRRyLw format: wav, 0xb7a9fd18
[Oct 30 21:16:39] DEBUG[4355] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Oct 30 21:16:39] DEBUG[4355] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Oct 30 21:16:39] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to read format slin
[Oct 30 21:16:39] DEBUG[4355] chan_dahdi.c: Requested indication 18 on channel DAHDI/3-1
[Oct 30 21:16:46] VERBOSE[4355] logger.c:     -- Recording automatically stopped after a silence of 3 seconds
[Oct 30 21:16:46] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to read format ulaw
[Oct 30 21:16:46] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to write format gsm
[Oct 30 21:16:46] DEBUG[4355] channel.c: Scheduling timer at 160 sample intervals
[Oct 30 21:16:46] VERBOSE[4355] logger.c:     -- <DAHDI/3-1> Playing 'auth-thankyou.gsm' (language 'en')
[Oct 30 21:16:46] DEBUG[4355] channel.c: Scheduling timer at 0 sample intervals
[Oct 30 21:16:46] DEBUG[4355] channel.c: Scheduling timer at 0 sample intervals
[Oct 30 21:16:46] DEBUG[4355] channel.c: Set channel DAHDI/3-1 to write format ulaw
[Oct 30 21:16:46] DEBUG[4355] app.c: Locked path '/var/spool/asterisk/voicemail/default/110/INBOX'
[Oct 30 21:16:46] DEBUG[4355] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/110/INBOX'
[Oct 30 21:16:46] DEBUG[4355] app_voicemail.c: Sent mail to 110@braingia.org with command '/usr/sbin/sendmail -t'
[Oct 30 21:16:46] DEBUG[4337] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Oct 30 21:16:46] DEBUG[4337] chan_sip.c: Initializing initreq for method NOTIFY - callid 3ade1b614262d2700f3624a37f3904ea@192.168.1.200
[Oct 30 21:16:46] DEBUG[4337] chan_sip.c: Trying to put 'NOTIFY sip' onto UDP socket destined for 192.168.1.15:5060
[Oct 30 21:16:46] VERBOSE[4355] logger.c:     -- Auto fallthrough, channel 'DAHDI/3-1' status is 'NOANSWER'
[Oct 30 21:16:46] DEBUG[4355] channel.c: Soft-Hanging up channel 'DAHDI/3-1'
[Oct 30 21:16:46] DEBUG[4355] channel.c: Hanging up channel 'DAHDI/3-1'
[Oct 30 21:16:46] DEBUG[4355] chan_dahdi.c: dahdi_hangup(DAHDI/3-1)
[Oct 30 21:16:46] DEBUG[4355] chan_dahdi.c: Hangup: channel: 3 index = 0, normal = 13, callwait = -1, thirdcall = -1
[Oct 30 21:16:46] DEBUG[4355] chan_dahdi.c: Disabled echo cancellation on channel 3
[Oct 30 21:16:46] DEBUG[4355] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/3-1
[Oct 30 21:16:46] DEBUG[4355] chan_dahdi.c: Updated conferencing on 3, with 0 conference users
[Oct 30 21:16:46] VERBOSE[4355] logger.c:     -- Hungup 'DAHDI/3-1'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is ''
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is ''
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 's'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 'dp-incoming'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 'DAHDI/3-1'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 'SIP/gxp2000-b7aa7ad8'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 'VoiceMail'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '110@default'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '2008-10-30 21:16:03'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '2008-10-30 21:16:31'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '2008-10-30 21:16:46'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '43'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '15'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 'ANSWERED'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is 'DOCUMENTATION'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is ''
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is '1225419363.3'
[Oct 30 21:16:46] DEBUG[4355] pbx.c: Function result is ''
By: Steve Suehring (ssuehring) 2008-10-31 10:05:35

Hmm.  I think I found a solution, though I don't know if it's a required solution that I failed to implement in my dial plan or if this is just a workaround.

Manually adding a Hangup call after the call to VoiceMail fixes the issue, so the dialplan now looks like this, note the addition of the s,n,Hangup.

exten => s,1,Dial(SIP/spa31&SIP/gxpste1&SIP/gxp2000,25)
exten => s,n,Answer
exten => s,n,Wait(2)
exten => s,n,VoiceMail(110@default)
exten => s,n,Hangup()
exten => t,1,Playback(vm-goodbye)
exten => t,2,Hangup()

Is that a documented thing that I just missed or is there an actual bug here?  It's weird that there would be a CDR record created but the callerid info would be cleared.
By: Terry Wilson (twilson) 2008-10-31 10:20:37

My initial impulse is to say that there is a bug.  Thanks for all the help in tracking this down.  I'll see if I can't run down the problem now that I think I'm done working on another issue.
By: Terry Wilson (twilson) 2008-12-04 17:41:30.000-0600

I don't seem to be able to recreate this at all now in the branch.  ssuehring, I know you found a workaround.  So, I'm going to go ahead and close this one.  If you still run into it, please feel free to reopen.