On Mon, Feb 23, 2015 at 3:21 PM, Alexey Suslikov
<[email protected]> wrote:
> On Sun, Feb 22, 2015 at 11:22 PM, Stuart Henderson <[email protected]> wrote:
>> I can replicate this on my system (I'm running Asterisk 13 on
>> -current at the moment), including with a simpler script that just
>> touches a file in /tmp and doesn't deal with input at all; script
>> doesn't appear to run at all.
>
> Try 5.6 (and below), you'll see a difference.
11.16 on 5.6. Calling AGI/System work as expected.
Definitely not an Asterisk issue.
[Feb 23 15:24:44] Asterisk 11.16.0 built by YYY @ ZZZ on a amd64
running OpenBSD on 2015-02-23 11:57:08 UTC
...
[Feb 23 15:28:04] VERBOSE[-1][C-00000001] netsock2.c: == Using SIP
RTP TOS bits 184
[Feb 23 15:28:04] VERBOSE[-1][C-00000001] pbx.c: -- Executing
[XXXXXXXXXX@from-trunk:1] Wait("SIP/test-145-00000001", "1") in new
stack
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] pbx.c: -- Executing
[XXXXXXXXXX@from-trunk:2] AGI("SIP/test-145-00000001", "test.agi") in
new stack
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c: -- Launched
AGI Script /usr/local/share/asterisk/agi-bin/test.agi
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_request: test.agi
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_channel: SIP/test-145-00000001
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_language: ru
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_type: SIP
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_uniqueid: 1424698084.1
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_version: 11.16.0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_callerid: 938457579
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_calleridname: unknown
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_callingpres: 0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_callingani2: 0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_callington: 0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_callingtns: 0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_dnid: XXXXXXXXXX
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_rdnis: unknown
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_context: from-trunk
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_extension: XXXXXXXXXX
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_priority: 2
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_enhanced: 0.0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_accountcode:
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> agi_threadid: 25982340237312
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >>
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Rx << VERBOSE "Output debug string to *
cli" 3
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c: -- test.agi:
Output debug string to * cli
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c:
<SIP/test-145-00000001>AGI Tx >> 200 result=1
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] res_agi.c: --
<SIP/test-145-00000001>AGI Script test.agi completed, returning 0
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] pbx.c: -- Executing
[XXXXXXXXXX@from-trunk:3] System("SIP/test-145-00000001", "/bin/pwd")
in new stack
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] pbx.c: -- Executing
[XXXXXXXXXX@from-trunk:4] Hangup("SIP/test-145-00000001", "") in new
stack
[Feb 23 15:28:05] VERBOSE[-1][C-00000001] pbx.c: == Spawn extension
(from-trunk, XXXXXXXXXX, 4) exited non-zero on 'SIP/test-145-00000001'
>
>> The asterisk code involved in this hasn't been modified in 4
>> years or so. For anyone else interested, it looks like this:
>
> I use Asterisk on OpenBSD for a 'heck long time' and haven't
> observed something like this. My setup on 5.6 (and below) is
> production solid.
>
> If not modified in 4 years, the code in question can be called
> "fundamental", this is why the only conclusion I came up to is
> a change in OS behavior.
>
>> http://svnview.digium.com/svn/asterisk/branches/13/res/res_agi.c?view=markup#l1828
>> http://svnview.digium.com/svn/asterisk/branches/13/main/app.c?view=markup#l2904
>>
>> I've given it a bit of a poke with added logging in Asterisk but
>> not getting very far there, either I'm doing something wrong with
>> my ast_log(..) additions, or the if (!pid) block after line 1893
>> in res_agi.c isn't getting run at all.
>>
>>
>> On 2015/02/22 20:57, Alexey Suslikov wrote:
>>> Hello.
>>>
>>> Found while migrating to 5.7 snap.
>>>
>>> Two systems:
>>> * 5.6 (RELEASE) running Asterisk 11.11
>>> * 5.7 (Feb 22 snap) running Asterisk 11.16 (also tried with 11.11, 11.7,
>>> 11.5.1)
>>>
>>> Both systems have same Asterisk setup.
>>>
>>> extensions.conf:
>>> [from-trunk]
>>> exten => _XXXXXXXXXX,1,Wait(1)
>>> exten => _XXXXXXXXXX,n,AGI(test.agi)
>>> exten => _XXXXXXXXXX,n,System(/bin/pwd)
>>> exten => _XXXXXXXXXX,n,Hangup
>>>
>>> mount:
>>> /dev/sd0a on / type ffs (local)
>>> /dev/sd0d on /tmp type ffs (local, nodev, nosuid, softdep)
>>> /dev/sd0f on /usr type ffs (local, nodev)
>>> /dev/sd0e on /var type ffs (local, nodev, nosuid, softdep)
>>>
>>> ls -l /usr/local/share/asterisk/agi-bin/test.agi:
>>> -rwxrwx--- 1 _asterisk _asterisk 246 Feb 22 18:58
>>> /usr/local/share/asterisk/agi-bin/test.agi
>>>
>>> test.agi:
>>> #!/bin/sh
>>>
>>> readToFile() {
>>> stdin="0"
>>>
>>> while [ "${stdin}" != "" ]; do
>>> read stdin
>>> if [ "${stdin}" != EOF ]; then
>>> echo ${stdin} >> /tmp/agi.log
>>> fi
>>> done
>>> }
>>>
>>> readToFile
>>> echo "VERBOSE \"Output debug string to * cli\" 3"
>>> read RESPONSE
>>>
>>> exit 0
>>>
>>> But behavior of executing AGI/System is weirdly different (calling System
>>> is provided to show a fact that problem maybe not in AGI itself but with
>>> exec'ing external stuff).
>>>
>>> On 5.6/11.11:
>>>
>>> [Feb 22 18:02:17] VERBOSE[-1][C-00000017] netsock2.c: == Using SIP
>>> RTP TOS bits 184
>>> [Feb 22 18:02:17] VERBOSE[-1][C-00000017] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:1] Wait("SIP/test-145-00000017", "1") in new
>>> stack
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:2] AGI("SIP/test-145-00000017", "test.agi") in
>>> new stack
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c: -- Launched
>>> AGI Script /usr/local/share/asterisk/agi-bin/test.agi
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_request: test.agi
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_channel: SIP/test-145-00000017
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_language: ru
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_type: SIP
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_uniqueid: 1424620937.23
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_version: 11.11.0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_callerid: asterisk
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_calleridname: anonymous
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_callingpres: 0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_callingani2: 0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_callington: 0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_callingtns: 0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_dnid: XXXXXXXXXX
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_rdnis: unknown
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_context: from-trunk
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_extension: XXXXXXXXXX
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_priority: 2
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_enhanced: 0.0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_accountcode:
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> agi_threadid: 34529947892224
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >>
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Rx << VERBOSE "Output debug string to *
>>> cli" 3
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c: -- test.agi:
>>> Output debug string to * cli
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c:
>>> <SIP/test-145-00000017>AGI Tx >> 200 result=1
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] res_agi.c: --
>>> <SIP/test-145-00000017>AGI Script test.agi completed, returning 0
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:3] System("SIP/test-145-00000017", "/bin/pwd")
>>> in new stack
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:4] Hangup("SIP/test-145-00000017", "") in new
>>> stack
>>> [Feb 22 18:02:18] VERBOSE[-1][C-00000017] pbx.c: == Spawn extension
>>> (from-trunk, XXXXXXXXXX, 4) exited non-zero on 'SIP/test-145-00000017'
>>>
>>> On 5.7/11.16 (and other mentioned above Asterisk versions):
>>>
>>> [Feb 22 18:05:40] VERBOSE[-1][C-00000007] netsock2.c: == Using SIP
>>> RTP TOS bits 184
>>> [Feb 22 18:05:40] VERBOSE[-1][C-00000007] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:1] Wait("SIP/test-145-00000007", "1") in new
>>> stack
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:2] AGI("SIP/test-145-00000007", "test.agi") in
>>> new stack
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c: -- Launched
>>> AGI Script /usr/local/share/asterisk/agi-bin/test.agi
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_request: test.agi
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_channel: SIP/test-145-00000007
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_language: ru
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_type: SIP
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_uniqueid: 1424621140.7
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_version: 11.16.0
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_callerid: asterisk
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_calleridname: anonymous
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_callingpres: 0
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_callingani2: 0
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_callington: 0
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_callingtns: 0
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_dnid: XXXXXXXXXX
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_rdnis: unknown
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_context: from-trunk
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_extension: XXXXXXXXXX
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_priority: 2
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_enhanced: 0.0
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_accountcode:
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >> agi_threadid: 25204087336192
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c:
>>> <SIP/test-145-00000007>AGI Tx >>
>>> [Feb 22 18:05:41] ERROR[-1][C-00000007] utils.c: write() returned
>>> error: Broken pipe
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] res_agi.c: --
>>> <SIP/test-145-00000007>AGI Script test.agi completed, returning 0
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] pbx.c: -- Executing
>>> [XXXXXXXXXX@from-trunk:3] System("SIP/test-145-00000007", "/bin/pwd")
>>> in new stack
>>> [Feb 22 18:05:41] WARNING[-1][C-00000007] app_system.c: Unable to
>>> execute '/bin/pwd'
>>> [Feb 22 18:05:41] VERBOSE[-1][C-00000007] pbx.c: == Spawn extension
>>> (from-trunk, XXXXXXXXXX, 3) exited non-zero on 'SIP/test-145-00000007'
>>>
>>> Notice 'Broken pipe' and 'Unable to execute'.
>>>
>>> I'm out of ideas so any help is welcome.
>>>
>>> Cheers,
>>> Alexey
>>>
