redirect_stdout does not redirect output from ccall

[GregPlowman]

I'm not sure if redirect_stdout is supposed to redirect the output from a ccall, but it appears that it doesn't. I don't know where the output goes but it is not redirected and is not displayed to the terminal.

The docs do suggest that C output should be redirected:

help?> redirect_stdout
search: redirect_stdout redirect_stdin redirect_stderr

  redirect_stdout([stream]) -> (rd, wr)

  Create a pipe to which all C and Julia level stdout output will be redirected. Returns a tuple (rd, wr) representing the pipe ends. Data written to stdout may now be read from the rd end of the
  pipe. The wr end is given for convenience in case the old stdout object was cached by the user and needs to be replaced elsewhere.

Here's an example, using a function from RNGTest package which executes ccall.

First, the normal output without redirection:

Julia-1.1.0> using Random, RNGTest

Julia-1.1.0> rng = RNGTest.wrap(MersenneTwister(), UInt64);

Julia-1.1.0> RNGTest.smallcrushTestU01(rng)

========= Summary results of SmallCrush =========

 Version:          TestU01 1.2.3
 Generator:
 Number of statistics:  15
 Total CPU time:   00:00:12.17

 All tests were passed

Now with redirection:

Julia-1.1.0> rd, wr = redirect_stdout()
(Base.PipeEndpoint(Base.Libc.WindowsRawSocket(0x00000000000003f4) open, 0 bytes waiting), Base.PipeEndpoint(Base.Libc.WindowsRawSocket(0x00000000000003f0) open, 0 bytes waiting))

Julia-1.1.0> println("this is line 1")

Julia-1.1.0> RNGTest.smallcrushTestU01(rng)

Julia-1.1.0> println("this is line 2")

Julia-1.1.0> readline(rd)
"this is line 1"

Julia-1.1.0> readline(rd)
"this is line 2"

[jpsamaroo]

Just a guess (since I don't know how RNGTest's C library works), but is it possible that the library is choosing not to create output because it detects that its stdout pipe is no longer a TTY? This would of course only be a potential explanation if redirect_stdout redirects its stdout fd to a different fd (which I'd imagine is the only option if you also want to capture output from C).

[GregPlowman]

Actually, I can get it to work by using Base.Libc.flush_cstdio()

[StefanKarpinski]

Might be worth thinking about how to make the API easier to use correctly.

[GregPlowman]

Might be worth thinking about how to make the API easier to use correctly.

Do you mean something like redirect_stdout(f, stream, flushc=true)?

This could be implemented by executing Base.Libc.flush_cstdio() after f():

function Base.redirect_stdout(f::Function, stream, flushc::Bool)
    if flushc
        redirect_stdout(()->(f(); Base.Libc.flush_cstdio()), stream)
    else
        redirect_stdout(f, stream)
    end 
end

But I think if output from ccalls are intermingled with Julia output, then the order of output is not preserved unless flushing occurs between each switch of ccall / julia output.

For example, the following prints the ccall output before both Julia printlns

using Random, RNGTest
rng = RNGTest.wrap(MersenneTwister(), UInt64);
filename = tempname()

open(filename, "w") do fileout
    redirect_stdout(fileout) do
        println("Before ccall 1")
        println("Before ccall 2")
        RNGTest.smallcrushTestU01(rng)
        println("After ccall 1")
        println("After ccall 2")
        Base.Libc.flush_cstdio()
    end
end
println(read(filename, String))

========= Summary results of SmallCrush =========

 Version:          TestU01 1.2.3
 Generator:
 Number of statistics:  15
 Total CPU time:   00:00:11.64

 All tests were passed



Before ccall 1
Before ccall 2
After ccall 1
After ccall 2

The only way I know to preserve the output ordering is to flush after each output switch (ccall / julia):

open(filename, "w") do fileout
    redirect_stdout(fileout) do
        println("Before ccall 1")
        println("Before ccall 2")
        flush(stdout)
        RNGTest.smallcrushTestU01(rng)
        Base.Libc.flush_cstdio()
        println("After ccall 1")
        println("After ccall 2")
        flush(stdout)
    end
end

Before ccall 1
Before ccall 2

========= Summary results of SmallCrush =========

 Version:          TestU01 1.2.3
 Generator:
 Number of statistics:  15
 Total CPU time:   00:00:11.89

 All tests were passed



After ccall 1
After ccall 2