[Home]

Summary:ASTERISK-17396: Res_musiconhold Kills Mpg123 Upon Initial Start or Reload if a Streaming Source Defined
Reporter:Vladimir Mikhelson (vmikhelson)Labels:
Date Opened:2011-02-12 17:34:44.000-0600Date Closed:2012-01-30 23:48:27.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Resources/res_musiconhold
Versions:1.8.2 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) backtrace.txt
( 1) gdb.txt
Description:Added a streaming source to MOH. Static MOH works fine, streaming MOH produces silence.

mpg123 1.13.1

Asterisk 1.8.2.3
FreePBX 2.8.1.0

Was unable to test with branch/1.8 as voicemail application locks up upon the initial Asterisk load and consequentially prevents full system load.

****** ADDITIONAL INFORMATION ******

[root@pbx asterisk]# ps -A | grep mpg123
22076 pts/0    00:00:00 mpg123


[Feb 12 17:16:51] VERBOSE[22065] loader.c:     -- Reloading module 'res_musiconhold.so' (Music On Hold Resource)
[Feb 12 17:16:51] VERBOSE[22065] config.c:   == Parsing '/etc/asterisk/musiconhold.conf': [Feb 12 17:16:51] VERBOSE[22065] config.c:   == Found
[Feb 12 17:16:51] VERBOSE[22065] config.c:   == Parsing '/etc/asterisk/musiconhold_custom.conf': [Feb 12 17:16:51] VERBOSE[22065] config.c:   == Found
[Feb 12 17:16:51] VERBOSE[22065] config.c:   == Parsing '/etc/asterisk/musiconhold_additional.conf': [Feb 12 17:16:51] VERBOSE[22065] config.c:   == Found
[Feb 12 17:16:51] DEBUG[22065] res_musiconhold.c: killing 22076!
[Feb 12 17:16:52] DEBUG[22065] res_musiconhold.c: mpg123 pid 22076 and child died after 64560 bytes read

pbx*CLI> moh show classes
Class: moh
       Mode: files
       Directory: /var/lib/asterisk//mohmp3/moh/
Class: VikVik
       Mode: custom
       Directory: nodir
       Application: /usr/local/bin/mpg123 -q -r 8000 -f 8192 -s --mono -b 0 http://213.251.162.25:80/
       Format: ulaw
Class: default
       Mode: files
       Directory: /var/lib/asterisk//mohmp3/
Class: none
       Mode: files
       Directory: /var/lib/asterisk//mohmp3/.nomusic_reserved

[root@pbx asterisk]# mpg123 --version
mpg123 1.13.1

Comments:By: Vladimir Mikhelson (vmikhelson) 2011-02-12 17:39:52.000-0600

I made sure mpg123 starts and works fine if started manually.

I played with all parameters with no luck.

Format: ulaw, slin -- makes no difference.
By: Vladimir Mikhelson (vmikhelson) 2011-02-23 21:28:03.000-0600

May be related to 0018877: external moh is blocked when using dahdi timer.
By: Vladimir Mikhelson (vmikhelson) 2011-02-28 20:15:09.000-0600

Yep, that was it.

1.8.3 which includes the 0018877 patch fixed this issue.

Now I experience the new flavor of the same issue.

If I use yum update and load qwell's 1.8.3 build streaming works granted I have the infamous "res_musiconhold.c: Request to schedule in the past?!?!" messages in my log.

If I build Asterisk myself from the 1.8.3 tag static MOH still works fine, streaming is silent.

Log analysis showed that when qwell's Asterisk starts it first loads res_musiconhold.so which complains of the lack of the timing source, " res_musiconhold.c: Unable to create timer: No such file or directory" and then loader subsequently loads res_timing_dahdi.so. See Exhibit 1. In this case streaming MOH is happy.

When my build loads it starts with loading timing interfaces and only then loads musiconhold.  See Exhibit 2.  In this case streaming MOH is unhappy, i.e produces dead air.


******* Exhibit 1 **********
[Feb 28 20:10:15] WARNING[10787] res_musiconhold.c: Unable to create timer: No such file or directory
[Feb 28 20:10:15] VERBOSE[10787] pbx.c:   == Registered application 'MusicOnHold'
[Feb 28 20:10:15] VERBOSE[10787] pbx.c:   == Registered application 'WaitMusicOnHold'
[Feb 28 20:10:15] VERBOSE[10787] pbx.c:   == Registered application 'SetMusicOnHold'
[Feb 28 20:10:15] VERBOSE[10787] pbx.c:   == Registered application 'StartMusicOnHold'
[Feb 28 20:10:15] VERBOSE[10787] pbx.c:   == Registered application 'StopMusicOnHold'
[Feb 28 20:10:15] VERBOSE[10787] loader.c:  res_musiconhold.so => (Music On Hold Resource)
[Feb 28 20:10:15] VERBOSE[10787] loader.c:  res_timing_dahdi.so => (DAHDI Timing Interface)
[Feb 28 20:10:15] VERBOSE[10787] rtp_engine.c:   == Registered RTP engine 'asterisk'
[Feb 28 20:10:15] VERBOSE[10787] config.c:   == Parsing '/etc/asterisk/rtp.conf': [Feb 28 20:10:15] VERBOSE[107
87] config.c:   == Found
[Feb 28 20:10:15] VERBOSE[10787] res_rtp_asterisk.c:   == RTP Allocating from port range 10000 -> 20000
[Feb 28 20:10:15] VERBOSE[10787] loader.c:  res_rtp_asterisk.so => (Asterisk RTP Stack)
[Feb 28 20:10:15] VERBOSE[10787] rtp_engine.c:   == Registered RTP engine 'multicast'
[Feb 28 20:10:15] VERBOSE[10787] loader.c:  res_rtp_multicast.so => (Multicast RTP Engine)
[Feb 28 20:10:15] VERBOSE[10787] loader.c:  res_timing_pthread.so => (pthread Timing Interface)


**************** Exhibit 2 ******************
[Feb 28 22:03:33] VERBOSE[31785] loader.c:  res_timing_pthread.so => (pthread Timing Interface)
[Feb 28 22:03:33] VERBOSE[31785] loader.c:  res_timing_dahdi.so => (DAHDI Timing Interface)
[Feb 28 22:03:33] VERBOSE[31785] rtp_engine.c:   == Registered RTP engine 'asterisk'
[Feb 28 22:03:33] VERBOSE[31785] config.c:   == Parsing '/etc/asterisk/rtp.conf': [Feb 28 22:03:33] VERBOSE[317
85] config.c:   == Found
[Feb 28 22:03:33] VERBOSE[31785] res_rtp_asterisk.c:   == RTP Allocating from port range 10000 -> 20000
[Feb 28 22:03:33] VERBOSE[31785] loader.c:  res_rtp_asterisk.so => (Asterisk RTP Stack)
[Feb 28 22:03:33] VERBOSE[31785] config.c:   == Parsing '/etc/asterisk/musiconhold.conf': [Feb 28 22:03:33] VER
BOSE[31785] config.c:   == Found
[Feb 28 22:03:33] VERBOSE[31785] config.c:   == Parsing '/etc/asterisk/musiconhold_custom.conf': [Feb 28 22:03:
33] VERBOSE[31785] config.c:   == Found
[Feb 28 22:03:33] VERBOSE[31785] config.c:   == Parsing '/etc/asterisk/musiconhold_additional.conf': [Feb 28 22
:03:33] VERBOSE[31785] config.c:   == Found
[Feb 28 22:03:33] VERBOSE[31785] pbx.c:   == Registered application 'MusicOnHold'
[Feb 28 22:03:33] VERBOSE[31785] pbx.c:   == Registered application 'WaitMusicOnHold'
[Feb 28 22:03:33] VERBOSE[31785] pbx.c:   == Registered application 'SetMusicOnHold'
[Feb 28 22:03:33] VERBOSE[31785] pbx.c:   == Registered application 'StartMusicOnHold'
[Feb 28 22:03:33] VERBOSE[31785] pbx.c:   == Registered application 'StopMusicOnHold'
[Feb 28 22:03:33] VERBOSE[31785] loader.c:  res_musiconhold.so => (Music On Hold Resource)
[Feb 28 22:03:33] VERBOSE[31785] rtp_engine.c:   == Registered RTP engine 'multicast'
[Feb 28 22:03:33] VERBOSE[31785] loader.c:  res_rtp_multicast.so => (Multicast RTP Engine)

-Vladimir


By: Vladimir Mikhelson (vmikhelson) 2011-03-01 01:14:40.000-0600

Preloaded res_musiconhold.so in modules.conf.

That resolved the issue.  So far I do not see any adverse effects.

I still think it is a work around, not a true solution.

-Vladimir
By: Vladimir Mikhelson (vmikhelson) 2011-03-01 01:23:19.000-0600

Issue # 18884 is definitely related.

https://issues.asterisk.org/view.php?id=18884


By: Vladimir Mikhelson (vmikhelson) 2011-03-02 21:25:30.000-0600

Preloading is not a panacea. A simple "moh reload" places res_musiconhold.so after the res_timing_dahdi.so and the music stops right there...

res_timing_dahdi.so is referenced 8 times in my environment so unloading it in the middle of the game is quite unpractical.

Just confirming.
By: Vladimir Mikhelson (vmikhelson) 2011-03-02 22:32:18.000-0600

Another observation.

If somebody listens to MOH at the time "moh reload" is issued their MOH does not stop.  All new MOH sessions will deliver dead air.

The following messages will show up in the log after the initial MOH session stops.
res_musiconhold.c: killing 22076!
res_musiconhold.c: mpg123 pid 22076 and child died after 64560 bytes read
By: Vladimir Mikhelson (vmikhelson) 2011-04-14 10:30:43

A quick update.

No change as of 1.8.3.3 + DAHDI 2.4.1.2.

https://issues.asterisk.org/view.php?id=18877 is related but closed with no research or remedy.
By: Luke H (luckman212) 2011-04-20 10:52:06

Is this still an issue in the latest SVN or 1.8.4rc2 ?  anyone tested?  This issue is a real bugger
By: Luke H (luckman212) 2011-04-20 17:00:28

Well I just compiled SVN 1.8.314417M and wanted to report, this is still broken.
By: Vladimir Mikhelson (vmikhelson) 2011-04-26 16:05:59

russel,

There seems to be a typo in the relationship you have added, "related to 0018887"

It should have been 0018877 I would think.

Going to 0018887 produces "Access Denied."

-Vladimir


By: Vladimir Mikhelson (vmikhelson) 2011-05-15 16:06:26

Just in case it helps somebody to figure out what goes wrong.

Figure 1.
Asterisk loaded first time, MOH is idle. res_timing_dahdi.so use count is 1.
pbx*CLI> module show like timing
Module                         Description                              Use Count
res_timing_pthread.so          pthread Timing Interface                 0
res_timing_dahdi.so            DAHDI Timing Interface                   1
2 modules loaded

Figure 2.
Asterisk loaded first time, MOH is active, i.e playing.  res_timing_dahdi.so use count is 2.
pbx*CLI> module show like timing
Module                         Description                              Use Count
res_timing_pthread.so          pthread Timing Interface                 0
res_timing_dahdi.so            DAHDI Timing Interface                   2
2 modules loaded

Figure 3.
Asterisk reloaded with "core reload", MOH is idle. res_timing_dahdi.so use count is 2.
pbx*CLI> module show like timing
Module                         Description                              Use Count
res_timing_pthread.so          pthread Timing Interface                 0
res_timing_dahdi.so            DAHDI Timing Interface                   2
2 modules loaded

Figure 4.
Asterisk reloaded with "core reload", MOH is active, i.e playing.  res_timing_dahdi.so use count is 3.
pbx*CLI> module show like timing
Module                         Description                              Use Count
res_timing_pthread.so          pthread Timing Interface                 0
res_timing_dahdi.so            DAHDI Timing Interface                   3
2 modules loaded

It looks like there maybe some thread stuck in res_timing_dahdi.

-Vladimir

BTW, Asterisk is now 1.8.4, DAHDI 2.4.1.2.
By: Vladimir Mikhelson (vmikhelson) 2011-06-04 15:18:22

Patch for issue 0018028 does not fix the problem.

-Vladimir
By: Vladimir Mikhelson (vmikhelson) 2011-06-04 17:19:01

I am still to look more into it, but I experienced 7 consequent Asterisk seg faults after applying the patch.

[root@pbx]# /usr/sbin/safe_asterisk: line 145: 14975 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
/usr/sbin/safe_asterisk: line 145: 15115 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
/usr/sbin/safe_asterisk: line 145: 15231 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
/usr/sbin/safe_asterisk: line 145: 15345 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
/usr/sbin/safe_asterisk: line 145: 15453 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
/usr/sbin/safe_asterisk: line 145: 15561 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
/usr/sbin/safe_asterisk: line 145: 15673 Segmentation fault (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.


By: Vladimir Mikhelson (vmikhelson) 2011-06-05 00:34:52

Backtrace.txt and gdb.txt collected from the last (7th) core dump are uploaded.
By: Luke H (luckman212) 2011-09-08 12:34:41.946-0500

Can we get this issue merged with ASTERISK-17474?  same bug.
https://issues.asterisk.org/jira/browse/ASTERISK-17474
By: Vladimir Mikhelson (vmikhelson) 2012-01-30 23:46:42.335-0600

The issue seems to be resolved in 1.8.9.0.  "preload => musiconhold.so" should be removed in /etc/asterisk/modules.conf otherwise just default music will play till first "moh relaod" is issued.

Now we see something like the following:

pbx*CLI> module show like res_tim
Module                         Description                              Use Count
res_timing_pthread.so          pthread Timing Interface                 0
res_timing_dahdi.so            DAHDI Timing Interface                   2
2 modules loaded
pbx*CLI> moh reload
 == Parsing '/etc/asterisk/musiconhold.conf':   == Found
 == Parsing '/etc/asterisk/musiconhold_custom.conf':   == Found
 == Parsing '/etc/asterisk/musiconhold_additional.conf':   == Found
[Jan 30 23:17:20] DEBUG[7308]: res_musiconhold.c:1587 moh_class_destructor: killing 7385!
[Jan 30 23:17:20] DEBUG[7308]: res_musiconhold.c:1621 moh_class_destructor: mpg123 pid 7385 and child died after 57898 bytes read
pbx*CLI> module show like res_tim
Module                         Description                              Use Count
res_timing_pthread.so          pthread Timing Interface                 0
res_timing_dahdi.so            DAHDI Timing Interface                   2
2 modules loaded


res_timing_dahdi use count does not go up probably because the moh_class_destructor now kicks in.

Thank you for fixing this old, old bug.

-Vladimir



By: Vladimir Mikhelson (vmikhelson) 2012-01-30 23:48:27.616-0600

Fixed in 1.8.9.0.