Using Suppressor to silence tests

Project.toml

@@ -24,6 +24,7 @@ Libxc = "66e17ffc-8502-11e9-23b5-c9248d0eb96d"
 LineSearches = "d3d80556-e9d4-5f37-9878-2ab0fcc64255"
 LinearAlgebra = "37e2e46d-f89d-539d-b4ee-838fcccc9c8e"
 LinearMaps = "7a12625a-238d-50fd-b39a-03d52299707e"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 LoopVectorization = "bdcacae8-1622-11e9-2a5c-532679323890"
 MPI = "da04e1cc-30fd-572f-bb4f-1f8673147195"
 Markdown = "d6f4376e-aef5-505a-96c1-9c027394607a"
@@ -95,6 +96,7 @@ Libxc = "0.3.17"
 LineSearches = "7"
 LinearAlgebra = "1"
 LinearMaps = "3"
+Logging = "1"
 LoopVectorization = "0.12"
 MPI = "0.20.13"
 Markdown = "1"
@@ -139,7 +141,6 @@ IntervalArithmetic = "d1acc4aa-44c8-5952-acd4-ba5d80a2a253"
 JLD2 = "033835bb-8acc-5ee8-8aae-3f567f8a3819"
 JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"
 KrylovKit = "0b1a1467-8014-51b9-945f-bf0ae24f4b77"
-Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80"
 QuadGK = "1fd47b50-473d-5c70-9696-f719f8f3bcdc"
 Random = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c"
@@ -150,4 +151,4 @@ WriteVTK = "64499a7a-5c06-52f2-abe2-ccb03c286192"
 wannier90_jll = "c5400fa0-8d08-52c2-913f-1e3f656c1ce9"
 
 [targets]
-test = ["Test", "TestItemRunner", "ASEconvert", "Aqua", "AtomsIO", "AtomsIOPython", "CUDA", "CUDA_Runtime_jll", "ComponentArrays", "DoubleFloats", "FiniteDiff", "FiniteDifferences", "GenericLinearAlgebra", "IntervalArithmetic", "JLD2", "JSON3", "Logging", "Plots", "QuadGK", "Random", "KrylovKit", "Wannier", "WriteVTK", "wannier90_jll"]
+test = ["Test", "TestItemRunner", "ASEconvert", "Aqua", "AtomsIO", "AtomsIOPython", "CUDA", "CUDA_Runtime_jll", "ComponentArrays", "DoubleFloats", "FiniteDiff", "FiniteDifferences", "GenericLinearAlgebra", "IntervalArithmetic", "JLD2", "JSON3", "KrylovKit", "Plots", "QuadGK", "Random", "Wannier", "WriteVTK", "wannier90_jll"]

src/DFTK.jl

@@ -26,6 +26,7 @@ export Mat3
 export mpi_nprocs
 export mpi_master
 export setup_threading, disable_threading
+include("common/logging.jl")
 include("common/timer.jl")
 include("common/constants.jl")
 include("common/ortho.jl")

src/common/logging.jl

@@ -0,0 +1,21 @@
+using Logging
+#using Preferences
+
+# Bypasses everything to ConsoleLogger but Info which just shows message without any
+# formatting.
+Base.@kwdef struct DFTKLogger <: AbstractLogger
+    io::IO
+    min_level::LogLevel = Info
+    fallback = ConsoleLogger(io, min_level)
+end
+function Logging.handle_message(logger::DFTKLogger, level, msg, args...; kwargs...)
+    io = isopen(logger.io) ? logger.io : stdout  # not sure what happens when docs are run
+    level == Info && return level < logger.min_level ? nothing : println(io, msg)
+    Logging.handle_message(logger.fallback, level, msg, args...; kwargs...)
+end
+Logging.min_enabled_level(logger::DFTKLogger) = logger.min_level
+Logging.shouldlog(::DFTKLogger, args...) = true
+
+# Minimum log level is read from LocalPreferences.toml; defaults to Info.
+#min_level = @load_preference("min_log_level"; default="0")
+default_logger() = DFTKLogger(; io=stdout)

src/common/threading.jl

@@ -19,7 +19,7 @@
         "JULIA_NUM_THREADS is unset and julia does not get the `-t` flag passed."
     )
     @assert n_julia == 1  # To exit in non-master MPI nodes
-    setup_threading(;n_fft=1, n_blas=1)
+    setup_threading(; n_fft=1, n_blas=1)
 end
 
 # Parallelization loop breaking range into chunks.

src/eigen/lobpcg_hyper_impl.jl

@@ -39,10 +39,6 @@
 ## TODO it seems there is a lack of orthogonalization immediately after locking, maybe investigate this to save on some choleskys
 ## TODO debug orthogonalizations when A=I
 
-# TODO Use @debug for this
-# vprintln(args...) = println(args...)  # Uncomment for output
-vprintln(args...) = nothing
-
 using LinearAlgebra
 import LinearAlgebra: BlasFloat
 import Base: *
@@ -180,7 +176,7 @@
             success = true
         catch err
             @assert isa(err, PosDefException)
-            vprintln("fail")
+            @debug "fail"
             # see https://arxiv.org/pdf/1809.11085.pdf for a nice analysis
             # We are not being very clever here; but this should very rarely happen
             # so it should be OK
@@ -220,7 +216,7 @@
         # condR = 1/LAPACK.trcon!('I', 'U', 'N', Array(R))
         condR = normest(R)*norminvR  # in practice this seems to be an OK estimate
 
-        vprintln("Ortho(X) success? $success ", eps(real(T))*condR^2, " < $tol")
+        @debug "Ortho(X) success? $success ", eps(real(T))*condR^2, " < $tol"
 
         # a good a posteriori error is that X'X - I is eps()*κ(R)^2;
         # in practice this seems to be sometimes very overconservative
@@ -289,7 +285,7 @@
         niter > 10 && error("Ortho(X,Y) is failing badly, this should never happen")
         niter += 1
     end
-    vprintln("ortho choleskys: ", ninners)  # get how many Choleskys are performed
+    @debug "ortho choleskys: ", ninners  # get how many Choleskys are performed
 
     # @assert (norm(BY'X)) < tol
     # @assert (norm(X'X-I)) < tol
@@ -325,6 +321,7 @@
 @timing function LOBPCG(A, X, B=I, precon=I, tol=1e-10, maxiter=100;
                         miniter=1, ortho_tol=2eps(real(eltype(X))),
                         n_conv_check=nothing, display_progress=false)
+    old_logger = global_logger(default_logger())
     N, M = size(X)
 
     # If N is too small, we will likely get in trouble
@@ -411,7 +408,7 @@
                 resid_history[i + nlocked, niter+1] = norm(new_R[:, i])
             end
         end
-        vprintln(niter, "   ", resid_history[:, niter+1])
+        @debug niter, "   ", resid_history[:, niter+1]
 
         # it is actually a good question of knowing when to
         # precondition. Here seems sensible, but it could plausibly be
@@ -429,7 +426,7 @@
             for i=nlocked+1:M
                 if resid_history[i, niter+1] < tol
                     nlocked += 1
-                    vprintln("locked $nlocked")
+                    @debug "locked $nlocked"
                 else
                     # We lock in order, assuming that the lowest
                     # eigenvectors converge first; might be tricky otherwise
@@ -439,8 +436,8 @@
         end
 
         if display_progress
-            println("Iter $niter, converged $(nlocked)/$(n_conv_check), resid ",
-                    norm(resid_history[1:n_conv_check, niter+1]))
+            @info "Iter $niter, converged $(nlocked)/$(n_conv_check), resid " *
+                  "$(norm(resid_history[1:n_conv_check, niter+1]))"
         end
 
         if nlocked >= n_conv_check  # Converged!
@@ -534,6 +531,7 @@
         niter < maxiter || break
         niter = niter + 1
     end
+    global_logger(old_logger)
 
     final_retval(full_X, full_AX, full_BX, resid_history, maxiter, n_matvec)
 end

src/scf/scf_callbacks.jl

@@ -38,6 +38,7 @@ function ScfDefaultCallback(; show_damping=true, show_time=true)
     ScfDefaultCallback(show_damping, show_time, Ref(0))
 end
 function (cb::ScfDefaultCallback)(info)
+    old_logger = global_logger(default_logger())
     # If first iteration clear a potentially cached previous time
     info.n_iter ≤ 1 && (cb.prev_time[] = 0)
 
@@ -67,10 +68,10 @@ function (cb::ScfDefaultCallback)(info)
         label_damp = show_damp ? ("   α   ", "   ----") : ("", "")
         label_diag = show_diag ? ("   Diag", "   ----") : ("", "")
         label_time = show_time ? ("   Δtime", "   ------") : ("", "")
-        @printf "n     Energy            log10(ΔE)   log10(Δρ)"
-        println(label_magn[1], label_damp[1], label_diag[1], label_time[1])
-        @printf "---   ---------------   ---------   ---------"
-        println(label_magn[2], label_damp[2], label_diag[2], label_time[2])
+        @info "n     Energy            log10(ΔE)   log10(Δρ)" *
+              "$(label_magn[1]) $(label_damp[1]) $(label_diag[1]) $(label_time[1])"
+        @info "---   ---------------   ---------   ---------" *
+              "$(label_magn[2]) $(label_damp[2]) $(label_diag[2]) $(label_time[2])"
     end
     E    = isnothing(info.energies) ? Inf : info.energies.total
     magn = sum(spin_density(info.ρout)) * info.basis.dvol
@@ -97,8 +98,9 @@ function (cb::ScfDefaultCallback)(info)
     αstr = ""
     show_damp && (αstr = isnan(info.α) ? "       " : @sprintf "  % 4.2f" info.α)
 
-    @printf "% 3d   %s   %s   %s" info.n_iter Estr ΔE Δρstr
-    println(Mstr, αstr, diagstr, tstr)
+    line = @sprintf "% 3d   %s   %s   %s" info.n_iter Estr ΔE Δρstr
+    @info line * "$Mstr $αstr $diagstr $tstr"
+    global_logger(old_logger)
 
     flush(stdout)
     info

src/workarounds/forwarddiff_rules.jl

@@ -209,7 +209,7 @@ function self_consistent_field(basis_dual::PlaneWaveBasis{T};
     end
 
     ## Implicit differentiation
-    response.verbose && println("Solving response problem")
+    response.verbose && @info "Solving response problem"
     δresults = ntuple(ForwardDiff.npartials(T)) do α
         δHextψ = [ForwardDiff.partials.(δHextψk, α) for δHextψk in Hψ_dual]
         solve_ΩplusK_split(scfres, -δHextψ; tol=last(scfres.history_Δρ), response.verbose)

test/forwarddiff.jl

@@ -3,6 +3,7 @@
     using DFTK
     using ForwardDiff
     using LinearAlgebra
+    using Logging
     silicon = TestCases.silicon
 
     function compute_force(ε1, ε2; metal=false, tol=1e-10)
@@ -17,7 +18,7 @@
         end
         basis = PlaneWaveBasis(model; Ecut=5, kgrid=[2, 2, 2], kshift=[0, 0, 0])
 
-        response     = ResponseOptions(; verbose=true)
+        response     = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info)
         is_converged = DFTK.ScfConvergenceForce(tol)
         scfres = self_consistent_field(basis; is_converged, response)
         compute_forces_cart(scfres)
@@ -61,6 +62,7 @@ end
     using ForwardDiff
     using LinearAlgebra
     using ComponentArrays
+    using Logging
     aluminium = TestCases.aluminium
 
     function compute_band_energies(ε::T) where {T}
@@ -76,9 +78,10 @@ end
         basis = PlaneWaveBasis(model; Ecut=5, kgrid=[2, 2, 2], kshift=[0, 0, 0])
 
         is_converged = DFTK.ScfConvergenceDensity(1e-10)
+        response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info)
         scfres = self_consistent_field(basis; is_converged, mixing=KerkerMixing(),
                                        nbandsalg=FixedBands(; n_bands_converge=10),
-                                       damping=0.6, response=ResponseOptions(; verbose=true))
+                                       damping=0.6, response)
 
         ComponentArray(
            eigenvalues=stack([ev[1:10] for ev in scfres.eigenvalues]),
@@ -103,6 +106,7 @@ end
     using LinearAlgebra
     using ComponentArrays
     using DftFunctionals
+    using Logging
     silicon = TestCases.silicon
 
     function compute_force(ε1::T) where {T}
@@ -115,8 +119,8 @@ end
         basis = PlaneWaveBasis(model; Ecut=5, kgrid=[2, 2, 2], kshift=[0, 0, 0])
 
         is_converged = DFTK.ScfConvergenceDensity(1e-10)
-        scfres = self_consistent_field(basis; is_converged,
-                                       response=ResponseOptions(; verbose=true))
+        response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info)
+        scfres = self_consistent_field(basis; is_converged, response)
         compute_forces_cart(scfres)
     end
 
@@ -146,6 +150,7 @@ end
     using DFTK
     using ForwardDiff
     using LinearAlgebra
+    using Logging
 
     function compute_force(ε::T) where {T}
         # solve the 1D Gross-Pitaevskii equation with ElementGaussian potential
@@ -160,8 +165,8 @@ end
         basis = PlaneWaveBasis(model; Ecut=500, kgrid=(1, 1, 1))
         ρ = zeros(Float64, basis.fft_size..., 1)
         is_converged = DFTK.ScfConvergenceDensity(1e-10)
-        scfres = self_consistent_field(basis; ρ, is_converged,
-                                       response=ResponseOptions(; verbose=true))
+        response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info)
+        scfres = self_consistent_field(basis; ρ, is_converged, response)
         compute_forces_cart(scfres)
     end
     derivative_ε = let ε = 1e-5

test/printing.jl

@@ -3,6 +3,8 @@
 # rather to ensure that the code does not randomly stop working.
 @testitem "Test printing" setup=[TestCases] begin
     using DFTK
+    using Logging
+
     magnesium = TestCases.magnesium
 
     function test_basis_printing(; modelargs=(; temperature=1e-3),
@@ -11,14 +13,16 @@
                           disable_electrostatics_check=true, modelargs...)
         basis = PlaneWaveBasis(model; basisargs...)
 
-        println(model)
-        show(stdout, "text/plain", model)
+        io = DFTK.default_logger().min_level > Info ? devnull : stdout
+
+        @info model
+        show(io, "text/plain", model)
 
-        println(basis)
-        show(stdout, "text/plain", basis)
+        @info basis
+        show(io, "text/plain", basis)
 
-        println(basis.kpoints[1])
-        show(stdout, "text/plain", basis.kpoints[1])
+        @info basis.kpoints[1]
+        show(io, "text/plain", basis.kpoints[1])
 
         basis
     end
@@ -28,8 +32,10 @@
         scfres = self_consistent_field(basis; nbandsalg=FixedBands(; n_bands_converge=6),
                                        tol=1e-3)
 
-        println(scfres.energies)
-        show(stdout, "text/plain", scfres.energies)
+        io = DFTK.default_logger().min_level > Info ? devnull : stdout
+
+        @info scfres.energies
+        show(io, "text/plain", scfres.energies)
     end
 
     test_scfres_printing()

test/runtests_runner.jl

@@ -29,4 +29,11 @@ function dftk_testfilter(ti)
         return false
     end
 end
+
+using Logging
+using DFTK
+
+# Don't print anything below or at warning level.
+DFTK.default_logger() = DFTK.DFTKLogger(; io=stdout, min_level=LogLevel(1001))
+#@set_preferences!("min_log_level" => "1001"; export_prefs=false)
 @run_package_tests filter=dftk_testfilter verbose=true