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