[Home]

Summary:ASTERISK-16764: [patch] Call files generate two warning logs after each successful completion
Reporter:abelbeck (abelbeck)Labels:
Date Opened:2010-10-04 10:52:12Date Closed:2010-11-10 17:14:47.000-0600
Priority:BlockerRegression?No
Status:Closed/CompleteComponents:PBX/pbx_spool
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20101021__issue18089.diff.txt
Description:Call files with 1.8-rc2 with Issue ASTERISK-16608 patch works for me.

The problem reported here are two warning logs that are generated for each successful call file.  (See Additional Information)

Each warning log occurs at "RetryTime" seconds after the call-file completion or previous warning log.

While these warnings seem harmless, it indicates the queue is maintaining multiple instances of the call file, (or inotify is generating them during the processing).

If HAVE_INOTIFY is undefined in pbx_spool.c, the problem goes away.


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

In "demo" context:
exten => 502,1,Answer                            
exten => 502,n,Hangup
       
Using call-file.txt:
--
Channel: Local/502@demo
Extension: s
Priority: 1
Callerid: 1111
MaxRetries: 0
RetryTime: 10
WaitTime: 50
--

$ mv call-file.txt /var/spool/asterisk/outgoing/

== Verbosity 5 console ==
   -- Attempting call on Local/502@demo for s@:1 (Retry 1)
   -- Executing [502@demo:1] Answer("Local/502@demo-0964;2", "") in new stack
      > Channel Local/502@demo-0964;1 was answered.
   -- Executing [s@demo:1] Wait("Local/502@demo-0964;1", "1") in new stack
   -- Executing [502@demo:2] Hangup("Local/502@demo-0964;2", "") in new stack
 == Spawn extension (demo, 502, 2) exited non-zero on 'Local/502@demo-0964;2'
 == Spawn extension (demo, s, 1) exited non-zero on 'Local/502@demo-0964;1'
[Oct  4 10:17:24] NOTICE[3402]: pbx_spool.c:357 attempt_thread: Call completed to Local/502@demo

[Oct  4 10:17:34] WARNING[3225]: pbx_spool.c:400 scan_service: Unable to open /var/spool/asterisk/outgoing/call-file.txt: No such file or directory, deleting

[Oct  4 10:17:44] WARNING[3225]: pbx_spool.c:400 scan_service: Unable to open /var/spool/asterisk/outgoing/call-file.txt: No such file or directory, deleting
==

HAVE_INOTIFY is defined in pbx_spool.c

Using Issue ASTERISK-16608 patch:
http://svnview.digium.com/svn/asterisk?revision=290066&view=revision

Related to Issue ASTERISK-16097 Reported description.
Comments:By: Leif Madsen (lmadsen) 2010-10-12 14:53:03

Let us know if you still have problems with 1.8.0-rc3 because this has been fixed in that version.

By: abelbeck (abelbeck) 2010-10-12 15:22:42

Sorry Leif, the problem still exists in 1.8.0-rc3, I just tested for sure.

This issue was based on 1.8.0-rc2 + 0017924 patch, which is basically rc3 in this scope.

By: Leif Madsen (lmadsen) 2010-10-13 12:46:54

Please actually test with RC3 and not just RC2 + a patch because that'll be more accurate of a test.

By: abelbeck (abelbeck) 2010-10-13 12:58:31

I tested 1.8.0-rc3, and the problem still exists.

By: Michael Keuter (mkeuter) 2010-10-13 15:17:20

I do also have the same problem with 1.8.0.rc3.

By: Digium Subversion (svnbot) 2010-10-18 10:32:41

Repository: asterisk
Revision: 292083

U   branches/1.8/pbx/pbx_spool.c

------------------------------------------------------------------------
r292083 | jpeeler | 2010-10-18 10:32:40 -0500 (Mon, 18 Oct 2010) | 4 lines

Disable use of inotify for call file handling as it is not working properly.

(related to ASTERISK-16764)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=292083

By: Digium Subversion (svnbot) 2010-10-18 10:33:36

Repository: asterisk
Revision: 292084

_U  trunk/
U   trunk/pbx/pbx_spool.c

------------------------------------------------------------------------
r292084 | jpeeler | 2010-10-18 10:33:35 -0500 (Mon, 18 Oct 2010) | 11 lines

Merged revisions 292083 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

........
 r292083 | jpeeler | 2010-10-18 10:32:40 -0500 (Mon, 18 Oct 2010) | 4 lines
 
 Disable use of inotify for call file handling as it is not working properly.
 
 (related to ASTERISK-16764)
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=292084

By: Tilghman Lesher (tilghman) 2010-10-21 17:16:58

Patch uploaded that solves the problem for me.  The issue was in the transition from IN_CREATE to IN_CLOSE_WRITE, it was ignored that we write several times to the callfile while it is in-queue.  When we wrote to the callfile, IN_CLOSE_WRITE forced the file to be requeued erroneously.  This has been fixed by requiring an IN_CREATE before IN_CLOSE_WRITE, such that subsequent writes are ignored.

By: Michael Keuter (mkeuter) 2010-10-23 05:22:55

@tilghman:

I just tested your patch in 1.8.0 final and now I again get the error, but this time only once after "RetryTime". Without your patch I get no warning (because inotify is disabled).

By: Digium Subversion (svnbot) 2010-11-10 17:13:39.000-0600

Repository: asterisk
Revision: 294569

U   branches/1.8/pbx/pbx_spool.c

------------------------------------------------------------------------
r294569 | tilghman | 2010-11-10 17:13:38 -0600 (Wed, 10 Nov 2010) | 8 lines

Properly queue files with inotify(7).

(closes issue ASTERISK-16764)
Reported by: abelbeck
Patches:
      20101021__issue18089.diff.txt uploaded by tilghman (license 14)
Tested by: tilghman

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=294569

By: Digium Subversion (svnbot) 2010-11-10 17:14:46.000-0600

Repository: asterisk
Revision: 294570

_U  trunk/
U   trunk/pbx/pbx_spool.c

------------------------------------------------------------------------
r294570 | tilghman | 2010-11-10 17:14:45 -0600 (Wed, 10 Nov 2010) | 15 lines

Merged revisions 294569 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

........
 r294569 | tilghman | 2010-11-10 17:13:37 -0600 (Wed, 10 Nov 2010) | 8 lines
 
 Properly queue files with inotify(7).
 
 (closes issue ASTERISK-16764)
  Reported by: abelbeck
  Patches:
        20101021__issue18089.diff.txt uploaded by tilghman (license 14)
  Tested by: tilghman
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=294570

By: David Woodhouse (dwmw2) 2011-08-26 09:26:34.502-0500

The use of IN_CLOSE_WRITE seems to have broken the smsq utility. It hard-links its call file into the queue directory, causing an IN_CREATE event. But there is no subsequent IN_CLOSE_WRITE because smsq is actually following the *rules* and not writing to the queue file in-place.

In https://issues.asterisk.org/jira/browse/ASTERISK-18331 I fix smsq to use rename() instead of link() followed by unlink(), but it concerns me that the queue management is now penalising *correct* behaviour in order to pander to broken users.

Or have the rules changed?