From a4e7884284701c4b24307ea4038ffa2d6bea99fd 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 | 59 +++++++++++++++++++++++++++---------------------- base/util.jl | 6 +++++ test/compile.jl | 7 ++---- 3 files changed, 41 insertions(+), 31 deletions(-) diff --git a/base/loading.jl b/base/loading.jl index 5034824e6a187..7e2f1b3e53b78 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,10 +228,6 @@ 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 @@ -240,6 +235,7 @@ end const package_locks = Dict{Symbol,Condition}() # used to optionally track dependencies when requiring a module: +const DEBUG_LOADING = Ref(false) const _concrete_dependencies = Any[] # these dependency versions are "set in stone", and the process should try to avoid invalidating them const _require_dependencies = Any[] # a list of (path, mtime) tuples that are the file dependencies of the module currently being precompiled const _track_dependencies = Ref(false) # set this to true to track the list of file dependencies @@ -341,7 +337,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 +371,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 +389,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 +407,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 +420,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 +450,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 +631,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 +639,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 +664,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 +674,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 +697,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 +708,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..b9ed970b55378 100644 --- a/test/compile.jl +++ b/test/compile.jl @@ -16,6 +16,7 @@ function redirected_stderr(expected) return t end +delete!(ENV, "JULIA_DEBUG_LOADING") # this would affect some error messages being tested below olderr = STDERR dir = mktempdir() dir2 = mktempdir() @@ -225,11 +226,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