MOH not working in ARA 16.5

Hi,
I am using ARA with 16.5 v and it says in the logs
Started music on hold, class ‘250-1XXXXXXXXXX’, on channel ‘SIP/SIP123-0000012c’
but no music is playing so I debugged and found
it says
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: media_cache.c:236 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/moh/macroform-cold_day’

And the complete logs below

[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM musiconhold WHERE name = ?
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_config_odbc.c:134 custom_prepare: Parameter 1 (‘name’) = ‘250-1XXXXXXXXXX’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7faca8000900 into pool
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_musiconhold.c:1192 moh_scan_files: Scanning ‘/var/lib/asterisk/moh’ for files for class ‘250-1XXXXXXXXXX’
– Started music on hold, class ‘250-1XXXXXXXXXX’, on channel ‘SIP/SIP123-0000012c’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: channel.c:3182 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: channel.c:4859 ast_prod: Prodding channel ‘SIP/SIP123-0000012c’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_rtp_asterisk.c:4097 ast_rtp_update_source: Setting the marker bit due to a source update
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: app_queue.c:5519 is_our_turn: There is 1 available member.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: app_queue.c:5534 is_our_turn: It’s our turn (SIP/SIP123-0000012c).
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: app_queue.c:6818 try_calling: SIP/SIP123-0000012c is trying to call a queue member.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: app_queue.c:4682 ring_one: (Parallel) Trying ‘SIP/1000’ with metric 1000000
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: app_queue.c:4463 can_ring_entry: Add SIP/1000@DefaultZ to pending_members
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: chan_sip.c:30721 sip_request_call: Asked to create a SIP channel with formats: (ulaw)
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: chan_sip.c:9060 __sip_alloc: Allocating new SIP dialog for 1501a3e972235d423ef29766665565d1@[fe80::f122:41f4:694d:12d8]:5060 - INVITE (No RTP)
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7faca8000900 from class ‘asterisk’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_buddies WHERE name = ? AND host = ?
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_config_odbc.c:134 custom_prepare: Parameter 1 (‘name’) = ‘1000’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_config_odbc.c:134 custom_prepare: Parameter 2 (‘host’) = ‘dynamic’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7faca8000900 into pool
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: stasis.c:570 stasis_topic_create_with_detail: Creating topic. name: endpoint:SIP/1000, detail:
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: stasis.c:604 stasis_topic_create_with_detail: Topic ‘endpoint:SIP/1000’: 0x7fadd40049c0 created
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: stasis.c:570 stasis_topic_create_with_detail: Creating topic. name: cache:13650/endpoint:SIP/1000, detail:
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: stasis.c:604 stasis_topic_create_with_detail: Topic ‘cache:13650/endpoint:SIP/1000’: 0x7fadd4041e00 created
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: chan_sip.c:31601 build_peer: -REALTIME- peer built. Name: 1000. Peer objects: 2
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting ‘10.10.10.10’ into…
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:224 ast_sockaddr_split_hostport: …host ‘10.10.10.10’ and port ‘’.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: chan_sip.c:32236 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: chan_sip.c:32239 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: chan_sip.c:5712 realtime_peer: -REALTIME- loading peer from database to memory. Name: 1000. Peer objects: 2
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: rtp_engine.c:526 ast_rtp_instance_new: Using engine ‘asterisk’ for RTP instance ‘0x7fadd4049440’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_rtp_asterisk.c:3598 rtp_allocate_transport: Allocated port 10592 for RTP instance ‘0x7fadd4049440’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: res_rtp_asterisk.c:3628 rtp_allocate_transport: Creating ICE session 0.0.0.0:10592 (10592) for RTP instance ‘0x7fadd4049440’
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting ‘1.1.1.1’ into…
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:224 ast_sockaddr_split_hostport: …host ‘1.1.1.1’ and port ‘’.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting ‘1.1.1.1’ into…
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:224 ast_sockaddr_split_hostport: …host ‘1.1.1.1’ and port ‘’.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting ‘10.0.200.41’ into…
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:224 ast_sockaddr_split_hostport: …host ‘10.0.200.41’ and port ‘’.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting ‘10.0.200.41’ into…
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:224 ast_sockaddr_split_hostport: …host ‘10.0.200.41’ and port ‘’.
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance ‘0x7fadd4049440’ is setup and ready to go
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting ‘1.1.1.1.static-delhi.vsnl.net.in’ into…
[Sep 9 06:47:09] DEBUG[164151][C-000000df]: netsock2.c:224 ast_sockaddr_split_hostport: …host ‘1.1.1.1.static-delhi.vsnl.net.in’ and port ‘’.
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: acl.c:828 resolve_first: Multiple addresses. Using the first only
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: res_rtp_asterisk.c:7783 ast_rtp_prop_set: Setup RTCP on RTP instance ‘0x7fadd4049440’
== Using SIP RTP CoS mark 5
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:5847 do_setnat: Setting NAT on RTP to On
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: acl.c:990 ast_ouraddrfor: For destination ‘10.10.10.10’, our source address is ‘1.1.1.1’.
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:3958 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 1.1.1.1:5060
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:5847 do_setnat: Setting NAT on RTP to On
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8849 change_callid_pvt: SIP call-id changed from ‘1501a3e972235d423ef29766665565d1@[fe80::f122:41f4:694d:12d8]:5060’ to ‘4ae02c5d0de4b1df2b0a8dfc58144263@1.1.1.1:5060’
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: stasis.c:570 stasis_topic_create_with_detail: Creating topic. name: channel:1568011630.468, detail:
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: stasis.c:604 stasis_topic_create_with_detail: Topic ‘channel:1568011630.468’: 0x7fadd4012c00 created
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: stasis.c:570 stasis_topic_create_with_detail: Creating topic. name: cache:13651/channel:1568011630.468, detail:
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: stasis.c:604 stasis_topic_create_with_detail: Topic ‘cache:13651/channel:1568011630.468’: 0x7fadd40415a0 created
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: channel.c:989 __ast_channel_alloc_ap: Channel 0x7fadd4052a00 ‘SIP/1000-0000012d’ allocated
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8213 sip_new: *** Our native formats are (ulaw)
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8214 sip_new: *** Joint capabilities are (ulaw)
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8215 sip_new: *** Our capabilities are (ulaw|alaw)
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8216 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8218 sip_new: *** Our preferred formats from the incoming channel are (ulaw)
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:8249 sip_new: This channel will not be able to handle video.
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: channel_internal_api.c:770 ast_channel_callid_set: Channel Call ID changing from [C-000000df] to [C-000000df]
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:6527 sip_call: Outgoing Call for 1000
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:6816 update_call_counter: Updating call counter for outgoing call
[Sep 9 06:47:10] DEBUG[2635]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for SIP - 1000
[Sep 9 06:47:10] DEBUG[2635]: chan_sip.c:30614 sip_devicestate: Checking device state for peer 1000
[Sep 9 06:47:10] DEBUG[2635]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7faca8000900 from class ‘asterisk’
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:13585 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:13586 add_sdp: ** Our prefcodec: (ulaw)
[Sep 9 06:47:10] DEBUG[2635]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_buddies WHERE name = ? AND host = ?
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:13757 add_sdp: – Done with adding codecs to SDP
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:13976 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw)
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:3444 initialize_initreq: Initializing initreq for method INVITE - callid 4ae02c5d0de4b1df2b0a8dfc58144263@1.1.1.1:5060
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: chan_sip.c:3801 __sip_xmit: Trying to put ‘INVITE sip:’ onto UDP socket destined for 10.10.10.10:57852
– Called SIP/1000
– SIP/1000-0000012d connected line has changed. Saving it until answer for SIP/SIP123-0000012c
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: res_timing_timerfd.c:167 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: media_cache.c:236 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/moh/macroform-cold_day’
[Sep 9 06:47:10] DEBUG[2635]: res_config_odbc.c:134 custom_prepare: Parameter 1 (‘name’) = ‘1000’
[Sep 9 06:47:10] DEBUG[2635]: res_config_odbc.c:134 custom_prepare: Parameter 2 (‘host’) = ‘dynamic’
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: media_cache.c:236 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/moh/macroform-cold_day’
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: channel.c:5645 set_format: Channel SIP/SIP123-0000012c setting write format path: slin -> ulaw
[Sep 9 06:47:10] DEBUG[2635]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7faca8000900 into pool
[Sep 9 06:47:10] DEBUG[2635]: stasis.c:570 stasis_topic_create_with_detail: Creating topic. name: endpoint:SIP/1000, detail:
[Sep 9 06:47:10] DEBUG[2635]: stasis.c:575 stasis_topic_create_with_detail: Topic is already exist. name: endpoint:SIP/1000, detail:
[Sep 9 06:47:10] DEBUG[2635]: stasis.c:570 stasis_topic_create_with_detail: Creating topic. name: cache:13652/endpoint:SIP/1000, detail:
[Sep 9 06:47:10] DEBUG[2635]: stasis.c:604 stasis_topic_create_with_detail: Topic ‘cache:13652/endpoint:SIP/1000’: 0x7fae4401c2c0 created
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: res_musiconhold.c:385 ast_moh_files_next: SIP/SIP123-0000012c Opened file 0 ‘/var/lib/asterisk/moh/macroform-cold_day’
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: audiohook.c:189 ast_audiohook_write_frame: Flushing audiohook 0x7fadd4043af0 so it remains in sync
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: audiohook.c:199 ast_audiohook_write_frame: Audiohook 0x7fadd4043af0 has stale audio in its factories. Flushing them both
[Sep 9 06:47:10] DEBUG[164151][C-000000df]: res_rtp_asterisk.c:4097 ast_rtp_update_source: Setting the marker bit due to a source update

Can anyone shed some light why it is failing to obtain media when it exists

Thanks in advance

It’s a debug message, it means that it wasn’t found in the cache - not that it wasn’t found at all. It falls back to the local filesystem and pens the file:

[Sep 9 06:47:10] DEBUG[164151][C-000000df]: res_musiconhold.c:385 ast_moh_files_next: SIP/SIP123-0000012c Opened file 0 ‘/var/lib/asterisk/moh/macroform-cold_day’

Debug messages can send you down the wrong direction unless you know what is going on, as they can indicate a problem when none exists.

try checking permissions or which codec is it moh is picky more than regular media files