[Home]

Summary:ASTERISK-17069: Callfile retries behave erratically as file size grows
Reporter:Jeremy Kister (jkister)Labels:
Date Opened:2010-12-05 11:33:18.000-0600Date Closed:2016-09-23 14:25:20
Priority:MajorRegression?No
Status:Closed/CompleteComponents:PBX/pbx_spool
Versions:SVN 11.6.0 11.7.0 12.0.0-beta1 Frequency of
Occurrence		Constant
Related
Issues:
is duplicated byASTERISK-22787 Call file RetryTime not respected after several retries
Environment:Attachments:( 0) callfile.txt
( 1) extensions.conf
( 2) sip.conf
Description:if you make a callfile with
MaxRetries: 5
RetryTime: 420

the pbx does not reschedule the retry in 420 seconds - instead, it is much sooner, sometimes even immediately.

the call file itself is modified by the pbx:
Channel: Local/121@extensions
Callerid: 121
MaxRetries: 15
RetryTime: 420
WaitTime: 60
Context: alarm-ack
Extension: s
Priority: 1

StartRetry: 4419 1 (1291569420)

EndRetry: 4419 1 (1291569037)

StartRetry: 4419 2 (1291569481)

EndRetry: 4419 2 (1291569099)

StartRetry: 4419 3 (1291569840)

DelayedRetry: 4419 2 (1291569457)

EndRetry: 4419 3 (1291569457)

StartRetry: 4419 4 (1291569901)

but those epochs are actually *in the future*.  for example, the last "StartRetry 1291569901" was printed appended to the file 380 seconds in the future:

pbx1> perl -e 'print "$^T\n"'
1291569521


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

it seems the scheduler has some sanity, as 380 seconds into the future + the 60 second WaitTime = 420 = RetryTime.  but something is confusing the clock.
Comments:By: Jeremy Kister (jkister) 2011-01-03 15:38:57.000-0600

put callfile.txt in /var/spool/asterisk/tmp

use provided extensions.conf, etc

{code}
cd /var/spool/asterisk
cp tmp/callfile.txt tmp/143.call
mv tmp/143.call outgoing/
{code}

answer the call, hang up rather quickly.

the next call should not arrive until Jan 1, 2015, but instead is processed within seconds (or a few minutes).
By: Jeremy Kister (jkister) 2011-01-03 15:39:54.000-0600

It seems this problem is related to keeping the call file and Channel identical.  if I change the callfile name to 143.$$.call ($$ being the PID), i can not replicate the broken behavior.
By: Jeremy Kister (jkister) 2011-01-03 15:41:05.000-0600

I realize I made a mistake in the [extensions] context (1XX vs _1XX, but it doesnt matter anyway)
By: Ishtiyaq Husain (ishtiyaq) 2013-02-22 14:39:20.038-0600

i am facing same problem, plz some resolve this problem.
By: Rusty Newton (rnewton) 2013-11-13 09:15:36.208-0600

Duplicate in ASTERISK-22787. Still occurs in 11.7.1 and SVN of 12.
By: Jeremy Kister (jkister) 2013-11-16 22:43:04.257-0600

another problem is when the file is larger than 512 (sometimes 1024?) bytes, Asterisk gets confused and retries immediately/randomly instead of at the specified RetryTime.

to reproduce:
{noformat}
cat <<__EOC__ > /var/spool/asterisk/tmp/mycall.tmp
Channel: Local/9999@extensions
Callerid: 1234
MaxRetries: 25
RetryTime: 60
WaitTime: 60
Context: alarm-ack
Extension: s
Priority: 1
__EOC__

mv /var/spool/asterisk/tmp/mycall.tmp /var/spool/asterisk/outgoing/mycall
{noformat}

Do not answer the call when it comes in. Instead, use 'ls -l /var/spool/asterisk/outgoing/mycall' after Asterisk stops ringing the extension.

Asterisk will use pbx/pbx_spool:safe_append to append to the file (in place).  Let this repeat for a few times, until the file is larger than 512 (sometimes 1024?) bytes.  Asterisk gets confused and retries immediately/randomly instead of at the specified RetryTime.

I believe this is because files written in the pbx spool must be done atomically.  

By: Jeremy Kister (jkister) 2013-11-16 22:52:17.204-0600

another similar/related issue:

{noformat}
cat <<__EOC__ > /var/spool/asterisk/tmp/timetest.tmp
Channel: Local/9999@extensions
Context: alarm-ack
Extension: s
Priority: 1
__EOC__

touch -cm -t `date --date="5min" +'%Y%m%d%H%S'` /var/spool/asterisk/tmp/timetest.tmp
mv /var/spool/asterisk/tmp/timetest.tmp /var/spool/asterisk/outgoing/timetest
sleep 5
touch -cm -t `date +'%Y%m%d%H%S'` /var/spool/asterisk/outgoing/timetest
{noformat}

I would expect the call to come in rather immediately.  But after Asterisk knows something about the callfile (in this case, to schedule it for 5 min in the future), it doesn't seem to respect changes to the mtime.
By: newborn (newborn838) 2014-07-17 13:19:28.435-0500

The same broblem is in Asterisk 1.8.21.0

Here is the 'timestamp' log

The callfile options is
Context: calltest-external_office-answered
Extension: s
Priority: 1
MaxRetries: 3
RetryTime: 90
WaitTime: 30

call1 (initial) start 21:39:28
call1 (initial) end 21:39:43

call2 start 21:40:58
call2 end 21:41:20

call3 start 21:42:28
call3 end 21:42:50

call 4 (last) start -notice the time! 21:42:50
21:43:01
call 4 (last) end 21:43:06

Retry:

call1 (initial) start 21:52:43
call1 (initial) end 21:52:58

call2 start 21:54:13
call2 end 21:54:37

call3 start 21:55:44
call3 end 21:55:58

call 4 (last) start -notice the time!21:56:07
call 4 (last) end 21:56:21

note that the 4th call (3rd attempt) counts from call2 end in both cases.
it's a BUG!!!!