Voicemail troubleshooting

ThePowerTool · December 5, 2022, 3:23pm

1st post! I’ve been reading here for years to learn. I guess I’ve been lucky as I haven’t had to ask any questions even though I don’t really feel confident responding to other’s questions. I’ve always found answers, here.

I just upgraded my Asterisk PBX:
Fedora 36 (headless)
asterisk.18.4.0-1.fc36.5.x86_64

The previoous version was SIP and I haven’t yet moved over to pjsip but plan to do that immediately after resolving the voicemail problem.

The problem: When asterisk sends a call to voicemail the greeting plays but then there is no subsequent beep or recording.

What I’ve tried:
1 - logs–I have looked for, but not found, any errors. I may not be reviewing a specific log because of my ignorance.
2 - verbose–I start asterisk with vvvvvvvv but no errors present when asterisk starts playing the greeting and after when it should be playing a beep and recording. Nothing is displayed until the call disconnects.
3 - searching–I haven’t been able to find any problem stated as voicemail where the greeting is played but no beep or recording.
4 - ownership and permissions–I looked for the voicemail module and it was owned by root so I tried changing it to asterisk:asterisk (no luck). It was a “hail mary” as the other modules appeared to be working fine. Again, I’m no expert.

My request: Can someone please point me to some troubleshooting steps for voicemail?

I’m happy to provide more detail, upon request, but my I am hoping someone can help me improve my knowledge of asterisk by pointing me to better troubleshooting.

Thanks!

penguinpbx · December 5, 2022, 5:02pm

Welcome!

You might try checking:

Are there any config file differences, especially /etc/asterisk/voicemail.conf ?
Permissions on /var/spool/asterisk/voicemail/ sub-directories for the voicemail box(es) you are testing.
Output of core show channels on the Asterisk CLI - run it when the call is stuck and not playing audio.
Enabling core set debug X on the Asterisk CLI to generate more log details (try X = 5).
Are you missing the beep file now? That would be odd… probably you would see other sound files missing, too, or maybe in the wrong place as if a directory got renamed in the newer package.

Also pasting a bit of the logs might help others to offer up more ideas.

ThePowerTool · December 5, 2022, 9:06pm

penguinpbx, yes, you nailed-it in one. My request was for pointers exactly like the ones you provided.

So, I looked at ownership and permissions for /var/spool/asterisk/voicemail. I changed ownership to asterisk:asterisk (from root:root). I thought that would cover it.

I arrived at your step-2 and a quick 777 fixed the problem.

I am wondering why I didn’t see any errors but I also hadn’t tried your suggestion of enabling core set debug X. If I wasn’t in such a hurry to get to pjsip I’d play with that (and may come back to it, later).

Thank you very much for your help!

sedwards · December 5, 2022, 9:53pm

…iike taking the front door of your house off because the lockset is sticky.

Looking at a couple of my hosts shows 755 would be a better choice.

ThePowerTool · December 5, 2022, 10:10pm

Done! Thank you.

ThePowerTool · December 7, 2022, 2:13am

OK, now I must hang my head in shame.

When I tested, I declined the call to speed the call to voicemail to speed the test process. This caused a “false” “pass” meaning my shortcut bypassed the problem making me think the issue was resolved. I am sorry.

I have now discovered:
VoiceMail(xxxx@default,b) - “busy” - works
VoiceMail(xxxx@default,u) - “unavail” - fails (plays u-greeting, no beep or record)

To answer your questions:

config changes–I reviewed my config. If there are differences I don’t see them.
permissions:

]# ls -l /var/spool/asterisk/
-rw-r--r--. 1 asterisk asterisk 12288 Dec  6 20:46 astdb.sqlite3
drwxrwx---. 2 asterisk asterisk     6 Jun 27 06:25 monitor
drwxrwx---. 2 asterisk asterisk     6 Jun 27 06:25 outgoing
drwxr-x---. 2 asterisk asterisk     6 Jun 27 06:25 tmp
drwxr-x---. 2 asterisk asterisk     6 Jun 27 06:25 uploads
drwxr-xr-x. 3 asterisk asterisk    21 Aug  4 12:21 voicemail

]# ls -l /var/spool/asterisk/voicemail/
drwxr-xr-x. 3 asterisk asterisk 18 Aug  4 12:21 default

see below
done, see below
beep file–so when VoiceMail is called with the “b” flag the instructions execute and the beep is played (see below). when VoiceMail is called with the “u” flag nothing seems to happen. I did wait during one test and it appears the time-out works and disconnects the call.

Here is the console detail for the (working) VoiceMail “b” (busy) flag:

    Incoming call to me forwarded to my-phone,[my ext] where call is manually declined:
    -- Executing [7045551212@from-trunk:13] GotoIf("SIP/Obitrunk1-00000004", "10?my-phone,1003,1") in new stack
    -- Goto (my-phone,1003,1)
    -- Executing [1003@my-phone:1] Dial("SIP/Obitrunk1-00000004", "SIP/1003,15") in new stack
  == Using SIP RTP CoS mark 5
    -- Called SIP/1003
    -- SIP/1003-00000005 is ringing
       > 0x7f77f000fa10 -- Strict RTP switching to RTP target address 192.168.1.48:16854 as source
    -- Got SIP response 603 "Decline" back from 192.168.1.9:55980
    -- SIP/1003-00000005 is busy
  == Everyone is busy/congested at this time (1:1/0/0)
    -- Executing [1003@my-phone:2] GotoIf("SIP/Obitrunk1-00000004", "1?busy:unavail") in new stack
    -- Goto (my-phone,1003,5)
    -- Executing [1003@my-phone:5] VoiceMail("SIP/Obitrunk1-00000004", "1003@default,b") in new stack
    -- <SIP/Obitrunk1-00000004> Playing '/var/spool/asterisk/voicemail/default/1003/busy.slin' (language 'en')
       > 0x7f77f000fa10 -- Strict RTP learning complete - Locking on source address 192.168.1.48:16854
    -- <SIP/Obitrunk1-00000004> Playing 'vm-intro.ulaw' (language 'en')
    -- <SIP/Obitrunk1-00000004> Playing 'beep.ulaw' (language 'en')
    -- Recording the message
    -- x=0, open writing:  /var/spool/asterisk/voicemail/default/1003/tmp/erdnhT format: wav49, 0x7f77980182e0
    -- x=1, open writing:  /var/spool/asterisk/voicemail/default/1003/tmp/erdnhT format: gsm, 0x7f7798018d90
    -- x=2, open writing:  /var/spool/asterisk/voicemail/default/1003/tmp/erdnhT format: wav, 0x7f7798017d20
    -- User hung up
  == Spawn extension (my-phone, 1003, 5) exited non-zero on 'SIP/Obitrunk1-00000004'

Here is the console detail for the non-working VoiceMail “u” (unavail) flag:
Please note, per your #3, core show channels included below:

    -- Executing [7045551212@from-trunk:13] GotoIf("SIP/Obitrunk1-00000006", "10?my-phone,1003,1") in new stack
    -- Goto (my-phone,1003,1)
    -- Executing [1003@my-phone:1] Dial("SIP/Obitrunk1-00000006", "SIP/1003,15") in new stack
  == Using SIP RTP CoS mark 5
    -- Called SIP/1003
    -- SIP/1003-00000007 is ringing
       > 0x7f77f000fa10 -- Strict RTP switching to RTP target address 192.168.1.48:16856 as source
       > 0x7f77f000fa10 -- Strict RTP learning complete - Locking on source address 192.168.1.48:16856
    -- Nobody picked up in 15000 ms
    -- Executing [1003@my-phone:2] GotoIf("SIP/Obitrunk1-00000006", "0?busy:unavail") in new stack
    -- Goto (my-phone,1003,3)
    -- Executing [1003@my-phone:3] VoiceMail("SIP/Obitrunk1-00000006", "1003@default,u") in new stack
    -- <SIP/Obitrunk1-00000006> Playing '/var/spool/asterisk/voicemail/default/1003/unavail.slin' (language 'en')

*CLI> core show channels
Channel              Location             State   Application(Data)             
SIP/Obitrunk1-000000 1003@my-phone:3      Up      VoiceMail(1003@default,u)     
1 active channel
1 active call
4 calls processed
*CLI>
; here I manually hung-up the phone (the phone I used to initiate the call) 
*CLI>   == Spawn extension (my-phone, 1003, 3) exited non-zero on 'SIP/Obitrunk1-00000006'

*CLI>

Finally, here is the messages log:

[Dec  4 00:00:21] Asterisk 18.4.0 built by mockbuild @ buildvm-x86-15.iad2.fedoraproject.org on a x86_64 running Linux on 2022-06-27 10:23:26 UTC
[Dec  5 17:09:50] ERROR[22683][C-0000001b] app.c: Unable to create lock file '/var/spool/asterisk/voicemail/default/1003/INBOX': Permission denied
[Dec  5 17:09:50] ERROR[22683][C-0000001b] app.c: Could not unlock path '/var/spool/asterisk/voicemail/default/1003/INBOX': No such file or directory
[Dec  5 17:09:51] ERROR[22683][C-0000001b] app_voicemail.c: Unable to create message file: Resource temporarily unavailable
[Dec  6 20:08:51] Asterisk 18.4.0 built by mockbuild @ buildvm-x86-15.iad2.fedoraproject.org on a x86_64 running Linux on 2022-06-27 10:23:26 UTC
[Dec  6 20:08:51] NOTICE[24866] loader.c: 310 modules will be loaded.
[Dec  6 20:08:51] NOTICE[24866] cdr.c: CDR simple logging enabled.
[Dec  6 20:08:51] WARNING[24866] res_musiconhold.c: No music on hold classes configured, disabling music on hold.
[Dec  6 20:08:51] WARNING[24866] res_phoneprov.c: Unable to find a valid server address or name.
[Dec  6 20:08:51] NOTICE[24866] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener.
[Dec  6 20:08:51] WARNING[24866] chan_dahdi.c: Ignoring any changes to 'userbase' (on reload) at line 23.
[Dec  6 20:08:51] WARNING[24866] chan_dahdi.c: Ignoring any changes to 'vmsecret' (on reload) at line 31.
[Dec  6 20:08:51] WARNING[24866] chan_dahdi.c: Ignoring any changes to 'hassip' (on reload) at line 35.
[Dec  6 20:08:51] WARNING[24866] chan_dahdi.c: Ignoring any changes to 'hasiax' (on reload) at line 39.
[Dec  6 20:08:51] WARNING[24866] chan_dahdi.c: Ignoring any changes to 'hasmanager' (on reload) at line 47.
[Dec  6 20:08:51] ERROR[24866] ari/config.c: No configured users for ARI
[Dec  6 20:08:51] NOTICE[24866] confbridge/conf_config_parser.c: Adding default_menu menu to app_confbridge
[Dec  6 20:08:51] NOTICE[24866] cel_custom.c: No mappings found in cel_custom.conf. Not logging CEL to custom CSVs.
[Dec  6 20:08:52] ERROR[24866] codec_dahdi.c: Failed to open /dev/dahdi/transcode: No such file or directory
[Dec  6 20:08:52] WARNING[24866] loader.c: Some non-required modules failed to load.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'res_monitor' has been loaded but may be removed in a future release. Its replacement is 'app_mixmonitor'.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'res_adsi' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_getcpeid' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_image' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_macro' has been loaded but may be removed in a future release. Its replacement is 'app_stack (GoSub)'.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_nbscat' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_url' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_dahdiras' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] WARNING[24866] loader.c: Module 'app_adsiprog' has been loaded but may be removed in a future release.
[Dec  6 20:08:52] ERROR[24866] loader.c: Error loading module 'res_ari_mailboxes.so': /usr/lib64/asterisk/modules/res_ari_mailboxes.so: undefined symbol: stasis_app_mailbox_to_json
[Dec  6 20:08:52] ERROR[24866] loader.c: res_timing_dahdi declined to load.
[Dec  6 20:08:52] ERROR[24866] loader.c: cdr_syslog declined to load.
[Dec  6 20:08:59] NOTICE[24866] chan_sip.c: The 'username' field for sip peers has been deprecated in favor of the term 'defaultuser'
[Dec  6 20:08:59] WARNING[24866] chan_sip.c: chan_sip has no official maintainer and is deprecated.  Migration to
[Dec  6 20:08:59] WARNING[24866] chan_sip.c: chan_pjsip is recommended.  See guides at the Asterisk Wiki:
[Dec  6 20:08:59] WARNING[24866] chan_sip.c: https://wiki.asterisk.org/wiki/display/AST/Migrating+from+chan_sip+to+res_pjsip
[Dec  6 20:08:59] WARNING[24866] chan_sip.c: https://wiki.asterisk.org/wiki/display/AST/Configuring+res_pjsip
[Dec  6 20:08:59] NOTICE[24930] chan_sip.c: Peer 'Obitrunk1' is now Reachable. (2ms / 2000ms)

Excerpt from extensions.conf:

[my-phone]
exten => 1003,1,Dial(SIP/1003,15)
   same => n,GotoIf($["${DIALSTATUS}" = "BUSY"]?busy:unavail)
   same => n(unavail),VoiceMail(1003@default,u)
   same => n,Hangup()
   same => n(busy),VoiceMail(1003@default,b)
   same => n,Hangup()

To summarize: VoiceMail (,b) works. VoiceMail (,u) fails as if “us” was sent meaning the u-greeting is played but no subsequent instructions, beep, recording.

I hope I have done a good job of following your direction regarding next steps but I am stuck.

Thank you, again, for your help.

Edit (additional note):
I changed:

   same => n(unavail),VoiceMail(1003@default,u)

to

   same => n(unavail),VoiceMail(1003@default,b)

Just to test. When I changed the flag (in “unavail”) the VoiceMail command worked properly for the b flag.

ThePowerTool · December 8, 2022, 12:36am

Kudos to my brother! After hearing about this over the phone he suggested replace my /var/spool/asterisk/voicemail/default/1003/unavail message with the busy messge.

Suddenly everything was working!

I think I’ll re-record my messages.

I have no clue what might have changed during my upgrade that the file would work on the old server and fail on the current.

I’m also curious this didn’t kick any type of error. I will keep the file–if anyone would like to review it I’d be happy to make a copy available.

Thank you very much for your help!

penguinpbx · December 15, 2022, 7:52pm

Glad it worked!

Now, take the “ain’t broke don’t fix” approach , or…

Per logs, they do not appear to show all the debug output available. In particular, in the app_voicemail.c’s leave_voicemail function, there is an ast_debug level 3 line that should write “Before find_user” – not seeing that in your output. Hmm. Could be in another file, depends how you have your /etc/asterisk/logger.conf setup eg. make sure “debug” is included in the “messages” log configuration line. This debug should also show any errors accessing/reading/copying the sln file.

Per functionality, you might try sticking in an Answer() before entering (into the caves of) VoiceMail(). And/or try an early Playback(beep) or Playback(silence/1) to get RTP moving. (Related CLI debug is “rtp set debug on”.)

InterLinked · December 17, 2022, 12:50pm

Per functionality, you might try sticking in an Answer() before entering (into the caves of) VoiceMail() . And/or try an early Playback(beep) or Playback(silence/1) to get RTP moving. (Related CLI debug is “rtp set debug on”.)

Answering the channel is kind of a brute force hack that is really a last resort. Usually Progress() is sufficient to get media moving and is the correct way to do it. You could then playback an audio file with the noanswer option to do this as well.

penguinpbx · December 19, 2022, 2:59pm

Agreed. But it is not as gory to Answer() before entering Voicemail() as, say, it would be to do so before a Dial().

system · January 18, 2023, 3:00pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.