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

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