Partial stdout even when child exist with status code 0

[neeraj9]

It appears the stdout from a child process is not flushed entirely even when it exists.

RelativeFilePath = <<"somefile.erl.fun">>,
Path = <<"/opt/beamparticle-data/git-data/git-src">>,
CtrlDir = <<"/opt/beamparticle-data/git-data">>,
Drv = alcove_drv:start_link([{ctldir, CtlDir}]),
Command = <<"/usr/bin/git">>,
Args = [<<"log">>, <<"--follow">>, <<"--pretty=\"%h\"">>, <<"-z">>, RelativeFilePath],
TimeoutMsec = 5000,

The execute_command/5 is as follows:

execute_command(Drv, Path, Command, Args, TimeoutMsec) ->
    {ok, ChildPID} = alcove:fork(Drv, []),
    alcove:chdir(Drv, [ChildPID], Path),
    EnvironmentVars = [],
    ok = alcove:execve(Drv, [ChildPID], Command, [Command | Args],
                       EnvironmentVars),
    lager:info("git-backend running command ~s ~s", [Command, Args]),
    receive
        {alcove_event, Drv, [ChildPID], {exit_status, ExitCode}} = Event ->
            lager:info("git-backend received event ~p", [Event]),
            Stdout = alcove:stdout(Drv, [ChildPID]),
            Stderr = alcove:stderr(Drv, [ChildPID]),
            {ExitCode, Stdout, Stderr}
    after
        TimeoutMsec ->
            alcove:kill(Drv, [], ChildPID, 9),
            {error, timeout}
    end.

The output (stdout) gives a partial listing for SHA-1 hashes (see below). Additionally, notice that the first time it gave two hashes (which is also less) and the second time just one.

([email protected])8> beamparticle_gitbackend_server:git_log(<<"/opt/beamparticle-data/git-data/git-src">>, short, <<"weather_for_city.erl.fun">>, 5000).
07:31:22.299 [info] git-backend running command /usr/bin/git log--follow--pretty="%h"-zweather_for_city.erl.fun
07:31:22.369 [info] git-backend received event {alcove_event,<0.4500.0>,[12071],{exit_status,0}}
07:31:22.369 [info] Content = <<34,97,100,50,101,56,48,102,34,0,34,55,99,57,97,53,98,48,34,0>>
[<<"\"ad2e80f\"">>,<<"\"7c9a5b0\"">>,<<>>]
([email protected])9> beamparticle_gitbackend_server:git_log(<<"/opt/beamparticle-data/git-data/git-src">>, short, <<"weather_for_city.erl.fun">>, 5000).
07:31:23.568 [info] git-backend running command /usr/bin/git log--follow--pretty="%h"-zweather_for_city.erl.fun
07:31:23.644 [info] git-backend received event {alcove_event,<0.4500.0>,[12072],{exit_status,0}}
07:31:23.644 [info] Content = <<34,97,100,50,101,56,48,102,34,0>>
[<<"\"ad2e80f\"">>,<<>>]

[msantos]

alcove:stdout/2 is doing a selective receive and returning the next message in the process mailbox. git seems to be flushing its output after each hash so each is delivered as a separate message. Some of the hashes might run together depending on when alcove does a read:

git: hash -> stdout, flush
git: hash -> stdout, flush
alcove <- hash, hash
git: hash -> stdout, flush
alcove <- hash

One way of handling this situation:

stdout(Drv, Chain) ->                                                           
  stdout(Drv, Chain, []).                                                       
stdout(Drv, Chain, Acc) ->                                                      
  case alcove:stdout(Drv, Chain) of                                             
    false ->                                                                    
      case Acc of                                                               
        [] -> false;                                                            
        _ -> lists:reverse(Acc)                                                 
      end;                                                                      
    Out ->                                                                      
      stdout(Drv, Chain, [Out|Acc])                                             
  end.           

But I think you are correct and alcove:stdout/2 should return all pending stdout. This will change the type signature:

% current
-spec stdout(alcove_drv:ref(),[pid_t()]) -> 'false' | binary().                 

% proposed
% [] is returned if no stdout available
-spec stdout(alcove_drv:ref(),[pid_t()]) -> [binary()].                 

I will take a look at making this change!

[neeraj9]

@msantos it makes sense now. I faced a similar situation when reading from java and python processes wherein the logs were not flushed entirely, but my latest test confirmed the issue (ref beamparticle/beamparticle#29).

Thanks for looking.

[msantos]

Change has been pushed, thanks @neeraj9 !

I looked at beamparticle/beamparticle#29. The writes might be buffered so the external process may need to explicitly do an fflush().

These writes can be forced to be flushed by default using stdbuf(1):

stdbuf -o0 /path/to/process

Or by setting some magic environment variables:

LD_PRELOAD=/usr/lib/x86_64-linux-gnu/coreutils/libstdbuf.so
_STDBUF_O=0

[neeraj9]

Thanks @msantos !
I tried multiple techniques to flush the stream within Python or Java application but they do not work predictably, I will test the functionality after your recent changes.