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. > 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 >>
