exec-port gets stuck on Mac OS X about erlexec

[obmarg]

Oh, and this is on mac os 10.11.4 if that makes a difference.

[saleyn]

Unfortunately I don't have Mac OS X environment to test this. PR would be welcome.
This works fine on Linux.

[whitfin]

@obmarg is still an issue on macOS Sierra?

[saleyn]

Never seen any followup on this one, but generally Mac OS might be of an issue (see the README note).

[obmarg]

@zackehh I've not upgraded to Sierra yet, so not sure if it's still an issue. I'll try and update when I do.

Did attempt to fix this myself but I don't really understand signals enough to do so.

[saleyn]

Do you mind checking if the current version experiences the same issue? I changed implementation to using a kqueue on Mac OS for signal delivery, but have no Mac to test this on.

[obmarg]

@saleyn Ah, nice! My initial investigation suggests this might have fixed the issue. I'll try to play around and make sure.

I did getting a few compile errors on the latest macOS. I'll make a PR to fix those later on.

[saleyn]

I believe I fixed the compilation issues, but if you could check if "make test" works on Mac OS X, that would be very helpful. That includes a test case that involves test/test_exec.erl, which is likely testing the problem described in this issue.

[obmarg]

Yep, you've fixed the compile issues I was having the other day, but I've got some new ones now.

When Running make test

When running make test I get rebar or rebar3 not found!. Stop.. Fixed this with:

--- a/Makefile
+++ b/Makefile
@@ -6,7 +6,7 @@ TARBALL = $(PROJECT)-$(VSN)

 DIALYZER = dialyzer
 REBAR   := $(shell which rebar3 2>/dev/null)
-REBAR   := $(if $(REBAR),$(REBAR),$(which rebar 2>/dev/null))
+REBAR   := $(if $(REBAR),$(REBAR),$(shell which rebar 2>/dev/null))

 ifeq (,$(REBAR))
 $(error rebar or rebar3 not found!)

Then I get some failures in the tests:

**in function exec:'-exec_test_/0-fun-0-'/0 (src/exec.erl, line 1102)
**error:{badmatch,
    {error,
        {undef,
            [{filelibename,join,
                 [["x86_64-apple-darwin14.5.0","exec-port"]],
                 []},
             {exec,default,1,[{file,"src/exec.erl"},{line,562}]},
             {exec,init,1,[{file,"src/exec.erl"},{line,602}]},
             {gen_server,init_it,6,[{file,"gen_server.erl"},{line,328}]},
             {proc_lib,init_p_do_apply,3,
                 [{file,"proc_lib.erl"},{line,240}]}]}}}

Fixed that with

--- a/src/exec.erl
+++ b/src/exec.erl
@@ -559,7 +559,7 @@ default(portexe) ->
         [Port] -> Port;
         _      ->
             Arch = erlang:system_info(system_architecture),
-            Tail = filelibename:join([Arch, "exec-port"]),
+            Tail = filename:join([Arch, "exec-port"]),
             os:find_executable(filename:join([Priv, Tail]))
     end,
     % Join the priv/port path

That lets make test run, but it appears to fail a bunch of times:

WARN:  Missing plugins: [pc]
==> erlexec (eunit)
exec:1105: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_monitor/0 (src/exec.erl, line 1125)
**error:{case_clause,{ok,94755}}
  output:<<"">>

exec:1106: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:'-test_sync/0-fun-0-'/0 (src/exec.erl, line 1130)
in call from exec:test_sync/0 (src/exec.erl, line 1129)
**error:{case_clause,{ok,94756}}
  output:<<"">>

exec:1107: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_stdin/0 (src/exec.erl, line 1136)
**error:{case_clause,{ok,94757}}
  output:<<"">>

exec:1108: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_stdin_eof/0 (src/exec.erl, line 1142)
**error:{case_clause,{ok,94758}}
  output:<<"">>

exec:1109: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_std/1 (src/exec.erl, line 1153)
**error:{case_clause,{ok,94759}}
  output:<<"">>

exec:1110: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_std/1 (src/exec.erl, line 1153)
**error:{case_clause,{ok,94760}}
  output:<<"">>

exec:1111: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:'-test_cmd/0-fun-0-'/0 (src/exec.erl, line 1176)
in call from exec:test_cmd/0 (src/exec.erl, line 1174)
**error:{case_clause,{ok,94762}}
  output:<<"">>

exec:1112: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:'-test_executable/0-fun-0-'/0 (src/exec.erl, line 1190)
in call from exec:test_executable/0 (src/exec.erl, line 1187)
**error:{case_clause,{ok,94764}}
  output:<<"">>

exec:1113: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:'-test_redirect/0-fun-0-'/0 (src/exec.erl, line 1211)
in call from exec:test_redirect/0 (src/exec.erl, line 1210)
**error:{case_clause,{ok,94765}}
  output:<<"">>

exec:1114: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:'-test_env/0-fun-0-'/0 (src/exec.erl, line 1218)
**error:{case_clause,{ok,94766}}
  output:<<"">>

exec:1115: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_kill_timeout/0 (src/exec.erl, line 1222)
**error:{case_clause,{ok,94767}}
  output:<<"">>

exec:1116: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:test_setpgid/0 (src/exec.erl, line 1231)
**error:{case_clause,{ok,94768}}
  output:<<"">>

exec:1117: exec_test_...*failed*
in function exec:do_run/2 (src/exec.erl, line 796)
in call from exec:'-test_pty/0-fun-0-'/0 (src/exec.erl, line 1240)
in call from exec:test_pty/0 (src/exec.erl, line 1239)
**error:{case_clause,{ok,94770}}
  output:<<"">>

exec: exec_run_many_test...*skipped*
undefined
*unexpected termination of test process*
::{{case_clause,{ok,94772}},
   [{exec,do_run,2,[{file,"src/exec.erl"},{line,796}]},
    {test_exec,handle_info,2,[{file,"test/test_exec.erl"},{line,127}]},
    {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,615}]},
    {gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,681}]},
    {proc_lib,init_p_do_apply,3,[{file,[...]},{line,...}]}]}

=======================================================
  Failed: 13.  Skipped: 0.  Passed: 0.
One or more tests were cancelled.

=ERROR REPORT==== 17-Nov-2016::14:25:42 ===
** Generic server test_exec terminating
** Last message in was start_child
** When Server state == {state,<0.45.0>,1,1000,0,0,
                               {set,0,16,16,8,80,48,
                                    {[],[],[],[],[],[],[],[],[],[],[],[],[],
                                     [],[],[]},
                                    {{[],[],[],[],[],[],[],[],[],[],[],[],[],
                                      [],[],[]}}}}
** Reason for termination ==
** {{case_clause,{ok,94772}},
    [{exec,do_run,2,[{file,"src/exec.erl"},{line,796}]},
     {test_exec,handle_info,2,[{file,"test/test_exec.erl"},{line,127}]},
     {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,615}]},
     {gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,681}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}

=INFO REPORT==== 17-Nov-2016::14:25:42 ===
    application: erlexec
    exited: killed
    type: temporary
ERROR: One or more eunit tests failed.
ERROR: eunit failed while processing /Users/graeme/src/thirdparty/erlexec: rebar_abort
make: *** [test] Error 1

Compiling from Elixir

I get some slightly different errors when pulling erlexec into an elxir project. Initially it fails on compile with:

c_src/exec.cpp:465:13: error: use of undeclared identifier 'setresuid'
            setresuid(-1, userid, geteuid()) // glibc, FreeBSD, OpenBSD, HP-UX

c_src/exec_impl.cpp:557:17: error: use of undeclared identifier 'setresuid'
                setresuid(op.user(), op.user(), op.user())

It seems like HAVE_SETRESUID is defined when it shouldn't be: if I force HAVE_SETREUID instead it gets past this. But then I get

clang: error: no such file or directory: '$LDFLAGS-m64-m64'
ERROR: sh(g++ c_src/ei++.o c_src/exec.o c_src/exec_impl.o $LDFLAGS-m64  -L"/Users/graeme/.asdf/installs/erlang/18.2.1/lib/erlang/lib/erl_interface-3.8.1/lib" -lerl_interface -lei -o priv/x86_64-apple-darwin14.5.0/exec-port)
failed with return code 1 and the following output:
clang: error: no such file or directory: '$LDFLAGS-m64-m64'

Not sure if there's some rebar configuration that elixir is failing to pick up correctly or something?

[obmarg]

Let me know if there's anything I can do to help with fixing: definitely happy to keep running mac tests for you, if nothing else.

[saleyn]

Could you please retry the build/run on Mac OS? I did some minor cleanup of the issues you listed. All build problems should go away. Regarding failing "make test" - is it possible that it was running the stale version of the exec-port binary?

All tests are passing on linux: https://travis-ci.org/saleyn/erlexec/builds/176721920. Unfortunately Travis-CI doesn't support building Erlang projects on OS X.

[obmarg]

Yep, that's fixed the build issues.

I believe it may have been using the old exec-port in tests: after a make clean that issue goes away.

I'm still getting undef on filelib:join. I believe it's actually filename:join you want?

Now I am getting:

==> erlexec (eunit)
undefined
*** context setup failed ***
**in function exec:'-exec_test_/0-fun-0-'/0 (src/exec.erl, line 1103)
**error:{badmatch,{error,{bad_return_value,"Cannot find file /Users/graeme/src/thirdparty/erlexec/priv/false: no such file or directory"}}}


exec: exec_run_many_test...*failed*
in function test_exec:run/3 (test/test_exec.erl, line 43)
in call from exec:'-exec_run_many_test/0-fun-0-'/0 (src/exec.erl, line 1123)
**error:{badmatch,{error,{"no such file or directory","erlexec.app"}}}
  output:<<"">>

On test run.

[saleyn]

Yes, you are right. Fixed.

[obmarg]

Actually, I have been assuming that make test would build exec-port before it ran the tests: that's why I was getting the failures in my last message. Now that I've fixed that I get a couple of failures:

exec:1109: exec_test_...*failed*
in function exec:'-test_stdin_eof/0-fun-0-'/0 (src/exec.erl, line 1146)
in call from exec:test_stdin_eof/0 (src/exec.erl, line 1146)
**error:{assertMatch,[{module,exec},
              {line,1146},
              {expression,"timeout"},
              {pattern,"{ stdout , I , << \"baz\\nbar\\nfoo\\n\" >> }"},
              {value,timeout}]}
  output:<<"">>

exec:1118: exec_test_...*failed*
in function exec:'-test_pty/0-fun-1-'/0 (src/exec.erl, line 1242)
in call from exec:test_pty/0 (src/exec.erl, line 1242)
**error:{assertMatch,[{module,exec},
              {line,1242},
              {expression,"exec : run ( \"tty\" , [ stdin , stdout , pty , sync ] )"},
              {pattern,"{ ok , [ { stdout , [ << \"/dev/pts/\" , _ / binary >> ] } ] }"},
              {value,{ok,[{stdout,[<<"/dev/ttys004\r\n">>]}]}}]}
  output:<<"">>

[obmarg]

(The first of those is probably because I don't have tac installed on my machine by the way: though seems odd that it times out instead of erroring...)

[saleyn]

I fixed both cases. Apparently the tty device is named differently on linux/mac.

Regarding the first one - yes, it's due to missing tac. The timeout is expected as it's not executed synchronously and timed out waiting for stdout.

[obmarg]

Yep, that's fixed those. Though I am now getting some sporadic timeouts while waiting for monitor DOWN messages:

exec:1108: exec_test_...*failed*
in function exec:'-test_stdin/0-fun-2-'/0 (src/exec.erl, line 1140)
**error:{assertMatch,[{module,exec},
              {line,1140},
              {expression,"timeout"},
              {pattern,"{ 'DOWN' , _ , process , P , normal }"},
              {value,timeout}]}
  output:<<"">>

exec:1118: exec_test_...*failed*
in function exec:'-test_pty/0-fun-5-'/0 (src/exec.erl, line 1260)
**error:{assertMatch,[{module,exec},
              {line,1260},
              {expression,"timeout"},
              {pattern,"{ 'DOWN' , _ , process , P , normal }"},
              {value,timeout}]}
  output:<<"">>

exec: exec_run_many_test...*timed out*
undefined
=======================================================
  Failed: 2.  Skipped: 0.  Passed: 11.
One or more tests were cancelled.

=ERROR REPORT==== 17-Nov-2016::16:08:50 ===
** Generic server test_exec terminating
** Last message in was {'EXIT',<0.69.0>,killed}
** When Server state == {state,<0.69.0>,1,0,1,1000,
                               {set,1,16,16,8,80,48,
                                    {[],[],[],[],[],[],[],[],[],[],[],[],[],
                                     [],[],[]},
                                    {{[],[],[],[],[],[],[],[],
                                      [13643],
                                      [],[],[],[],[],[],[]}}}}
** Reason for termination ==
** killed

Sometimes they pass fine, but other times they fail. Not sure if this is just a timing issue, or...?

[saleyn]

It must be some race condition in the pselectx() function on the C++ side on OS X. The issue seems that for some reason it's somehow missing the SIGCHLD signal. This needs further debugging.

You can try to build exec.erl with all functions exported, and run a specific test function that's failing with enabling debugging of the port program:

$ erlc +export_all -I include -DTEST -DEUNIT -o $(make path) src/exec.erl
$ erl -pa $(make path)
1> exec:start([{debug, 2}]).
2> exec:test_stdin().
3> q().

[obmarg]

Ok, cool - I'll have a go at debugging it then.

Thanks for all your efforts on this by the way, it's really appreciated.

[obmarg]

I've done a bit of investigation:

• gotsigchild is called almost never in my testing. I've ran the test_stdin function 50+ times, but only twice have I seen the "Child process exited" message that is in that function. I am not sure why this is.
• I'm seeing timeouts in the tests because exec-port is sitting in the select call until it timesout after 5 seconds. Once that timeout expires it detects the child process has exited and sends the DOWN message, but by that point the test has usually timed out.
• I can get that test to pass consistently by changing SLEEP_TIMEOUT_SEC to 1.

I'm not sure if that would be an acceptable fix?

[saleyn]

Not really. Can you try to comment out this line and rerun?
https://github.com/saleyn/erlexec/blob/master/c_src/exec.cpp#L192

[obmarg]

That seems to make it to pass consistently.

[saleyn]

And "make test" works properly?

[obmarg]

Sort of. Says there were zero failures, but then errors out:

==> erlexec (eunit)
exec: exec_run_many_test...*timed out*
undefined
=======================================================
  Failed: 0.  Skipped: 0.  Passed: 13.
One or more tests were cancelled.
ERROR: One or more eunit tests failed.
ERROR: eunit failed while processing /Users/graeme/src/thirdparty/erlexec: rebar_abort
make: *** [test] Error 1

[saleyn]

Can you please try the current version? I made some changes to get rid of pselect() all together. Hopefully this will work both on Linux and Mac.

[obmarg]

Yep, that compiles, make test works and the unit tests in my project that uses erlexec also work.

[saleyn]

Great! Thanks for your help!