From 6aa2fb2178a4ec67f7e72b1d9eb622408e08b981 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 16 Oct 2020 17:21:54 -0400
Subject: [PATCH] Log precompile _failures_ as well as errors. Pass log level
 through to helper process.
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

This allows users to set the debug log level in the process, not just
via the `JULIA_DEBUG=all` environment variable (we _thought_ we had
enabled the debug messages, but we had not! 😬 ).

Also, adds a log statement for precompile statements that _fail_, not
just those that error. For example, this surfaces this failure:

```julia
┌ Debug: Precompilation failed: precompile(Tuple{typeof(Base.deepcopy_internal), Any, Base.IdDict{Any, Any}})
└ @ Main.anonymous none:31
```

Which is a pattern I've noticed in our own precompilation failures,
where Julia seems to be emitting a precompile statement with an abstract
argument (`Any` in this case, but i've seen others) for a method that is
_not_ marked `@nospecialize`, which causes `precompile()` to fail, since
you cannot normally instantiate a method for abstract types.

So that's a separate issue that we need to dig into, but this PR allows
us to identify issues like these. :)
---
 Project.toml           |  1 +
 src/PackageCompiler.jl | 16 +++++++++++++---
 2 files changed, 14 insertions(+), 3 deletions(-)

diff --git a/Project.toml b/Project.toml
index cc34d3de..d361bae9 100644
--- a/Project.toml
+++ b/Project.toml
@@ -4,6 +4,7 @@ version = "1.2.2"
 
 [deps]
 Libdl = "8f399da3-3557-5675-b5ff-fb832c97cbdb"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f"
 UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4"
 
diff --git a/src/PackageCompiler.jl b/src/PackageCompiler.jl
index 1d78c437..b2cfabb2 100644
--- a/src/PackageCompiler.jl
+++ b/src/PackageCompiler.jl
@@ -4,6 +4,7 @@ using Base: active_project
 using Libdl: Libdl
 using Pkg: Pkg
 using UUIDs: UUID, uuid1
+using Logging
 
 export create_sysimage, create_app, audit_app, restore_default_sysimage
 
@@ -212,6 +213,12 @@ function create_sysimg_object_file(object_file::String, packages::Vector{String}
     precompile_code = """
         # This @eval prevents symbols from being put into Main
         @eval Module() begin
+
+            using Logging
+            # Pass through the user's logging level to the spawned process.
+            logger = ConsoleLogger(stderr, Logging.$(Logging.min_enabled_level(global_logger())))
+            global_logger(logger)
+
             PrecompileStagingArea = Module()
             for (_pkgid, _mod) in Base.loaded_modules
                 if !(_pkgid.name in ("Main", "Core", "Base"))
@@ -226,10 +233,13 @@ function create_sysimg_object_file(object_file::String, packages::Vector{String}
                 # N with a large number seems to work around it.
                 statement = replace(statement, r"Vararg{(.*?), N} where N" => s"Vararg{\1, 100}")
                 try
-                    Base.include_string(PrecompileStagingArea, statement)
-                catch
+                    success = Base.include_string(PrecompileStagingArea, statement)
+                    if !success
+                        @debug "Precompilation failed: \$statement"
+                    end
+                catch e
                     # See julia issue #28808
-                    @debug "failed to execute \$statement"
+                    @debug "Error executing \$statement:\n\$e"
                 end
             end
         end # module