Asterisk recently sent a voicemail email to an address that is not associated with that particular extension. Unfortunately, Asterisk doesn’t log any of the logic it uses to determine what email to use so I could figure out where in the selection process it went wrong. Here is a quick description and all log entries I can find. What I’d love to see is debug logging of the voicemail-email process so we can see each step of how it determines the proper email…
A call came in to a DID that uses an IVR. The caller made a selection that sent the call to exten 3060. That user didn’t pick up so it was sent to voicemail. The voicemail was recorded and an email was sent. The email for 3060 has always been correct in the gui/voicemail.conf. Instead of sending to the 3060 email the message went to the email for exten 1913 (which appears 55 lines BEFORE 3060 in voicemail.conf).
Here is the relevant part of the full log:
[2015-07-20 16:38:53] VERBOSE[C-000109c1] pbx.c: -- Executing [s-NOMESSAGE@macro-vm:3] VoiceMail("SIP/UC1-000296cf", "3060@default,s") in new stack [2015-07-20 16:38:53] VERBOSE[C-000109c1] file.c: -- <SIP/UC1-000296cf> Playing 'beep.ulaw' (language 'en') [2015-07-20 16:38:53] VERBOSE[C-000109c1] app_voicemail.c: -- Recording the message [2015-07-20 16:38:53] VERBOSE[C-000109c1] app.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/3060/tmp/FvvSOP format: wav, 0x7f4c72fc18d8 [2015-07-20 16:41:03] VERBOSE[C-000109c1] app.c: -- User hung up [2015-07-20 16:41:03] VERBOSE[C-000109c1] config.c: == Parsing '/var/spool/asterisk/voicemail/default/3060/INBOX/msg0000.txt': Found [2015-07-20 16:41:03] VERBOSE[C-000109c1] app_macro.c: == Spawn extension (macro-vm, s-NOMESSAGE, 3) exited non-zero on 'SIP/UC1-000296cf' in macro 'vm'
It’s clear that the call came in properly and was properly routed to the voicemail for exten 3060. The full log has no entries for email, so I correlated this with maillog:
Jul 20 16:41:03 voip2 postfix/pickup: DA4A05806EF: uid=499 from=<asterisk> Jul 20 16:41:03 voip2 postfix/cleanup: DA4A05806EF: message-id=<Asteriskfirstname.lastname@example.org> Jul 20 16:41:03 voip2 postfix/qmgr: DA4A05806EF: from=<email@example.com>, size=2856108, nrcpt=1 (queue active) Jul 20 16:41:04 voip2 postfix/smtp: DA4A05806EF: to=<WRONG@EMAIL.com>, relay=mail.mycompany.com [x.x.x.x]:25, delay=0.58, delays=0.14/0/0.06/0.39, dsn=2.0.0, status=sent (250 OK) Jul 20 16:41:04 voip2 postfix/qmgr: DA4A05806EF: removed
So somehow asterisk grabbed the wrong email for exten 3060.
There are 2 interesting things about my scenario:
- One of the other admins must have clicked the Apply Config button (we’re using FreePBX) while the voicemail was being left because once the “open writing” line appears there are thousands of config reload lines that are normally seen when someone applies the config. The voicemail is open for writing on line 3008329 and the user hangs up on line 3063708 (55,379 lines of config applying later).
- One of the other admins tried to put multiple email addresses in for a few of the extensions and separated them with a comma instead of a semicolon. These 3 extensions were new, so they were placed at the very end of voicemail.conf. I would assume that when Asterisk needs to find an email for an extension it could do something as simple as grep for the extension (^3060) and then awk the line for the email address. But if that’s not how it’s done, these commas could have broken the parsing of voicemail.conf.