search

invenia / Memento.jl

A flexible logging library for Julia
https://invenia.github.io/Memento.jl/latest
Other
87 stars 14 forks source link

`serialize(io, handler)` in tests no longer throws an exception #184

Closed KristofferC closed 1 year ago

KristofferC commented 2 years ago

The following code no longer throws on Julia 1.8 leading to a test failure:

https://github.com/invenia/Memento.jl/blob/eccf67abe9b139e7ea893dd25f3ef6671c4de8b3/test/handlers.jl#L117-L123

I haven't looked into it in detail but it would be good to understand what changed. Maybe the serializer can handle the conditions that it previously failed on?

PkgEval report: https://s3.amazonaws.com/julialang-reports/nanosoldier/pkgeval/by_hash/f51f24c_vs_2ca8b0c/Memento.primary.log

iamed2 commented 2 years ago

I tried to reproduce the original error in the comment above and I ended up here:

julia> pmap(1:3) do i
           Memento.info(LOGGER, i)  # ERROR: cannot serialize a running Task
       end
ERROR: On worker 2:
MethodError: no method matching info(::Logger, ::Int64)
Closest candidates are:
  info(::Logger, ::AbstractString) at ~/.julia/packages/Memento/Qk5GZ/src/loggers.jl:425 (method too new to be called from this world context.)
Stacktrace:
 [1] #11
   @ ./REPL[21]:2
 [2] #invokelatest#2
   @ ./essentials.jl:729
 [3] invokelatest
   @ ./essentials.jl:727
 [4] #106
   @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:285
 [5] run_work_thunk
   @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:70
 [6] macro expansion
   @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:285 [inlined]
 [7] #105
   @ ./task.jl:476
Stacktrace:
  [1] (::Base.var"#932#934")(x::Task)
    @ Base ./asyncmap.jl:177
  [2] foreach(f::Base.var"#932#934", itr::Vector{Any})
    @ Base ./abstractarray.jl:2769
  [3] maptwice(wrapped_f::Function, chnl::Channel{Any}, worker_tasks::Vector{Any}, c::UnitRange{Int64})
    @ Base ./asyncmap.jl:177
  [4] wrap_n_exec_twice
    @ ./asyncmap.jl:153 [inlined]
  [5] #async_usemap#917
    @ ./asyncmap.jl:103 [inlined]
  [6] #asyncmap#916
    @ ./asyncmap.jl:81 [inlined]
  [7] pmap(f::Function, p::WorkerPool, c::UnitRange{Int64}; distributed::Bool, batch_size::Int64, on_error::Nothing, retry_delays::Vector{Any}, retry_check::Nothing)
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:126
  [8] pmap(f::Function, p::WorkerPool, c::UnitRange{Int64})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:101
  [9] pmap(f::Function, c::UnitRange{Int64}; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:156
 [10] pmap(f::Function, c::UnitRange{Int64})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:156
 [11] top-level scope
    @ REPL[21]:1

julia> pmap(1:3) do i
           Memento.info(LOGGER, string(i))  # ERROR: cannot serialize a running Task
       end
      From worker 2:
      From worker 2:    signal (11): Segmentation fault: 11
      From worker 2:    in expression starting at none:0
      From worker 2:    uv__check_before_write at /workspace/srcdir/libuv/src/unix/stream.c:1406
      From worker 2:    uv_write2 at /workspace/srcdir/libuv/src/unix/stream.c:1449
      From worker 2:    uv_write at /workspace/srcdir/libuv/src/unix/stream.c:1517
      From worker 2:    jl_uv_write at /Users/ericdavies/repos/julia1p8/src/jl_uv.c:478
      From worker 2:    uv_write_async at ./stream.jl:1075
      From worker 2:    uv_write at ./stream.jl:1032
      From worker 2:    unsafe_write at ./stream.jl:1115
      From worker 2:    write at ./strings/io.jl:244 [inlined]
      From worker 2:    print at ./strings/io.jl:246 [inlined]
      From worker 2:    #with_output_color#909 at ./util.jl:107
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    do_apply at /Users/ericdavies/repos/julia1p8/src/builtins.c:725
      From worker 2:    with_output_color##kw at ./util.jl:74
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    do_apply at /Users/ericdavies/repos/julia1p8/src/builtins.c:725
      From worker 2:    #printstyled#910 at ./util.jl:130
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    do_apply at /Users/ericdavies/repos/julia1p8/src/builtins.c:725
      From worker 2:    printstyled##kw at ./util.jl:130
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    emit at /Users/ericdavies/.julia/packages/Memento/Qk5GZ/src/handlers.jl:211
      From worker 2:    log at /Users/ericdavies/.julia/packages/Memento/Qk5GZ/src/handlers.jl:44
      From worker 2:    unknown function (ip: 0x10543ec4d)
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    log at /Users/ericdavies/.julia/packages/Memento/Qk5GZ/src/loggers.jl:366
      From worker 2:    unknown function (ip: 0x105428c1d)
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    _log at /Users/ericdavies/.julia/packages/Memento/Qk5GZ/src/loggers.jl:411
      From worker 2:    log at /Users/ericdavies/.julia/packages/Memento/Qk5GZ/src/loggers.jl:390 [inlined]
      From worker 2:    info at /Users/ericdavies/.julia/packages/Memento/Qk5GZ/src/loggers.jl:426 [inlined]
      From worker 2:    #13 at ./REPL[22]:2
      From worker 2:    unknown function (ip: 0x10543cc05)
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    jl_f__call_latest at /Users/ericdavies/repos/julia1p8/src/builtins.c:769
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    do_apply at /Users/ericdavies/repos/julia1p8/src/builtins.c:725
      From worker 2:    #invokelatest#2 at ./essentials.jl:729
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    do_apply at /Users/ericdavies/repos/julia1p8/src/builtins.c:725
      From worker 2:    invokelatest at ./essentials.jl:727
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    do_apply at /Users/ericdavies/repos/julia1p8/src/builtins.c:725
      From worker 2:    #106 at /Users/ericdavies/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:285
      From worker 2:    run_work_thunk at /Users/ericdavies/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:70
      From worker 2:    macro expansion at /Users/ericdavies/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:285 [inlined]
      From worker 2:    #105 at ./task.jl:476
      From worker 2:    unknown function (ip: 0x1053f291f)
      From worker 2:    _jl_invoke at /Users/ericdavies/repos/julia1p8/src/gf.c:0 [inlined]
      From worker 2:    ijl_apply_generic at /Users/ericdavies/repos/julia1p8/src/gf.c:2522
      From worker 2:    jl_apply at /Users/ericdavies/repos/julia1p8/src/./julia.h:1825 [inlined]
      From worker 2:    start_task at /Users/ericdavies/repos/julia1p8/src/task.c:931
      From worker 2:    Allocations: 15555769 (Pool: 15548895; Big: 6874); GC: 19
Worker 2 terminated.ERROR:
ProcessExitedException(Unhandled Task ERROR: EOFError: read end of file
Stacktrace:
 [1] (::Base.var"#wait_locked#674")(s::Sockets.TCPSocket, buf::IOBuffer, nb::Int64)
   @ Base ./stream.jl:941
 [2] unsafe_read(s::Sockets.TCPSocket, p::Ptr{UInt8}, nb::UInt64)
   @ Base ./stream.jl:950
 [3] unsafe_read
   @ ./io.jl:759 [inlined]
 [4] unsafe_read(s::Sockets.TCPSocket, p::Base.RefValue{NTuple{4, Int64}}, n::Int64)
   @ Base ./io.jl:758
 [5] read!
   @ ./io.jl:760 [inlined]
 [6] deserialize_hdr_raw
   @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/messages.jl:167 [inlined]
 [7] message_handler_loop(r_stream::Sockets.TCPSocket, w_stream::Sockets.TCPSocket, incoming::Bool)
   @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:172
 [8] process_tcp_streams(r_stream::Sockets.TCPSocket, w_stream::Sockets.TCPSocket, incoming::Bool)
   @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/process_messages.jl:133
 [9] (::Distributed.var"#99#100"{Sockets.TCPSocket, Sockets.TCPSocket, Bool})()
   @ Distributed ./task.jl:476
2)
Stacktrace:
  [1] try_yieldto(undo::typeof(Base.ensure_rescheduled))
    @ Base ./task.jl:834
  [2] wait()
    @ Base ./task.jl:894
  [3] wait(c::Base.GenericCondition{ReentrantLock})
    @ Base ./condition.jl:124
  [4] take_buffered(c::Channel{Any})
    @ Base ./channels.jl:416
  [5] take!(c::Channel{Any})
    @ Base ./channels.jl:410
  [6] take!(::Distributed.RemoteValue)
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/remotecall.jl:726
  [7] remotecall_fetch(f::Function, w::Distributed.Worker, args::Int64; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/remotecall.jl:461
  [8] remotecall_fetch(f::Function, w::Distributed.Worker, args::Int64)
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/remotecall.jl:457
  [9] remotecall_fetch(f::Function, id::Int64, args::Int64; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/remotecall.jl:492
 [10] remotecall_fetch(f::Function, id::Int64, args::Int64)
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/remotecall.jl:492
 [11] remotecall_pool(rc_f::Function, f::Function, pool::WorkerPool, args::Int64; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/workerpool.jl:123
 [12] remotecall_pool
    @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/workerpool.jl:121 [inlined]
 [13] #remotecall_fetch#194
    @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/workerpool.jl:229 [inlined]
 [14] remotecall_fetch
    @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/workerpool.jl:229 [inlined]
 [15] #202#203
    @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/workerpool.jl:274 [inlined]
 [16] #202
    @ ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/workerpool.jl:274 [inlined]
 [17] (::Base.var"#922#927"{Distributed.var"#202#204"{Distributed.var"#202#203#205"{WorkerPool, var"#13#14"}}})(r::Base.RefValue{Any}, args::Tuple{Int64})
    @ Base ./asyncmap.jl:100
 [18] macro expansion
    @ ./asyncmap.jl:234 [inlined]
 [19] (::Base.var"#938#939"{Base.var"#922#927"{Distributed.var"#202#204"{Distributed.var"#202#203#205"{WorkerPool, var"#13#14"}}}, Channel{Any}, Nothing})()
    @ Base ./task.jl:476
Stacktrace:
  [1] (::Base.var"#932#934")(x::Task)
    @ Base ./asyncmap.jl:177
  [2] foreach(f::Base.var"#932#934", itr::Vector{Any})
    @ Base ./abstractarray.jl:2769
  [3] maptwice(wrapped_f::Function, chnl::Channel{Any}, worker_tasks::Vector{Any}, c::UnitRange{Int64})
    @ Base ./asyncmap.jl:177
  [4] wrap_n_exec_twice
    @ ./asyncmap.jl:153 [inlined]
  [5] #async_usemap#917
    @ ./asyncmap.jl:103 [inlined]
  [6] #asyncmap#916
    @ ./asyncmap.jl:81 [inlined]
  [7] pmap(f::Function, p::WorkerPool, c::UnitRange{Int64}; distributed::Bool, batch_size::Int64, on_error::Nothing, retry_delays::Vector{Any}, retry_check::Nothing)
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:126
  [8] pmap(f::Function, p::WorkerPool, c::UnitRange{Int64})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:101
  [9] pmap(f::Function, c::UnitRange{Int64}; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:156
 [10] pmap(f::Function, c::UnitRange{Int64})
    @ Distributed ~/repos/julia1p8/usr/share/julia/stdlib/v1.8/Distributed/src/pmap.jl:156
 [11] top-level scope
    @ REPL[22]:1

A few more experiments had processes segfault like that as well. Given that, I don't have time to look further. Maybe someone else will pick it up.

bicepjai commented 2 years ago

I have the same issue

julia> versioninfo()
Julia Version 1.6.6
Commit b8708f954a (2022-03-28 07:17 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-11.0.1 (ORCJIT, haswell)
Environment:
  JULIA_NUM_THREADS = 8
  JULIA_EDITOR = code

(@v1.6) pkg> status Memento
      Status `~/.julia/environments/v1.6/Project.toml`
  [f28f55f0] Memento v1.3.1
iamed2 commented 1 year ago

@KristofferC we tracked it down to https://github.com/JuliaLang/julia/pull/43325! Looks like this is an issue that was fixed.

The pmap has a segfault issue on both 1.6 and 1.8 (I don't know what it is but it's probably something that should be fixed somewhere), but it looks like the task serialization error goes away. I think we're good to make the failure test conditional on older versions.