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@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@XXX' Method:
OPTIONS
REGISTER attempt 1 to XXXXXXXXXX@trunk
Really destroying SIP dialog '33dff0b60f7ce29944351e446c2e7b5b@XXX' Method:
REGISTER
Really destroying SIP dialog 'AE6C429F@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@XXX' Method:
OPTIONS
Really destroying SIP dialog '49515A3F@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@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@XXX' Method:
INVITE
== Spawn extension (from-trunk, XXXXXXXXXX, 3) exited non-zero on
'SIP/trunk-00000035'
--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
http://www.asterisk.org/hello
asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-users
