replacing with Logging

Author: epolack

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"
@@ -139,16 +140,14 @@ 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"
-Suppressor = "fd094767-a336-5f1f-9728-57cf17d0bbfb"
 Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
 TestItemRunner = "f8b46487-2199-4994-9208-9a1283c18c0a"
 Wannier = "2b19380a-1f7e-4d7d-b1b8-8aa60b3321c9"
 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", "KrylovKit", "Logging", "Plots", "QuadGK", "Random", "Suppressor", "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 @@
+using Logging

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 @@ normest(M) = maximum(abs.(diag(M))) + norm(M - Diagonal(diag(M)))
             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 @@ normest(M) = maximum(abs.(diag(M))) + norm(M - Diagonal(diag(M)))
         # 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 @@ end
         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
@@ -411,7 +407,7 @@ end
                 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 +425,7 @@ end
             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 +435,8 @@ end
         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!

src/scf/scf_callbacks.jl

@@ -67,10 +67,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 +97,8 @@ 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"
 
     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/runtests_runner.jl

@@ -2,7 +2,6 @@
 # This is needed to play nicely with MPI parallelised tests
 #
 using TestItemRunner
-using Suppressor
 
 include("runtests_parser.jl")
 (; base_tag, excluded, included) = parse_test_args()
@@ -31,29 +30,8 @@ function dftk_testfilter(ti)
     end
 end
 
-function run_tests()
-    output = @capture_out try
-        @run_package_tests filter=dftk_testfilter verbose=true
-    catch err
-        Base.showerror(stderr, err, Base.catch_backtrace())
-    end
+using Logging
 
-    lines = split(output, "\n")
-    # Print failed tests.
-    println()
-    for id in findall(occursin.("Test Failed", lines))
-        id_context = id
-        while !isempty(lines[id_context])
-            println(lines[id_context])
-            id_context += 1
-        end
-        println()
-    end
-    # Print the summary.
-    idx = findfirst(occursin.(r"^Test Summary:", lines))
-    if !isnothing(idx)
-        println(join(lines[idx:end], "\n"))
-    end
+with_logger(ConsoleLogger(stdout, LogLevel(1))) do
+    @run_package_tests filter=dftk_testfilter verbose=true
 end
-
-run_tests()