Issue with stopping a container

[maleadt]

From JuliaLang/julia@a5758aa#commitcomment-48923479:

Mar 31 01:35:17 amdci8 bash[29029]:       From worker 2:        Error response from daemon: No such container: Percival-WDVmlJXs
Mar 31 01:35:17 amdci8 bash[29029]:       From worker 2:
Mar 31 01:35:19 amdci8 bash[29029]:       From worker 2:        Error response from daemon: No such container: NumericalAlgorithms-FsFmcjW6
Mar 31 01:35:22 amdci8 bash[29029]: [ Info: [Node 2 | 2021-03-31T01:35:22.895]: reporting results for PkgEvalJob JuliaLang/julia@a5758aa [daily]
Mar 31 01:35:22 amdci8 bash[29029]: [ Info: [Node 2 | 2021-03-31T01:35:22.897]: ...generating report...
Mar 31 01:35:22 amdci8 bash[29029]: [ Info: [Node 2 | 2021-03-31T01:35:22.968]: ...tarring data...
Mar 31 01:35:23 amdci8 bash[29029]: [ Info: [Node 2 | 2021-03-31T01:35:23.013]: ...moving /storage/pkgeval/Nanosoldier/workdir/tmpresults to /storage/pkgeval/Nanosoldier/workdir/NanosoldierReports/pkgeval/by_date/2021-03/31...
Mar 31 01:35:23 amdci8 bash[29029]: [ Info: [Node 2 | 2021-03-31T01:35:23.015]: ...pushing /storage/pkgeval/Nanosoldier/workdir/NanosoldierReports/pkgeval/by_date/2021-03/31 to GitHub...
Mar 31 01:35:23 amdci8 bash[29029]:       From worker 2:        [master 779b9ae97c] upload report for PkgEvalJob JuliaLang/julia@a5758aa [daily]
Mar 31 01:35:23 amdci8 bash[29029]:       From worker 2:         3 files changed, 53 insertions(+), 1 deletion(-)
Mar 31 01:35:23 amdci8 bash[29029]:       From worker 2:         create mode 100644 pkgeval/by_date/2021-03/31/data.tar.xz
Mar 31 01:35:23 amdci8 bash[29029]:       From worker 2:         create mode 100644 pkgeval/by_date/2021-03/31/report.md
Mar 31 01:35:23 amdci8 bash[29029]:       From worker 2:        Already up to date.
Mar 31 01:35:28 amdci8 bash[29029]:       From worker 2:        To https://github.com/JuliaCI/NanosoldierReports.git
Mar 31 01:35:28 amdci8 bash[29029]:       From worker 2:           297a357dc0..779b9ae97c  master -> master
Mar 31 01:35:28 amdci8 bash[29029]: ┌ Error: An exception occurred during job execution
Mar 31 01:35:28 amdci8 bash[29029]: │   exception =
Mar 31 01:35:28 amdci8 bash[29029]: │    NanosoldierError: failed to run tests: TaskFailedException:
Mar 31 01:35:28 amdci8 bash[29029]: │    failed process: Process(`docker stop Percival-WDVmlJXs`, ProcessExited(1)) [1]
Mar 31 01:35:28 amdci8 bash[29029]: │
Mar 31 01:35:28 amdci8 bash[29029]: │    Stacktrace:
Mar 31 01:35:28 amdci8 bash[29029]: │     [1] pipeline_error at ./process.jl:525 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [2] run(::Base.CmdRedirect; wait::Bool) at ./process.jl:440
Mar 31 01:35:28 amdci8 bash[29029]: │     [3] run at ./process.jl:438 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [4] kill_container at /storage/pkgeval/dev/PkgEval/src/run.jl:364 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [5] stop at /storage/pkgeval/dev/PkgEval/src/run.jl:167 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [6] #36 at /storage/pkgeval/dev/PkgEval/src/run.jl:234 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [7] lock(::PkgEval.var"#36#44"{String,PkgEval.var"#stop#38"{String},Base.Process}, ::ReentrantLock) at ./lock.jl:161
Mar 31 01:35:28 amdci8 bash[29029]: │     [8] macro expansion at /storage/pkgeval/dev/PkgEval/src/run.jl:231 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [9] (::PkgEval.var"#35#43"{Int64,String,Pipe,PkgEval.var"#stop#38"{String},ReentrantLock,Base.Process})() at ./task.jl:356
Mar 31 01:35:28 amdci8 bash[29029]: │    Stacktrace:
Mar 31 01:35:28 amdci8 bash[29029]: │     [1] wait at ./task.jl:267 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [2] fetch at ./task.jl:282 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [3] run_sandboxed_test(::String, ::NamedTuple{(:name, :uuid, :path, :registry),Tuple{String,Base.UUID,String,String}}; log_limit::Int64, time_limit::Int64, do_depwarns::Bool, kwargs::Base.Iterator
Mar 31 01:35:28 amdci8 bash[29029]: │     [4] macro expansion at /storage/pkgeval/dev/PkgEval/src/run.jl:584 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [5] (::PkgEval.var"#50#57"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}},String,Array{NamedTuple{(:julia, :install, :cache, :pkg),Tuple{VersionNumber,String,String,Nam
Mar 31 01:35:28 amdci8 bash[29029]: │    Stacktrace:
Mar 31 01:35:28 amdci8 bash[29029]: │     [1] sync_end(::Channel{Any}) at ./task.jl:314
Mar 31 01:35:28 amdci8 bash[29029]: │     [2] macro expansion at ./task.jl:333 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [3] run(::Array{VersionNumber,1}, ::Array{Any,1}; ninstances::Int64, retries::Int64, kwargs::Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}) at /storage/pkgeval/dev/PkgEval/s
Mar 31 01:35:28 amdci8 bash[29029]: │     [4] (::Nanosoldier.var"#30#36"{Nanosoldier.PkgEvalJob,Dict{String,VersionNumber},Array{Any,1}})() at /storage/pkgeval/Nanosoldier/src/jobs/PkgEvalJob.jl:231
Mar 31 01:35:28 amdci8 bash[29029]: │     [5] withenv(::Nanosoldier.var"#30#36"{Nanosoldier.PkgEvalJob,Dict{String,VersionNumber},Array{Any,1}}, ::Pair{String,Bool}) at ./env.jl:161
Mar 31 01:35:28 amdci8 bash[29029]: │     [6] execute_tests!(::Nanosoldier.PkgEvalJob, ::Dict{String,Nanosoldier.BuildRef}, ::Dict{String,Array{String,1}}, ::Dict{Any,Any}) at /storage/pkgeval/Nanosoldier/src/jobs/PkgEvalJob.jl:229
Mar 31 01:35:28 amdci8 bash[29029]: │     [7] run(::Nanosoldier.PkgEvalJob) at /storage/pkgeval/Nanosoldier/src/jobs/PkgEvalJob.jl:355
Mar 31 01:35:28 amdci8 bash[29029]: │     [8] (::Distributed.var"#106#108"{Distributed.CallMsg{:call_fetch}})() at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.5/Distributed/src/process_messages.jl:294
Mar 31 01:35:28 amdci8 bash[29029]: │     [9] run_work_thunk(::Distributed.var"#106#108"{Distributed.CallMsg{:call_fetch}}, ::Bool) at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.5/Distributed/src/process_messages.
Mar 31 01:35:28 amdci8 bash[29029]: │     [10] macro expansion at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.5/Distributed/src/process_messages.jl:294 [inlined]
Mar 31 01:35:28 amdci8 bash[29029]: │     [11] (::Distributed.var"#105#107"{Distributed.CallMsg{:call_fetch},Distributed.MsgHeader,Sockets.TCPSocket})() at ./task.jl:356
Mar 31 01:35:28 amdci8 bash[29029]: └ @ Nanosoldier /storage/pkgeval/Nanosoldier/src/jobs/PkgEvalJob.jl:425

Maybe PkgEval decided to stop the container when it was already exiting?

[maleadt]

Actually, I couldn't stop those containers either, so maybe Docker has broken down here (as it has in the past). Not sure how to best deal with this; ignore and continue might result in CPUs being wasted by those zombie containers, and then other runs timing out due to the added CPU load.

[maleadt]

Seems to be happening more often: JuliaLang/julia#40067 (comment)

[maleadt]

I made stopping the container non-fatal, maybe we can spot in the logs why it didn't give the coordinator a minute to gather stats and stop the container while it was still running (this whole design is iffy, but I couldn't find another way to gather stats at the end).

[maleadt]

Now that a build completed, I could inspect the logs:

Network usage:
Could not render usage statistics: KeyError: key "networks" not found
Stacktrace:
 [1] getindex(::Dict{String,Any}, ::String) at ./dict.jl:467
 [2] run_sandboxed_test(::String, ::NamedTuple{(:name, :uuid, :path, :registry),Tuple{String,Base.UUID,String,String}}; log_limit::Int64, time_limit::Int64, do_depwarns::Bool, kwargs::Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol,Symbol},NamedTuple{(:cache, :storage, :cpus),Tuple{String,String,Array{Int64,1}}}}) at /storage/pkgeval/dev/PkgEval/src/run.jl:275
 [3] macro expansion at /storage/pkgeval/dev/PkgEval/src/run.jl:585 [inlined]
 [4] (::PkgEval.var"#50#57"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}},String,Array{NamedTuple{(:julia, :install, :cache, :pkg),Tuple{VersionNumber,String,String,NamedTuple{(:name, :uuid, :path, :registry),Tuple{String,Base.UUID,String,String}}}},1},Array{Union{Nothing, NamedTuple{(:julia, :install, :cache, :pkg),Tuple{VersionNumber,String,String,NamedTuple{(:name, :uuid, :path, :registry),Tuple{String,Base.UUID,String,String}}}}},1},Array{Dates.DateTime,1},PkgEval.var"#stop_work#53"{Array{Union{Nothing, NamedTuple{(:julia, :install, :cache, :pkg),Tuple{VersionNumber,String,String,NamedTuple{(:name, :uuid, :path, :registry),Tuple{String,Base.UUID,String,String}}}}},1},Array{Task,1}},Int64})() at ./task.jl:356

[maleadt]

Actually, no that happens after gathering statistics... I'm going to chalk this up to docker acting up.