Logging after stream finalization AND displaysize missing isopen check

[maleadt]

When printing from finalizers, we're used to see errors relating to streams being closed:

julia> finalizer(x->println(x), "")
""

julia> 
error in running finalizer: ArgumentError(msg="stream is closed or unusable")

With Logging, this becomes worse as certain functions called by the stdlib on the closed streams cause Julia to segfault:

julia> finalizer(x->@info(x), "")
""

julia> 

signal (11): Segmentation fault
in expression starting at no file:0
uv_tty_get_winsize at /home/tbesard/Julia/julia-dev/deps/srccache/libuv-be317349252699670131395f125c3861d793ca86/src/unix/tty.c:243
displaysize at ./stream.jl:403
unknown function (ip: 0x7f7d85e45797)
jl_call_fptr_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:383 [inlined]
jl_call_method_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:402 [inlined]
jl_apply_generic at /home/tbesard/Julia/julia-dev/src/gf.c:2100
#handle_message#2 at /home/tbesard/Julia/julia-dev/build/release/usr/share/julia/site/v0.7/Logging/src/ConsoleLogger.jl:99
unknown function (ip: 0x7f7d85e4ccc9)
jl_call_fptr_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:383 [inlined]
jl_call_method_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:402 [inlined]
jl_apply_generic at /home/tbesard/Julia/julia-dev/src/gf.c:2100
jl_apply at /home/tbesard/Julia/julia-dev/src/julia.h:1529 [inlined]
jl_invoke at /home/tbesard/Julia/julia-dev/src/gf.c:55
handle_message at /home/tbesard/Julia/julia-dev/build/release/usr/share/julia/site/v0.7/Logging/src/ConsoleLogger.jl:90
unknown function (ip: 0x7f7d85e4ba41)
jl_call_fptr_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:383 [inlined]
jl_call_method_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:402 [inlined]
jl_apply_generic at /home/tbesard/Julia/julia-dev/src/gf.c:2100
macro expansion at ./logging.jl:314 [inlined]
#5 at ./REPL[1]:1
jl_call_fptr_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:383 [inlined]
jl_call_method_internal at /home/tbesard/Julia/julia-dev/src/julia_internal.h:402 [inlined]
jl_apply_generic at /home/tbesard/Julia/julia-dev/src/gf.c:2100
jl_apply at /home/tbesard/Julia/julia-dev/src/julia.h:1529 [inlined]
run_finalizer at /home/tbesard/Julia/julia-dev/src/gc.c:112
jl_gc_run_finalizers_in_list at /home/tbesard/Julia/julia-dev/src/gc.c:204
run_finalizers at /home/tbesard/Julia/julia-dev/src/gc.c:240
jl_atexit_hook at /home/tbesard/Julia/julia-dev/src/init.c:260
unknown function (ip: 0xd29726c7a1)
__libc_start_main at /usr/lib/libc.so.6 (unknown line)
unknown function (ip: 0xd29726c609)
Allocations: 1186584 (Pool: 1185691; Big: 893); GC: 2
zsh: segmentation fault  julia --depwarn=no --color=yes

A quick fix would be to reconfigure the global logger at exit to use raw streams, preventing the segfault and making it possible to log rich messages from finalizers:

julia> using Logging

julia> atexit(()->global_logger(Logging.ConsoleLogger(Core.stderr)))

julia> finalizer(x->@info(x), "yay")
"yay"

julia> 
[ Info: yay

... but I'm not sure how that plays into the design of Logging (@c42f), or whether this is acceptable as an atexit hook.

In a related vein, this is also a very useful pattern to be able to log from @generated functions.

[KristofferC]

Getting the same error reported here JuliaLang/Pkg.jl#573.

[vtjnash]

yeah, the patch for this was deleted by #28107 (and may have been closed prematurely also)

[c42f]

@maleadt I think this is a perfect use for the capabilities of the logging system; the ability to switch loggers based on context is what it's all about. On the flip side, switching out the global logger from under the user isn't a great solution (though it's better than crashing!) hmm.

I think the right thing here is to temporarily replace the task local logger with a low level log cache when entering "dangerous" contexts - finalizers, generated functions, certain low level runtime functions, etc. Basically any place where it's dangerous to call into arbitrary user code.

Then when we exit the context, dump the cache of messages through the user's selected logger. The cache might have to be a ring buffer if we're in a context where we can't allocate, I'm not sure there's much we can do about that.

This is very like to the situation I ran into when trying to standardize all logs coming from the runtime - see, for example #25413. Sometimes you're in a context where it's just not permissable to call into arbitrary julia code and the fact I was trying to do so made Jeff understandably leery of the whole project :-)

[c42f]

Hah, I got a bit carried away in the analogy to other similar problems there. All the above being said, temporary logger replacement obviously can't work at exit if we never re-enter a safe context.

As a simple solution I think an atexit hook is pretty acceptable. Though it would be nice for the knowledgeable user to be able to override the safe fallback logger at their option.

As a more general solution, would it be possible to stage the exit process somehow? That seems hard and possibly circular.

[c42f]

Regarding a staged exit, perhaps we could do two rounds of finalization? The first round cleaning up nearly everything except for a few specially rooted objects such as the streams; the second round doing the final cleanup? The second round objects would have to avoid rooting any important objects from the first round, which seems error prone...

[vtjnash]

Closed by #34623