[asterisk-bugs] [Asterisk 0016305]: [patch] ExternalIVR confuses AGI by double closing FDs
Asterisk Bug Tracker
noreply at bugs.digium.com
Wed Dec 2 16:25:01 CST 2009
A NOTE has been added to this issue.
======================================================================
https://issues.asterisk.org/view.php?id=16305
======================================================================
Reported By: diLLec
Assigned To: thedavidfactor
======================================================================
Project: Asterisk
Issue ID: 16305
Category: Applications/app_externalivr
Reproducibility: always
Severity: major
Priority: normal
Status: ready for review
Asterisk Version: 1.6.1.10
JIRA:
Regression: No
Reviewboard Link:
SVN Branch (only for SVN checkouts, not tarball releases): 1.6.1
SVN Revision (number only!):
Request Review:
======================================================================
Date Submitted: 2009-11-22 10:38 CST
Last Modified: 2009-12-02 16:24 CST
======================================================================
Summary: [patch] ExternalIVR confuses AGI by double closing
FDs
Description:
By putting a asterisk system on higher load (15 Calls per Second) as normal
curios effects are arrising when using AGI and ExternalIVR together.
For getting into the issue I've added some extensive output to the code
which mainly concentrates on when and which fd is opened, closed and used.
Further our AGI/ExternalIVR scripts use timeouts while reading from STDIN.
Their log messages are the reason why I've started investigating on it.
1.) AGI suddenly can't write to the FD of the pipe which is connected to
the agi scripts STDIN (in parantheses after ast_agi_send you can see the fd
which is used for writing)
[2009-11-22 16:02:48.004] WARNING[18107] res_agi.c: 003_Agi opened pipes:
toast 0=38 1=106 | fromast 0=199 1=363 | errno=0
[2009-11-22 16:02:48.007] WARNING[18107] res_agi.c: ast_agi_send(363) >>
agi_request: init-call.php
[2009-11-22 16:02:48.007] ERROR[18107] utils.c: write() returned error:
Bad file descriptor
[2009-11-22 16:02:48.007] WARNING[18107] res_agi.c: ast_agi_send(363) >>
agi_channel: SIP/sipp-ae747388
[2009-11-22 16:02:48.007] ERROR[18107] utils.c: write() returned error:
Bad file descriptor
[2009-11-22 16:02:48.007] WARNING[18107] res_agi.c: ast_agi_send(363) >>
agi_language: de
[2009-11-22 16:02:48.007] ERROR[18107] utils.c: write() returned error:
Bad file descriptor
2.) ExternalIVR script reads content from another AGI process (log
messages of our externalivr script):
17:02:48 22.11.2009 | uid=1258905766.2546 chan=SIP/sipp-b00f88a8 |
ExternalIVR: Command: S,/home/voice/cgm53stage2/6000/1/Ansage_RP1
17:02:48 22.11.2009 | uid=1258905766.2546 chan=SIP/sipp-b00f88a8 |
ExternalIVR: 'T,1258905768'
17:02:50 22.11.2009 | uid=1258905766.2546 chan=SIP/sipp-b00f88a8 |
ExternalIVR: '200 result=1'
17:02:50 22.11.2009 | uid=1258905766.2546 chan=SIP/sipp-b00f88a8 |
ExternalIVR: DTMF Digit: 200 result=1
17:02:50 22.11.2009 | uid=1258905766.2546 chan=SIP/sipp-b00f88a8 |
ExternalIVR: '200 result=1'
17:02:50 22.11.2009 | uid=1258905766.2546 chan=SIP/sipp-b00f88a8 |
ExternalIVR: DTMF Digit: 200 result=1
3.) ExternalIVR can't write/read from the FDs of the pipes which are
connected to the externalivr script:
[2009-11-22 16:02:53.520] WARNING[18047] app_externalivr.c: ExternalIVR:
sending command 'G,1258905773,sys_context=6000_1' chan_state=6
[2009-11-22 16:02:53.520] WARNING[18047] app_externalivr.c: ExternalIVR:
fprintf on handle 0xae7a8738 failed with error Bad file descriptor (9),
chan state=6
First it came to my mind, that the kernel may has a synchronization bug
while handing out FDs for the pipes:
AGI opened FDs:
[2009-11-22 16:02:48.004] WARNING[18107] res_agi.c: 003_Agi opened pipes:
toast 0=38 1=106 | fromast 0=199 1=363 | errno=0
ExternalIVR opened FDs
[2009-11-22 16:02:48.026] WARNING[18047] app_externalivr.c: Pipes created
child_stdin 0=199 1=363 | child_stdout 0=484 1=489 | child_stderr 0=491
1=49
I was able to negative this thoguht by using a systemtap script (see
attachements) which shows that everytime a pipe is created it is always
based on formerly closed fds - so kernel was right:
Sun Nov 22 16:02:48 2009 (ms=4) process asterisk[30094][18107]: pipe
opened: 0=[199, 363]
Sun Nov 22 16:02:48 2009 (ms=4) process asterisk[30094][17731]: fd closed:
363
Sun Nov 22 16:02:48 2009 (ms=11) process asterisk[30094][17731]: pipe
opened: 0=[363, 478]
But, the log also showed that while one thread of a process gets the FD by
a pipe, another thread (17731) of the process is closing it:
Sun Nov 22 16:02:48 2009 (ms=14) process asterisk[30094][17731]: fd
closed: 363
Sun Nov 22 16:02:48 2009 (ms=26) process asterisk[30094][18047]: pipe
opened: 0=[199, 363]
And thats it - thread 17731 was running ExternalIVR, which closes the FDs
first in eivr_comm() by fclose (line 785) and a second time in app_exec()
(line=495) by close().
The patch in the attachments passes the FDs by reference and assigns them
0 after fclose has finished. With that close() in app_exec() is not called.
======================================================================
----------------------------------------------------------------------
(0114601) svnbot (reporter) - 2009-12-02 16:24
https://issues.asterisk.org/view.php?id=16305#c114601
----------------------------------------------------------------------
Repository: asterisk
Revision: 232587
U trunk/apps/app_externalivr.c
------------------------------------------------------------------------
r232587 | diruggles | 2009-12-02 16:24:58 -0600 (Wed, 02 Dec 2009) | 12
lines
Prevent double closing of FDs by EIVR
This caused a problem when asterisk was under heavy load and running both
AGI and EIVR applications.
EIVR would close an FD at which point it would be considered freed and be
used by a new AGI instance
the second close would then close the FD now in use by AGI.
(closes issue https://issues.asterisk.org/view.php?id=16305)
Reported by: diLLec
Tested by: thedavidfactor, diLLec
Review: https://reviewboard.asterisk.org/r/436/
------------------------------------------------------------------------
http://svn.digium.com/view/asterisk?view=rev&revision=232587
Issue History
Date Modified Username Field Change
======================================================================
2009-12-02 16:25 svnbot Note Added: 0114601
======================================================================
More information about the asterisk-bugs
mailing list