|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-0600||Date Closed:||2016-09-23 14:25:20|
|Versions:||SVN 11.6.0 11.7.0 12.0.0-beta1||Frequency of|
|Environment:||Attachments:||( 0) callfile.txt|
( 1) extensions.conf
( 2) sip.conf
|Description:||if you make a callfile with |
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:
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"'
****** 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
cp tmp/callfile.txt tmp/143.call
mv tmp/143.call outgoing/
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.
cat <<__EOC__ > /var/spool/asterisk/tmp/mycall.tmp
mv /var/spool/asterisk/tmp/mycall.tmp /var/spool/asterisk/outgoing/mycall
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:
cat <<__EOC__ > /var/spool/asterisk/tmp/timetest.tmp
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
touch -cm -t `date +'%Y%m%d%H%S'` /var/spool/asterisk/outgoing/timetest
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 188.8.131.52
Here is the 'timestamp' log
The callfile options is
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
call 4 (last) end 21:43:06
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!!!!