Sample script demonstrating a few erlexec issues about erlexec

[saleyn]

Apparently the buffering part is easy to fix: http://stackoverflow.com/questions/7876660/how-to-turn-off-buffering-of-stdout-in-c. I'll try to commit it later tonight if I have time.

Regarding the other issues, I need to explore further if I can reproduce on Linux. I only have Fedora installation, but don't suppose Debian is too different in this regard. Can you run "uname -a" on your machine?

Can you also start exec with the debug option and include the output:

exec:start([debug]).

[OvermindDL1]

uname -a on machine 1 is: Linux minecraftforge.net 3.8.13-xxxx-grs-ipv6-64 #3 SMP Fri May 31 13:26:19 CEST 2013 x86_64 GNU/Linux
uname -a on machine 3 is: Linux overminddl1.com 3.5.0-28-generic #47-Ubuntu SMP Tue Apr 9 19:03:54 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

If you want me to test machine 2 again then I can do that tonight, but it is fairly identical to machine one, though an older version of debian.

Certainly, I replaced application:start(exec) with exec:start([debug]) and got this output on the two machines I can test right now:

Serializer::read() - message size: 114
--Erl->-C--[ 114]: <<131,104,2,97,1,104,3,100,0,3,114,117,110,107,0,56,106,97,118,97,32,45,88,109,115,49,71,32,45,88,109,120,49,71,32,45,106,97,114,32,109,105,110,101,99,114,97,102,116,95,115,101,114,118,101,114,46,49,46,54,46,50,46,106,97,114,32,110,111,103,117,105,108,0,0,0,2,104,2,100,0,6,115,116,100,101,114,114,100,0,4,116,114,117,101,104,2,100,0,6,115,116,100,111,117,116,100,0,4,116,114,117,101,106>>
Created pipe (readfd=5, writefd=6)
Created pipe (readfd=7, writefd=8)
Starting child: java -Xms1G -Xmx1G -jar minecraft_server.1.6.2.jar nogui
Setup pid 1529 stdout redirection
Setup pid 1529 stderr redirection
--Erl-<-C--[  17]: <<131,104,2,97,1,104,2,100,0,2,111,107,98,0,0,5,249>>
Added pid 1529 stdout reading (fd=5)
timeout {1375,978095,844018}
timeout {1375,978096,849017}
timeout {1375,978097,850018}
Added pid 1529 stdout reading (fd=5)
timeout {1375,978098,851018}
timeout {1375,978099,852018}
timeout {1375,978101,854018}
timeout {1375,978102,855159}
Added pid 1529 stdout reading (fd=5)
timeout {1375,978103,856301}
timeout {1375,978104,857430}
timeout {1375,978105,858549}
Added pid 1529 stdout reading (fd=5)
Added pid 1529 stdout reading (fd=5)
timeout {1375,978116,867833}
timeout {1375,978117,868967}
Added pid 1529 stdout reading (fd=5)
timeout {1375,978118,870017}
timeout {1375,978119,871020}
timeout {1375,978120,872017}
Serializer::read() - message size: 21
--Erl->-C--[  21]: <<131,104,2,97,1,104,3,100,0,4,107,105,108,108,98,0,0,5,249,97,9>>
Calling kill(pid=1529, sig=9)
--Erl-<-C--[  10]: <<131,104,2,97,1,100,0,2,111,107>>
Added pid 1529 stdout reading (fd=5)
Read 0 bytes from pid 1529's stdout
Process 1529 exited (sig=17)
Read 513 bytes from pid 1529's stderr
--Erl-<-C--[ 539]: <<131,104,2,97,0,104,3,100,0,6,115,116,100,101,114,114,98,0,0,5,249,109,0,0,2,1,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,73,78,70,79,93,32,83,116,97,114,116,105,110,103,32,109,105,110,101,99,114,97,102,116,32,115,101,114,118,101,114,32,118,101,114,115,105,111,110,32,49,46,54,46,50,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,73,78,70,79,93,32,76,111,97,100,105,110,103,32,112,114,111,112,101,114,116,105,101,115,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,73,78,70,79,93,32,68,101,102,97,117,108,116,32,103,97,109,101,32,116,121,112,101,58,32,83,85,82,86,73,86,65,76,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,73,78,70,79,93,32,71,101,110,101,114,97,116,105,110,103,32,107,101,121,112,97,105,114,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,73,78,70,79,93,32,83,116,97,114,116,105,110,103,32,77,105,110,101,99,114,97,102,116,32,115,101,114,118,101,114,32,111,110,32,42,58,50,53,53,54,53,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,87,65,82,78,73,78,71,93,32,42,42,42,42,32,70,65,73,76,69,68,32,84,79,32,66,73,78,68,32,84,79,32,80,79,82,84,33,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,87,65,82,78,73,78,71,93,32,84,104,101,32,101,120,99,101,112,116,105,111,110,32,119,97,115,58,32,106,97,118,97,46,110,101,116,46,66,105,110,100,69,120,99,101,112,116,105,111,110,58,32,65,100,100,114,101,115,115,32,97,108,114,101,97,100,121,32,105,110,32,117,115,101,10,50,48,49,51,45,48,56,45,48,56,32,49,50,58,48,56,58,49,52,32,91,87,65,82,78,73,78,71,93,32,80,101,114,104,97,112,115,32,97,32,115,101,114,118,101,114,32,105,115,32,97,108,114,101,97,100,121,32,114,117,110,110,105,110,103,32,111,110,32,116,104,97,116,32,112,111,114,116,63,10>>
Added pid 1529 stdout reading (fd=5)
Read 0 bytes from pid 1529's stdout
Read 0 bytes from pid 1529's stderr
--Erl-<-C--[  28]: <<131,104,2,97,0,104,3,100,0,11,101,120,105,116,95,115,116,97,116,117,115,98,0,0,5,249,97,9>>
Message {1375,978120,876194}: {stderr,1529,
                                      <<"2013-08-08 12:08:14 [INFO] Starting minecraft server version 1.6.2\n2013-08-08 12:08:14 [INFO] Loading properties\n2013-08-08 12:08:14 [INFO] Default game type: SURVIVAL\n2013-08-08 12:08:14 [INFO] Generating keypair\n2013-08-08 12:08:14 [INFO] Starting Minecraft server on *:25565\n2013-08-08 12:08:14 [WARNING] **** FAILED TO BIND TO PORT!\n2013-08-08 12:08:14 [WARNING] The exception was: java.net.BindException: Address already in use\n2013-08-08 12:08:14 [WARNING] Perhaps a server is already running on that port?\n">>}
Message {1375,978120,876340}: {'EXIT',<0.35.0>,{exit_status,9}}
timeout {1375,978121,877019}
timeout {1375,978122,878020}
timeout {1375,978123,879020}
timeout {1375,978125,881021}
timeout {1375,978126,882138}
timeout {1375,978127,883290}
timeout {1375,978128,884409}
timeout {1375,978129,885560}
{"init terminating in do_boot",{undef,[{erl_eval,q,0,[]},{erl_eval,expr,3,[]}]}}
Calling kill(pid=0, sig=15)
Got signal: 15
Exiting (91)

And I eagerly await stdin support as well as you mentioned on the mailing list. :)

[saleyn]

Implemented stdin support and fixed a couple of minor issues. There's still a problem with pipe output buffering, which I am not sure yet how to handle. The issue only happens with pipes and not with file descriptors. Please retest.

[OvermindDL1]

Re-testing above script (with debug), results:

Created stdout pipe (readfd=5, writefd=6)
Created stderr pipe (readfd=7, writefd=8)
Starting child: java -Xms1G -Xmx1G -jar minecraft_server.1.6.2.jar nogui
Setup pid 17384 stdout redirection (fd=5 [non-block])
Setup pid 17384 stderr redirection (fd=7 [non-block])
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
timeout {1376,96483,793018}
timeout {1376,96484,798019}
timeout {1376,96485,799018}
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
timeout {1376,96486,800018}
timeout {1376,96487,801018}
timeout {1376,96489,803018}
timeout {1376,96490,804021}
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
timeout {1376,96491,805134}
timeout {1376,96492,806252}
timeout {1376,96493,807365}
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
timeout {1376,96504,814439}
timeout {1376,96505,815555}
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
timeout {1376,96506,816663}
timeout {1376,96507,817509}
timeout {1376,96508,818022}
Calling kill(pid=17384, sig=9)
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
Process 17384 exited (sig=17, oktojump=0)
Pid 17384 adding stdout checking
Pid 17384 adding stderr checking
Message {1376,96508,821428}: {stderr,17384,
                                     <<"2013-08-09 21:01:22 [INFO] Starting minecraft server version 1.6.2\n2013-08-09 21:01:22 [INFO] Loading properties\n2013-08-09 21:01:22 [WARNING] server.properties does not exist\n2013-08-09 21:01:22 [INFO] Generating new properties file\n2013-08-09 21:01:22 [INFO] Default game type: SURVIVAL\n2013-08-09 21:01:22 [INFO] Generating keypair\n2013-08-09 21:01:22 [INFO] Starting Minecraft server on *:25565\n2013-08-09 21:01:22 [WARNING] **** FAILED TO BIND TO PORT!\n2013-08-09 21:01:22 [WARNING] The exception was: java.net.BindException: Address already in use\n2013-08-09 21:01:22 [WARNING] Perhaps a server is already running on that port?\n">>}
Message {1376,96508,821586}: {'EXIT',<0.35.0>,{exit_status,9}}
timeout {1376,96509,822018}
timeout {1376,96510,823019}
timeout {1376,96511,824019}
timeout {1376,96513,826022}
timeout {1376,96514,827155}
timeout {1376,96515,828285}
timeout {1376,96516,829397}
timeout {1376,96517,830036}
{"init terminating in do_boot",{undef,[{erl_eval,q,0,[]},{erl_eval,expr,3,[]}]}}
Setting alarm to 12 seconds
Calling kill(pid=0, sig=15)
Got signal: 15
Exiting (91)

Same issue, still seems everything is getting buffered and not sent to Erlang in a quick manner.

STDIN support is something big I have wanted, shall test it soon, thanks much for that!

[saleyn]

At this time I am uncertain why the buffering is taking place. I set the stdout of the child process to line buffering mode, which should flush the content upon encountering '\n', and it works like that when writing stdout to file, but not to pipe. I'll keep experimenting. Setting it to no buffering didn't change the behavior.

Regarding other "zombie" issues, have you been able to reproduce them with current version of erlexec?

[saleyn]

The issue with stdout buffering is fixed in the latest commit.

[OvermindDL1]

Just wanted to confirm that on all my systems that buffering seems perfect now. Thank you much!

Created stdout pipe (readfd=5, writefd=6)
Created stderr pipe (readfd=7, writefd=8)
Starting child: java -Xms1G -Xmx1G -jar minecraft_server.1.6.2.jar nogui
Setup pid 19532 stdout redirection (fd=5 [non-block])
Setup pid 19532 stderr redirection (fd=7 [non-block])
Message {1376,205966,35024}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [INFO] Starting minecraft server version 1.6.2\n">>}
Message {1376,205966,39222}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [INFO] Loading properties\n">>}
Message {1376,205966,39284}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [WARNING] server.properties does not exist\n">>}
Message {1376,205966,39339}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [INFO] Generating new properties file\n">>}
Message {1376,205966,39388}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [INFO] Default game type: SURVIVAL\n">>}
Message {1376,205967,40034}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [INFO] Generating keypair\n">>}
Message {1376,205967,40169}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [INFO] Starting Minecraft server on *:25565\n">>}
Message {1376,205967,40259}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [WARNING] **** FAILED TO BIND TO PORT!\n">>}
Message {1376,205967,40346}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [WARNING] The exception was: java.net.BindException: Address already in use\n">>}
Message {1376,205967,40414}: {stderr,19532,
                                     <<"2013-08-11 03:26:05 [WARNING] Perhaps a server is already running on that port?\n">>}
timeout {1376,205978,49747}
timeout {1376,205979,50902}
timeout {1376,205980,52030}
timeout {1376,205981,53192}
timeout {1376,205982,54340}
Calling kill(pid=19532, sig=9)
Process 19532 exited (sig=17, oktojump=0)
Message {1376,205982,58379}: {'EXIT',<0.35.0>,{exit_status,9}}
timeout {1376,205983,59024}
timeout {1376,205984,60025}
timeout {1376,205985,61024}
timeout {1376,205986,62025}
timeout {1376,205988,64025}
timeout {1376,205989,65185}
timeout {1376,205990,66029}
timeout {1376,205991,67159}
timeout {1376,205992,68321}
{"init terminating in do_boot",{undef,[{erl_eval,q,0,[]},{erl_eval,expr,3,[]}]}}
Setting alarm to 12 seconds
Calling kill(pid=0, sig=15)
Got signal: 15
Exiting (91)

[OvermindDL1]

I shall see if I can get zombie processes again, if I can then I will open a new issue, if not then consider it also fixed.