fix an inverted return conditional from stale_cachefile (#18366)

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

@@ -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("JL_DEBUG_LOADING: Failed to load $path_to_try because $(restored.msg)")
                 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}()
 
@@ -275,9 +275,9 @@ immutable PrecompilableError <: Exception
 end
 function show(io::IO, ex::PrecompilableError)
     if ex.isprecompilable
-        print(io, "__precompile__(true) is only allowed in module files being imported")
+        print(io, "Declaring __precompile__(true) is only allowed in module files being imported.")
     else
-        print(io, "__precompile__(false) is not allowed in files that are being precompiled")
+        print(io, "Declaring __precompile__(false) is not allowed in files that are being precompiled.")
     end
 end
 precompilableerror(ex::PrecompilableError, c) = ex.isprecompilable == c
@@ -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("The call to compilecache failed to create a usable precompiled cache file for module $name. Got:")
                 warn(m, prefix="WARNING: ")
+                # fall-through, TODO: disable __precompile__(true) error so that the normal include will succeed
             else
                 return # success
             end
@@ -448,7 +454,8 @@ 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.")
+                # TODO: disable __precompile__(true) error and do normal include instead of error
+                error("Module $mod declares __precompile__(true) but require failed to create a usable precompiled cache file.")
             end
         end
     finally
@@ -645,15 +652,15 @@ 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
             info("Precompiling module $name.")
         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
@@ -678,9 +685,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"
@@ -690,7 +695,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)
@@ -713,7 +718,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)
@@ -724,28 +729,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) has changed.")
                 return true
             end
         end

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)

test/compile.jl

@@ -16,6 +16,10 @@ 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" => nothing ) do
+
 olderr = STDERR
 dir = mktempdir()
 dir2 = mktempdir()
@@ -158,7 +162,7 @@ try
           end
           """)
 
-    t = redirected_stderr("ERROR: LoadError: __precompile__(false) is not allowed in files that are being precompiled\n in __precompile__")
+    t = redirected_stderr("ERROR: LoadError: Declaring __precompile__(false) is not allowed in files that are being precompiled.\n in __precompile__")
     try
         Base.compilecache("Baz") # from __precompile__(false)
         error("__precompile__ disabled test failed")
@@ -225,11 +229,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 +331,5 @@ let module_name = string("a",randstring())
     deleteat!(LOAD_PATH,1)
     rm(file_name)
 end
+
+end # !withenv