[Home]

Summary:ASTERISK-29879: res_musiconhold: Music on hold restarts after positon announcement
Reporter:ben kolodny (benphone)Labels:
Date Opened:2022-01-24 11:37:31.000-0600Date Closed:2022-02-07 12:11:53.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Resources/res_musiconhold
Versions:18.9.0 Frequency of
Occurrence		Constant
Related
Issues:
is related toASTERISK-27774 res_musiconhold: Music on hold restarts after every announcement
Environment:centos 7 real time queue Attachments:( 0) DEBUG_on1.txt
( 1) music_on_hold.txt
( 2) new_13_1.txt
( 3) queue_configure.txt
Description:{quote}
In /ext/moh/82497 are one or more audio files with a length of around 3 minutes. If a queue is configured with a periodic announcement every 30 seconds, the following will occur:

   Caller hears music on hold file #1, playing from the beginning
   After 30 seconds, the caller will hear the announcement
   Caller hears music on hold file #1, playing from the beginning
   After 30 seconds, the caller will hear the announcement
   ...

E.g., if the periodic announcement is made every 30 seconds the caller will only ever hear the first 30 seconds of music on hold over and over again.
{quote}

above is a quote from ASTERISK-27774

i seem to have the same problem with version 18.9.0 but it after playing the thank you message when Announce position: is set to yes
(the code that was fixed checks just announcement maybe position is treated differently?)
any tips would be appreciated

{noformat}
VERBOSE[2643] app_queue.c: Nobody picked up in 20000 ms
VERBOSE[2643] res_musiconhold.c: Stopped music on hold on PJSIP/fs2-00036104
VERBOSE[2643] file.c: <PJSIP/fs2-00036104> Playing 'pbx/188d949a5b9bbde4553ef85f252d8ddf.slin' (language 'he')
VERBOSE[2643] app_queue.c: Told PJSIP/fs2-00036104 in 1507 their queue position (which was 1)
VERBOSE[2643] file.c: <PJSIP/fs2-00036104> Playing 'queue-thankyou.gsm' (language 'he')
VERBOSE[2643] res_musiconhold.c: Started music on hold, class '1435', on channel 'PJSIP/fs2-00036104'
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2022-01-24 11:37:31.627-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Joshua C. Colp (jcolp) 2022-01-24 11:52:50.251-0600

We require additional debug to continue with triage of your issue. Please follow the instructions on the wiki [1] for how to collect debugging information from Asterisk. For expediency, where possible, attach the debug with a '.txt' file extension so that the debug will be usable for further analysis. Please also provide the complete configuration information for app_queue.

Thanks!

[1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information


By: ben kolodny (benphone) 2022-02-06 03:48:17.741-0600

queue configure.txt
By: ben kolodny (benphone) 2022-02-06 07:38:52.687-0600

debug
By: Joshua C. Colp (jcolp) 2022-02-06 07:46:10.521-0600

It does not appear as though you followed the linked instructions for getting debug information. The provided log contains only verbose messages.
By: ben kolodny (benphone) 2022-02-06 07:47:42.844-0600

i have uploaded some more info please check if  more info is needed (tried making empty lines before  should be easy to read !

{code:title=log|borderStyle=solid}
Line 313: [2022-01-31 12:59:18] VERBOSE[20005][C-00000a1b] pbx.c: Executing [900@authenticated:220] Set("PJSIP/200-0000003f", "CHANNEL(musicclass)=457") in new stack

Line 943: [2022-01-31 12:59:18] VERBOSE[20005][C-00000a1b] res_musiconhold.c: Started music on hold, class '457', on channel 'PJSIP/200-0000003f'

Line 4325: [2022-01-31 12:59:39] VERBOSE[20005][C-00000a1b] res_musiconhold.c: Stopped music on hold on PJSIP/200-0000003f
Line 4326: [2022-01-31 12:59:39] VERBOSE[20005][C-00000a1b] file.c: <PJSIP/200-0000003f> Playing 'queue-youarenext.gsm' (language 'he')
Line 4383: [2022-01-31 12:59:44] VERBOSE[20005][C-00000a1b] app_queue.c: Told PJSIP/200-0000003f in 9 their queue position (which was 1)
Line 4384: [2022-01-31 12:59:44] VERBOSE[20005][C-00000a1b] file.c: <PJSIP/200-0000003f> Playing 'queue-thankyou.gsm' (language 'he')
Line 4399: [2022-01-31 12:59:46] VERBOSE[20005][C-00000a1b] res_musiconhold.c: Started music on hold, class '457', on channel 'PJSIP/200-0000003f'
{code}
By: Joshua C. Colp (jcolp) 2022-02-06 07:50:41.549-0600

You should also provide the music on hold configuration as well alongside the debug.
By: Sean Bright (seanbright) 2022-02-06 15:40:58.927-0600

FWIW - I am not able to reproduce this on 16 with non-realtime MoH and non-realtime queues.
By: Sean Bright (seanbright) 2022-02-07 09:36:47.367-0600

[~benphone], we'll need [the debug information|https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information] that [~jcolp] already asked for, and your music on hold configuration as well as we are currently not able to reproduce this error on our end.
By: ben kolodny (benphone) 2022-02-07 11:46:57.108-0600

moh config
By: Joshua C. Colp (jcolp) 2022-02-07 11:53:57.635-0600

You're using an external custom stream player, Asterisk has no involvement in what that stream is providing or how it works. Within Asterisk the position is only maintained for file type.
By: ben kolodny (benphone) 2022-02-07 12:04:50.956-0600

{code:title=musicon hold debug|borderStyle=solid}



[2022-02-07 19:17:45] DEBUG[4565][C-00000e4d] pbx.c: Launching 'Return'
[2022-02-07 19:17:45] VERBOSE[4565][C-00000e4d] pbx.c: Executing [~~s~~@callEnd:48] Return("Local/AG-000-CC-538@fromotherpbx-00000d2c;2", "") in new stack
[2022-02-07 19:17:45] DEBUG[4565][C-00000e4d] channel.c: Channel 0x7fe64c0204b0 'Local/AG-000-CC-538@fromotherpbx-00000d2c;2' hanging up.  Refs: 3
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] autochan.c: Removed autochan 0x7fe67000a2e0 from the list, about to free it
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] channel.c: Channel 0x7fe64c0204b0 'Local/AG-000-CC-538@fromotherpbx-00000d2c;2' destroying
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] stasis.c: Destroying topic. name: channel:db02-1644254245.72706, detail:
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] stasis.c: Topic 'channel:db02-1644254245.72706': 0x7fe64c005610 destroyed
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] channel_internal_api.c:  <initializing>: MultistreamFormats: (nothing)
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] channel_internal_api.c:  Channel is being initialized or destroyed
[2022-02-07 19:17:45] VERBOSE[4568][C-00000e4d] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2022-02-07 19:17:45] VERBOSE[4568][C-00000e4d] app_mixmonitor.c: End MixMonitor Recording Local/AG-000-CC-538@fromotherpbx-00000d2c;2
[2022-02-07 19:17:45] DEBUG[4568][C-00000e4d] app_mixmonitor.c: No recipients to forward monitor to, moving on.
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_odbc.c: Reusing ODBC handle 0x296b430 from class 'asterisk1'
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM queue_member WHERE interface LIKE ? AND queue_name = ? ORDER BY interface
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%'
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_config_odbc.c: Parameter 2 ('queue_name') = '9'
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_odbc.c: Releasing ODBC handle 0x296b430 into pool
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] app_queue.c: There is 1 available member.
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] app_queue.c: It's our turn (SIP/oraclepbx-00000c08).
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_musiconhold.c: Destroying MOH class '457'
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_musiconhold.c: killing 4563!
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_musiconhold.c: Sent HUP to pid 4563 and all children
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_musiconhold.c: mpg123 pid 4563 and child died after 62592 bytes read
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] channel.c: Channel SIP/oraclepbx-00000c08 setting write format path: ulaw -> ulaw
[2022-02-07 19:17:46] VERBOSE[4560][C-00000e4d] res_musiconhold.c: Stopped music on hold on SIP/oraclepbx-00000c08
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] channel.c: Channel SIP/oraclepbx-00000c08 setting write format path: gsm -> ulaw
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] res_rtp_asterisk.c: (0x7fe7140f9b20) RTP audio difference is 768, ms is 116
[2022-02-07 19:17:46] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2022-02-07 19:17:46] VERBOSE[4560][C-00000e4d] file.c: <SIP/oraclepbx-00000c08> Playing 'queue-youarenext.gsm' (language 'he')
[2022-02-07 19:17:50] DEBUG[4560][C-00000e4d] res_rtp_asterisk.c: (0x7fe7140f9b20) RTCP got report of 100 bytes from XXX.X.XXX.XX:19717
[2022-02-07 19:17:51] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:51] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:51] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:51] DEBUG[4560][C-00000e4d] channel.c: Channel SIP/oraclepbx-00000c08 setting write format path: ulaw -> ulaw
[2022-02-07 19:17:51] VERBOSE[4560][C-00000e4d] app_queue.c: Told SIP/oraclepbx-00000c08 in 9 their queue position (which was 1)
[2022-02-07 19:17:51] DEBUG[4560][C-00000e4d] channel.c: Channel SIP/oraclepbx-00000c08 setting write format path: gsm -> ulaw
[2022-02-07 19:17:51] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2022-02-07 19:17:51] VERBOSE[4560][C-00000e4d] file.c: <SIP/oraclepbx-00000c08> Playing 'queue-thankyou.gsm' (language 'he')
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] channel.c: Channel SIP/oraclepbx-00000c08 setting write format path: ulaw -> ulaw
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] res_odbc.c: Reusing ODBC handle 0x296b430 from class 'asterisk1'
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM musiconhold WHERE name = ?
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] res_config_odbc.c: Parameter 1 ('name') = '457'
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] res_odbc.c: Releasing ODBC handle 0x296b430 into pool
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] channel.c: Channel SIP/oraclepbx-00000c08 setting write format path: slin -> ulaw
[2022-02-07 19:17:52] VERBOSE[4560][C-00000e4d] res_musiconhold.c: Started music on hold, class '457', on channel 'SIP/oraclepbx-00000c08'
[2022-02-07 19:17:52] DEBUG[4560][C-00000e4d] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second

{code}
{color:red}
 

also the music on hold apllication is using  custom mode

{color}
By: Asterisk Team (asteriskteam) 2022-02-07 12:09:01.797-0600

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Joshua C. Colp (jcolp) 2022-02-07 12:11:53.180-0600

This is not a bug. Asterisk does not maintain position for custom, it is only able to maintain it for file based