[Home]

Summary:ASTERISK-24442: Outgoing call files don't work properly when set in the future
Reporter:tootai (tootai)Labels:
Date Opened:2014-10-20 05:01:09Date Closed:2015-05-17 13:50:19
Priority:MinorRegression?Yes
Status:Closed/CompleteComponents:Core/PBX
Versions:SVN 1.8.31.0 11.13.1 12.6.1 13.0.0-beta3 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Linux VM Debian Wheezy. Asterisk compiled from source. Asterisk running as user root. Problem is the same with stock Debian version 1:1.8.13.1~dfsg1-3+deb7u3 running as Asterisk user.Attachments:( 0) issue2442.log
Description:Call file:
{noformat}
Channel: SIP/<peer>/<number>
Application: Playback
Data: hello-world
{noformat}

Now is 20141020, 11:42am
touch -t 1410201146 hello-world.call ;4 min in the future
sudo mv hello-world.call /var/spool/asterisk/outgoing/

Call is started at 11h46, all is good

Now is 20141020, 11:54am
touch -t 1410201201 hello-world.call ;7 min in the future
sudo mv hello-world.call /var/spool/asterisk/outgoing/

Call is started at 11:56

From various test we made, under 5min in the future it's OK, 6 min also. I know that with 5 , 10, 30 and 35 min in the future it's not OK
Comments:By: Matt Jordan (mjordan) 2014-10-20 11:36:07.465-0500

We require a complete debug log to help triage the issue. This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information


By: tootai (tootai) 2014-10-20 16:06:12.343-0500

Date was 14/10/20 at 22h46m, call file "touch -t 1410202252 hello-world.call" + mv to outgoing directory.  The debug level is 5 as well as verbose one.

logger.conf

messages => warning,error,verbose,dtmf                                                                                                                                        
notice=notice                                                                                                                                                                
debug=warning,error,debug

From message log file:

[2014-10-20 22:47:00] VERBOSE[25908] pbx_spool.c:     -- Attempting call on SIP/xxxxxx/yyyyyyyyyy for application Playback(hello-world) (Retry 1)
[2014-10-20 22:47:00] VERBOSE[25908] netsock2.c:   == Using SIP VIDEO TOS bits 136
[2014-10-20 22:47:00] VERBOSE[25908] netsock2.c:   == Using SIP VIDEO CoS mark 4
[2014-10-20 22:47:00] VERBOSE[25908] netsock2.c:   == Using SIP RTP TOS bits 184
[2014-10-20 22:47:00] VERBOSE[25908] netsock2.c:   == Using SIP RTP CoS mark 5
[2014-10-20 22:47:15] VERBOSE[25908] pbx.c:        > Channel SIP/xxxxxx-00000938 was answered.
[2014-10-20 22:47:15] VERBOSE[25908] pbx.c:        > Launching Playback(hello-world) on SIP/101742-00000938
[2014-10-20 22:47:15] VERBOSE[25908] file.c:     -- <SIP/xxxxxx-00000938> Playing 'hello-world.gsm' (language 'fr')  

From notice log file:

[2014-10-20 22:47:16] NOTICE[25908] pbx_spool.c: Call completed to SIP/xxxxxx/yyyyyyyyyy

From debug log file:

[2014-10-20 22:47:00] DEBUG[2759] pbx_spool.c: Filename: /var/spool/asterisk/outgoing/hello-world.call, Retries: 0, max: 0
[2014-10-20 22:47:00] DEBUG[2759] pbx_spool.c: Outgoing SIP/101742/0684903404: StartRetry


By: tootai (tootai) 2014-10-21 05:44:08.976-0500

Tried with asterisk11: problem is also there, but a different timing: for instance, a future call of +5min is launched at +3min

By: Matt Jordan (mjordan) 2014-10-28 11:19:58.402-0500

That's not a debug log.

Please provide the information requested so we can diagnose and determine the cause of the issue.
By: tootai (tootai) 2014-10-28 12:40:01.195-0500

Call file created on 20141028 18h25 then

touch -t 1410281846 hello-world.call ;20 min delay
sudo mv hello-world.call /var/spool/asterisk/outgoing/ ;done at 18h26

Call started at 18h29
By: tootai (tootai) 2014-10-28 12:41:04.181-0500

Debug file sended, done on our test asterisk 11.13.1 version
By: Rusty Newton (rnewton) 2014-11-04 11:32:13.868-0600

Yeah there is weirdness here in 13 as well. Pretty easy to reproduce. I tried a variety of times and got behavior all over the place. For example, setting a file with a timestamp 10 minutes away resulted in the file being played after about 4 minutes. Setting a file with a timestamp of 5 minutes away resulted in the file being played in 5 minutes.
By: Rusty Newton (rnewton) 2015-05-17 13:50:20.048-0500

Closing, as a fix was already merged. Auto-close of JIRA issues is failing at the moment.