Summary:	ASTERISK-26774: core: Playback URL fails after some time
Reporter:	Igor Gamayunov (gii)	Labels:
Date Opened:	2017-02-07 10:28:29.000-0600	Date Closed:	2017-03-01 04:48:42.000-0600
Priority:	Minor	Regression?	No
Status:	Closed/Complete	Components:	Applications/app_playback
Versions:	14.2.1	Frequency of Occurrence	Constant
Related Issues:
Environment:	Amazon Linux AMI release 2016.09	Attachments:	( 0) http_playback_failed_full.log
Description:	We have a custom greeting server which runs a dial plan context to  Playback a URL based greeting files to customers before redirecting calls elsewhere. We see consistently that after couple of hundreds  successful playbacks the Playback application starts failing. Basically, we have to restart the asterisk to recover. We are sure that the files at URL are valid and accessible all the time, because when we see errors we can do 'wget' of the file from the same server without any issues and only way to get back playback is to restart asterisk The following log  entrees show normal playbacks: {noformat} pbx.c: Executing [NNNNNNN@DDDDD:5] Playback("PJSIP/TTT-00000000", "silence/1&https://s3-us-west-1.amazonaws.com/xx/yyy.wav") in new stack file.c: <PJSIP/TTT-00000000> Playing 'silence/1.gsm' (language 'en') file.c: <PJSIP/trk_conf-000006ab> Playing 'https://s3-us-west-1.amazonaws.com/xx/yyy.wa.slin' (language 'en') {noformat} The following  log entries show when it starts failing: {noformat} pbx.c: Executing [NNNNNNN@DDDDD:5] Playback("PJSIP/TTT-00000000", "silence/1&https://s3-us-west-1.amazonaws.com/xx/yyy.wav") in new stack file.c: <PJSIP/TTT-00000000> Playing 'silence/1.gsm' (language 'en') file.c: File https://s3-us-west-1.amazonaws.com/xx/yyy.wav does not exist in any format file.c: Unable to open https://s3-us-west-1.amazonaws.com/xx/yyy.wav (format (ulaw|gsm)): No such file or directory app_playback.c: Playback failed on PJSIP/TTT-00000000 for silence/1&https://s3-us-west-1.amazonaws.com/xx/yyy.wav {noformat} This happens to all Asterisk 14 version since we discovered it can play URLs.
Comments:	By: Asterisk Team (asteriskteam) 2017-02-07 10:28:29.717-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. 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]. By: Joshua C. Colp (jcolp) 2017-02-08 09:52:24.979-0600 Thank you for taking the time to report this bug and helping to make Asterisk better. Unfortunately, we cannot work on this bug because your description did not include enough information. Please read over the Asterisk Issue Guidelines [1] which discusses the information necessary for your issue to be resolved and the format that information needs to be in. We would be grateful if you would then provide a more complete description of the problem. At a minimum, we need: 1. The specific steps or actions you took that caused you to encounter the problem. 2. The behavior you expected and the location of documentation that led you to that expectation. 3. The behavior you actually encountered. To demonstrate the issue in detail, please include Asterisk log files generated per the instructions on the wiki [2]. If applicable, please ensure that protocol-level trace debugging is enabled, e.g., 'sip set debug on' if the issue involves chan_sip, and configuration information such as dialplan and channel configuration. Thanks! [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines [2] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information By: Igor Gamayunov (gii) 2017-02-11 09:14:27.668-0600 We had followed the guidelines to collect the required debug information, however that action, somehow, made the issue diapered. We do not see any issues for two days, this probably mitigated the problem and it might appear later, so we are waiting. By: Igor Gamayunov (gii) 2017-02-23 07:19:38.285-0600 I have uploaded the required log level file without protocol-level trace since I believe it is not involved in the issue. This log shows playbacks started failing at some point. You can follow one sample  *8773190376@redirect*   starting from the *Feb 20 16:05:39* time stamp which was successfully played the greeting file +customer/63601/greeting.wav+  and then take a look  at the log entries starting from *Feb 20 16:23:14* time stamp. Media cache module assumes using _/tmp/bucket-AF2Ool_ cached local file and fails to read it because this file IS NOT EXIST ANYMORE since it was DELETED by the system tmpwatch cron application. It seems that the code does not check if the file exist and just trying to open it. I think that the issues caused by situation when a cached media bucket file has been deleted and the Playback media cache modules fails to verify if the file is exist. _It is very easy  to reproduce the failure by simply removing the corresponding cached file  */tmp/bucket-xxx* after the first successful playback._ # Here are steps and our dial plan - Call comes in - Retrieves a greeting file URL and a destination IP address to direct the call from a database table - Playback(URL) - Redirect call to a conference server {noformat} [redirect] exten => _X.,1,Answer same => n,Set(TDID=1110)    ; set the common part of the transfer number same => n,Set(ARRAY(GFILE,IPAddress)=${ODBC_CGRET_SQL(SELECT ... where DID='${EXTEN}')}) same => n,GotoIf($[!${EXISTS(${IPAddress})}]?error) same => n,Playback(silence/1&${GFILE}) ; play greeting same => n,ExecIf($["${PLAYBACKSTATUS}" != "SUCCESS"]?Playback(silence/1&${DFILE})) same => n,Dial(PJSIP/trk_conf/sip:${TDID}-${EXTEN}@${IPAddress},30,g) same => n,Hangup same => n(error),Playback(has-been-disconnected) same => n,Hangup {noformat} # https://wiki.asterisk.org/wiki/display/AST/Asterisk+14+Project+-+URI+Media+Playback # Playback starts failing after some time By: Igor Gamayunov (gii) 2017-02-23 07:20:29.739-0600 Log file By: Friendly Automation (friendly-automation) 2017-03-01 04:48:44.945-0600 Change 5107 merged by Joshua Colp: media_cache: Mark cache entry stale if cache file is removed [https://gerrit.asterisk.org/5107|https://gerrit.asterisk.org/5107] By: Friendly Automation (friendly-automation) 2017-03-01 04:49:01.990-0600 Change 5108 merged by Joshua Colp: media_cache: Mark cache entry stale if cache file is removed [https://gerrit.asterisk.org/5108|https://gerrit.asterisk.org/5108]