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 | ||
Priority: | Major | Regression? | No | ||
Status: | Closed/Complete | Components: | PBX/pbx_spool | ||
Versions: | SVN 11.6.0 11.7.0 12.0.0-beta1 | Frequency of Occurrence | Constant | ||
Related Issues: |
| ||||
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!!!! |