asterisk users - Feb 2011 - AGI script exits non-zero when running system command

Hey guys I was hoping I could get a few pointers on a problem I have been
trying to debug for the last couple of months regarding asterisk AGI scripts
and unexpected termination.
I have this agi script that accepts incoming faxes using RxFax on the latest
asterisk 1.4 branch. Its written with perl and it works fine except for one
line that causes the entire script to terminate unexpectedly.

The script always terminates at the point where I use the 'system'
command
or backticks to run a system command.
Example:
system( "/usr/bin/tiff2pdf -f -p letter -o $faxpath/$unique.pdf
$faxpath/$unique.tiff" );

The asterisk log with agi debugging on is pasted below

I have tried everything I can think of over the past few months, taking a
break every so often obviously, but now I feel like I really need outside
eyes.

Its worth noting that the script runs fine without running the system
command, and it does not matter which system command I run.  I tried just
doing a simple copy of the file and it failed in the same place.
Asterisk leaves me with little help, just explaining that the script
returned non-zero.

Are there any issues I should be aware of when running system commands from
an AGI script?  I did check permissions and made sure my asterisk user can
write to /tmp and use the converting commands.  I did a lot more testing of
course but that is probably the biggest face-palm error there could be.

Asterisk log:

    -- Launched AGI Script /var/lib/asterisk/agi-bin/fax.agi
AGI Tx >> agi_request: fax.agi
AGI Tx >> agi_channel: SIP/trunk-00000035
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1296624119.53
AGI Tx >> agi_callerid: anonymous
AGI Tx >> agi_calleridname: Anonymous
AGI Tx >> agi_callingpres: 32
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: XXXXXXXXXX
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: from-trunk
AGI Tx >> agi_extension: XXXXXXXXXX
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << GET VARIABLE EXTEN
AGI Tx >> 200 result=1 (XXXXXXXXXX)
AGI Rx << GET VARIABLE CALLERID(num)
AGI Tx >> 200 result=1 (anonymous)
AGI Rx << VERBOSE "DEBUG: EXTEN - XXXXXXXXXX CID - anonymous" 1
  fax.agi: DEBUG: EXTEN - XXXXXXXXXX CID - anonymous
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE UNIQUEID
AGI Tx >> 200 result=1 (1296624119.53)
AGI Rx << VERBOSE "RxFAX XXXXXXXXXX: /tmp/1296624119.53.tiff" 1
  fax.agi: RxFAX XXXXXXXXXX: /tmp/1296624119.53.tiff
AGI Tx >> 200 result=1
AGI Rx << EXEC RxFAX "/tmp/1296624119.53.tiff"
    -- AGI Script Executing Application: (RxFAX) Options:
(/tmp/1296624119.53.tiff)
Really destroying SIP dialog '6327EDB3 at XXX' Method: OPTIONS
[Feb  1 23:22:18] ERROR[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:214 phase_e_handler:
[FaxReceived ERROR] result (13) Unexpected message received.
 [FaxReceived ERROR] result (13) Unexpected message received.
[Feb  1 23:22:18] WARNING[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:478 fax_run: RXFAX:
t30_call_active is FALSE.
AGI Tx >> 200 result=0
AGI Rx << EXEC RxFAX "/tmp/1296624119.53.tiff"
    -- AGI Script Executing Application: (RxFAX) Options:
(/tmp/1296624119.53.tiff)
Really destroying SIP dialog '132f38cb284eef837df0038477511f55 at XXX'
Method:
OPTIONS
REGISTER attempt 1 to XXXXXXXXXX at trunk
Really destroying SIP dialog '33dff0b60f7ce29944351e446c2e7b5b at XXX'
Method:
REGISTER
Really destroying SIP dialog 'AE6C429F at XXX' Method: OPTIONS
[Feb  1 23:23:17] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:230 phase_d_handler:
[RXFAX NEW PAGE]: Channel: SIP/trunk-00000035 Pages: -1224970700 Speed:
14400
[Feb  1 23:23:17] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:231
phase_d_handler:                Bad rows: 0 - Longest bad row run: 0 -
Compression type: T.4 2-D
[Feb  1 23:23:17] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:232
phase_d_handler:                Image size bytes: 86071 - Image size: 1728 x
2156 - Image resolution: 8031 x 7700
    -- [RXFAX NEW PAGE]: Channel: SIP/trunk-00000035 Pages: -1224970700
Speed: 14400
[Feb  1 23:23:18] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:230 phase_d_handler:
[RXFAX NEW PAGE]: Channel: SIP/trunk-00000034 Pages: -1225599608 Speed:
14400
[Feb  1 23:23:18] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:231
phase_d_handler:                Bad rows: 0 - Longest bad row run: 0 -
Compression type: T.4 2-D
[Feb  1 23:23:18] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:232
phase_d_handler:                Image size bytes: 86072 - Image size: 1728 x
2156 - Image resolution: 8031 x 7700
    -- [RXFAX NEW PAGE]: Channel: SIP/trunk-00000034 Pages: -1225599608
Speed: 14400
Really destroying SIP dialog '439a2cca2a745a565a4e0aab56a054b8 at XXX'
Method:
OPTIONS
Really destroying SIP dialog '49515A3F at XXX' Method: OPTIONS
[Feb  1 23:23:59] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:230 phase_d_handler:
[RXFAX NEW PAGE]: Channel: SIP/trunk-00000035 Pages: -1224970700 Speed:
14400
[Feb  1 23:23:59] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:231
phase_d_handler:                Bad rows: 0 - Longest bad row run: 0 -
Compression type: T.4 2-D
[Feb  1 23:23:59] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:232
phase_d_handler:                Image size bytes: 70190 - Image size: 1728 x
2156 - Image resolution: 8031 x 7700
    -- [RXFAX NEW PAGE]: Channel: SIP/trunk-00000035 Pages: -1224970700
Speed: 14400
[Feb  1 23:24:00] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:230 phase_d_handler:
[RXFAX NEW PAGE]: Channel: SIP/trunk-00000034 Pages: -1225599608 Speed:
14400
[Feb  1 23:24:00] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:231
phase_d_handler:                Bad rows: 0 - Longest bad row run: 0 -
Compression type: T.4 2-D
[Feb  1 23:24:00] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:232
phase_d_handler:                Image size bytes: 70191 - Image size: 1728 x
2156 - Image resolution: 8031 x 7700
    -- [RXFAX NEW PAGE]: Channel: SIP/trunk-00000034 Pages: -1225599608
Speed: 14400
Really destroying SIP dialog '76CF8422 at XXX' Method: OPTIONS
[Feb  1 23:24:02] NOTICE[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:209 phase_e_handler:
[FaxReceived OK] Remote:  Local:  Pages: 0 Speed: 14400
 [FaxReceived OK] Remote:  Local:  Pages: 0 Speed: 14400
[Feb  1 23:24:02] WARNING[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:478 fax_run: TXFAX:
t30_call_active is FALSE.
[Feb  1 23:24:02] WARNING[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:599 fax_run: TXFAX:
Fax Transmission INCOMPLETE, check error code
[Feb  1 23:24:02] WARNING[13752]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:603 fax_run: TXFAX:
Transmission RES error = -1
[Feb  1 23:24:02] NOTICE[13752]: pbx_spool.c:370 attempt_thread: Call
completed to Sip/trunk/XXXXXXXXXX
[Feb  1 23:24:02] NOTICE[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:209 phase_e_handler:
[FaxReceived OK] Remote:  Local:  Pages: 2 Speed: 14400
 [FaxReceived OK] Remote:  Local:  Pages: 2 Speed: 14400
[Feb  1 23:24:02] WARNING[13753]:
/usr/src/asterisk/agx-ast-addons/app-spandsp/app_fax.c:478 fax_run: RXFAX:
t30_call_active is FALSE.
AGI Tx >> 200 result=0
AGI Rx << VERBOSE "Converting /tmp/1296624119.53.tiff to
/tmp/1296624119.53.pdf" 1
  fax.agi: Converting /tmp/1296624119.53.tiff to /tmp/1296624119.53.pdf
AGI Tx >> 200 result=1
Really destroying SIP dialog '371b80c6324ece0c779653c34d2e88a2 at XXX'
Method:
INVITE
  == Spawn extension (from-trunk, XXXXXXXXXX, 3) exited non-zero on
'SIP/trunk-00000035'
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20110201/934b94aa/attachment.htm>

On Tuesday 01 February 2011 23:43:34 Charles Solar
wrote:
> Hey guys I was hoping I could get a few pointers on a problem I have
> been trying to debug for the last couple of months regarding asterisk
> AGI scripts and unexpected termination.
> I have this agi script that accepts incoming faxes using RxFax on the
> latest asterisk 1.4 branch. Its written with perl and it works fine
> except for one line that causes the entire script to terminate
> unexpectedly.
<snip>
> AGI Tx >> 200 result=0
> AGI Rx << VERBOSE "Converting /tmp/1296624119.53.tiff to
> /tmp/1296624119.53.pdf" 1
>   fax.agi: Converting /tmp/1296624119.53.tiff to /tmp/1296624119.53.pdf
> AGI Tx >> 200 result=1
> Really destroying SIP dialog '371b80c6324ece0c779653c34d2e88a2 at
XXX'
> Method: INVITE
>   == Spawn extension (from-trunk, XXXXXXXXXX, 3) exited non-zero on
> 'SIP/trunk-00000035'
This isn't the script terminating non-zero.  It's the channel hanging
up.

One possible problem might be that your script is not properly handling the
SIGHUP signal sent to the AGI process when a hangup occurs.  If that is the
case, then your script may be terminating early due to the signal.  The
best way to handle that is to set a signal handler in your script (this is
dependent upon the language you're using), although there's also a
workaround for people who are unwilling or unable to set a signal handler.

Just remember that prior to Asterisk 1.6.2, once you receive the SIGHUP,
you may no longer interact with the Asterisk process.  That includes
setting and retrieving variables and using the VERBOSE command.  Starting
with Asterisk 1.6.2, an AGI is free to continue interacting with Asterisk
(the setting of final variables is likely the most productive task).

-- 
Tilghman