From 469c7d628a87fe2937adf9e5f776b63063c0a65f Mon Sep 17 00:00:00 2001 From: Jameson Nash Date: Mon, 5 Sep 2016 14:58:52 -0400 Subject: [PATCH] fix an inverted return conditional from stale_cachefile also add plenty of helpful debugging information enabled by the environment variable: JULIA_DEBUG_LOADING this bug would cause compilation to become confused and likely tardy at recompiling files when it should that would up with longer dependency chains where one of the files had been updated this is a fix for #18150 --- base/loading.jl | 63 +++++++++++++++++++++++++++++-------------------- base/util.jl | 6 +++++ test/compile.jl | 13 ++++++---- 3 files changed, 51 insertions(+), 31 deletions(-) diff --git a/base/loading.jl b/base/loading.jl index 5034824e6a187..ca6751c2b9620 100644 --- a/base/loading.jl +++ b/base/loading.jl @@ -210,7 +210,6 @@ function _require_search_from_serialized(node::Int, mod::Symbol, sourcepath::Str paths = @fetchfrom node find_all_in_cache_path(mod) end - local restored = nothing, failedpath = "" for path_to_try in paths::Vector{String} if stale_cachefile(sourcepath, path_to_try) continue @@ -220,7 +219,7 @@ function _require_search_from_serialized(node::Int, mod::Symbol, sourcepath::Str if isa(restored, ErrorException) && endswith(restored.msg, " uuid did not match cache file.") # can't use this cache due to a module uuid mismatch, # defer reporting error until after trying all of the possible matches - failedpath = path_to_try + DEBUG_LOADING[] && info(restored, prefix="INFO: JL_DEBUG_LOADING: Failed to load $path_to_try because ") continue end warn("Deserialization checks failed while attempting to load cache from $path_to_try.") @@ -229,13 +228,14 @@ function _require_search_from_serialized(node::Int, mod::Symbol, sourcepath::Str return restored end end - if isa(restored, Exception) - warn("Deserialization checks failed while attempting to load cache from $failedpath.") - warn(restored, prefix="WARNING: ") - end return !isempty(paths) end +# this value is set by `require` based on whether JULIA_DEBUG_LOADING +# is presently defined as an environment variable +# and makes the logic in this file noisier about what it is doing and why +const DEBUG_LOADING = Ref(false) + # to synchronize multiple tasks trying to import/using something const package_locks = Dict{Symbol,Condition}() @@ -341,7 +341,7 @@ during package development as code is modified. function reload(name::AbstractString) if isfile(name) || contains(name,Filesystem.path_separator) # for reload("path/file.jl") just ask for include instead - error("use `include` instead of `reload` to load source files") + error("Use `include` instead of `reload` to load source files.") else # reload("Package") is ok require(Symbol(require_modname(name))) @@ -375,6 +375,7 @@ function require(mod::Symbol) # and is not applied recursively to imported modules: old_track_dependencies = _track_dependencies[] _track_dependencies[] = false + DEBUG_LOADING[] = haskey(ENV, "JULIA_DEBUG_LOADING") global toplevel_load loading = get(package_locks, mod, false) @@ -392,7 +393,7 @@ function require(mod::Symbol) name = string(mod) path = find_in_node_path(name, nothing, 1) if path === nothing - throw(ArgumentError("module $name not found in current path.\nRun `Pkg.add(\"$name\")` to install the $name package.")) + throw(ArgumentError("Module $name not found in current path.\nRun `Pkg.add(\"$name\")` to install the $name package.")) end # attempt to load the module file via the precompile cache locations @@ -410,6 +411,10 @@ function require(mod::Symbol) if mod === concrete_mod warn("""Module $mod with uuid $concrete_uuid is missing from the cache. This may mean module $mod does not support precompilation but is imported by a module that does.""") + if JLOptions().incremental != 0 + # during incremental precompilation, this should be fail-fast + throw(PrecompilableError(false)) + end end end @@ -419,8 +424,9 @@ function require(mod::Symbol) cachefile = compilecache(mod) m = _require_from_serialized(1, mod, cachefile, last) if isa(m, Exception) - warn("Compilecache failed to create a usable precompiled cache file for module $name. Got:") + warn("`compilecache` failed to create a usable precompiled cache file for module $name. Got:") warn(m, prefix="WARNING: ") + # fall-through else return # success end @@ -448,7 +454,7 @@ function require(mod::Symbol) m = _require_from_serialized(1, mod, cachefile, last) if isa(m, Exception) warn(m, prefix="WARNING: ") - error("module $mod declares __precompile__(true) but require failed to create a usable precompiled cache file.") + error("Module $mod declares __precompile__(true) but require failed to create a usable precompiled cache file.") end end finally @@ -629,7 +635,7 @@ function compilecache(name::String) end end # run the expression and cache the result - if isinteractive() + if isinteractive() || DEBUG_LOADING[] if isfile(cachefile) info("Recompiling stale cache file $cachefile for module $name.") else @@ -637,7 +643,7 @@ function compilecache(name::String) end end if !success(create_expr_cache(path, cachefile, concrete_deps)) - error("Failed to precompile $name to $cachefile") + error("Failed to precompile $name to $cachefile.") end return cachefile end @@ -662,9 +668,7 @@ function parse_cache_header(f::IO) n = ntoh(read(f, Int32)) n == 0 && break totbytes -= 4 + n + 8 - if n < 0 # probably means this wasn't a valid file to be read by Base.parse_cache_header - error("EOF while reading cache header") - end + @assert n >= 0 "EOF while reading cache header" # probably means this wasn't a valid file to be read by Base.parse_cache_header push!(files, (String(read(f, n)), ntoh(read(f, Float64)))) end @assert totbytes == 4 "header of cache file appears to be corrupt" @@ -674,7 +678,7 @@ end function parse_cache_header(cachefile::String) io = open(cachefile, "r") try - !isvalid_cache_header(io) && throw(ArgumentError("invalid cache file $cachefile")) + !isvalid_cache_header(io) && throw(ArgumentError("Invalid header in cache file $cachefile.")) return parse_cache_header(io) finally close(io) @@ -697,7 +701,7 @@ end function cache_dependencies(cachefile::String) io = open(cachefile, "r") try - !isvalid_cache_header(io) && throw(ArgumentError("invalid cache file $cachefile")) + !isvalid_cache_header(io) && throw(ArgumentError("Invalid header in cache file $cachefile.")) return cache_dependencies(io) finally close(io) @@ -708,28 +712,35 @@ function stale_cachefile(modpath::String, cachefile::String) io = open(cachefile, "r") try if !isvalid_cache_header(io) + DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile due to it containing an invalid cache header.") return true # invalid cache file end modules, files = parse_cache_header(io) # check if this file is going to provide one of our concrete dependencies - provides_concrete = false - for (mod, uuid) in _concrete_dependencies - if get(modules, mod, UInt64(0)) === uuid - provides_concrete = true - else - return false # cachefile doesn't provide the required version of the dependency + # or if it provides a version that conflicts with our concrete dependencies + # or neither + for (mod, uuid_req) in _concrete_dependencies + uuid = get(modules, mod, UInt64(0)) + if uuid !== UInt64(0) + if uuid === uuid_req + return false # this is the file we want + end + DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile because it provides the wrong uuid (got $uuid) for $mod (want $uuid_req).") + return true # cachefile doesn't provide the required version of the dependency end end - provides_concrete && return false # this is the file we want # now check if this file is fresh relative to its source files if files[1][1] != modpath + DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile because it is for file $(files[1][1])) not file $modpath.") return true # cache file was compiled from a different path end - for (f, ftime) in files + for (f, ftime_req) in files # Issue #13606: compensate for Docker images rounding mtimes - if mtime(f) ∉ (ftime, floor(ftime)) + ftime = mtime(f) + if ftime != ftime_req && ftime != floor(ftime_req) + DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting stale cache file $cachefile (mtime $ftime_req) because file $f (mtime $ftime) is updated.") return true end end diff --git a/base/util.jl b/base/util.jl index ff43543ec6f7e..ad0d06e4d77b5 100644 --- a/base/util.jl +++ b/base/util.jl @@ -383,6 +383,12 @@ warn(io::IO, err::Exception; prefix="ERROR: ", kw...) = warn(err::Exception; prefix="ERROR: ", kw...) = warn(STDERR, err, prefix=prefix; kw...) +info(io::IO, err::Exception; prefix="ERROR: ", kw...) = + info(io, sprint(buf->showerror(buf, err)), prefix=prefix; kw...) + +info(err::Exception; prefix="ERROR: ", kw...) = + info(STDERR, err, prefix=prefix; kw...) + function julia_cmd(julia=joinpath(JULIA_HOME, julia_exename())) opts = JLOptions() cpu_target = unsafe_string(opts.cpu_target) diff --git a/test/compile.jl b/test/compile.jl index f49de8f02d590..d879ef42a0c07 100644 --- a/test/compile.jl +++ b/test/compile.jl @@ -16,6 +16,11 @@ function redirected_stderr(expected) return t end +# this environment variable would affect some error messages being tested below +# so we disable it for the tests below +withenv("JULIA_DEBUG_LOADING"=>"") do +delete!(ENV, "JULIA_DEBUG_LOADING") + olderr = STDERR dir = mktempdir() dir2 = mktempdir() @@ -225,11 +230,7 @@ try @test !Base.stale_cachefile(FooBar1_file, joinpath(dir2, "FooBar1.ji")) @test !Base.stale_cachefile(FooBar_file, joinpath(dir2, "FooBar.ji")) - t = redirected_stderr(""" - WARNING: Deserialization checks failed while attempting to load cache from $(joinpath(dir2, "FooBar1.ji")). - WARNING: Module FooBar uuid did not match cache file. - WARNING: replacing module FooBar1. - """) + t = redirected_stderr("WARNING: replacing module FooBar1.") try reload("FooBar1") finally @@ -331,3 +332,5 @@ let module_name = string("a",randstring()) deleteat!(LOAD_PATH,1) rm(file_name) end + +end # !withenv