Use same logging format in Python and Julia

src/julia/Project.toml

@@ -8,8 +8,10 @@ CPLEX = "a076750e-1247-5638-91d2-ce28b192dca0"
 CPLEXW = "cfecb002-79c2-11e9-35be-cb59aa640f85"
 Gurobi = "2e9cd046-0924-5485-92f1-d5272153d98b"
 JuMP = "4076af6c-e467-56ae-b986-b466b2749572"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 MathOptInterface = "b8f27783-ece8-5eb3-8dc8-9495eed66fee"
 PackageCompiler = "9b87118b-4619-50d2-8e1e-99f35a4d4d9d"
+Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7"
 PyCall = "438e738f-606a-5dbb-bf0a-cddfbfd45ab0"
 Revise = "295af30f-e4ad-537b-8983-00126c2a3abe"
 Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"

src/julia/src/MIPLearn.jl

@@ -4,6 +4,7 @@
 
 __precompile__(false)
 module MIPLearn
+
 using PyCall
 miplearn = pyimport("miplearn")
 Instance = miplearn.Instance
@@ -13,6 +14,8 @@ module MIPLearn
 
 include("jump_solver.jl")
 include("knapsack.jl")
+include("log.jl")
 
 export Instance, LearningSolver, InternalSolver, JuMPSolver, BenchmarkRunner
-end
+
+end # module

src/julia/src/jump_solver.jl

@@ -51,7 +51,6 @@ function optimize_and_capture_output!(model; tee::Bool=false)
         end
         return log
     end
-    JuMP.unset_silent(model)
     JuMP.optimize!(model)
     sleep(1)
     redirect_stdout(original_stdout)

src/julia/src/log.jl

@@ -0,0 +1,62 @@
+import Logging: min_enabled_level, shouldlog, handle_message
+using Base.CoreLogging, Logging, Printf
+
+struct TimeLogger <: AbstractLogger
+    initial_time::Float64
+    file::Union{Nothing, IOStream}
+    screen_log_level
+    io_log_level
+end
+
+function TimeLogger(;
+                    initial_time::Float64,
+                    file::Union{Nothing, IOStream} = nothing,
+                    screen_log_level = CoreLogging.Info,
+                    io_log_level = CoreLogging.Info,
+                   ) :: TimeLogger
+    return TimeLogger(initial_time, file, screen_log_level, io_log_level)
+end
+
+min_enabled_level(logger::TimeLogger) = logger.io_log_level
+shouldlog(logger::TimeLogger, level, _module, group, id) = true
+
+function handle_message(logger::TimeLogger,
+                        level,
+                        message,
+                        _module,
+                        group,
+                        id,
+                        filepath,
+                        line;
+                        kwargs...)
+    elapsed_time = time() - logger.initial_time
+    time_string = @sprintf("[%12.3f] ", elapsed_time)
+    
+    if level >= Logging.Error
+        color = :light_red
+    elseif level >= Logging.Warn
+        color = :light_yellow
+    else
+        color = :light_green
+    end
+    
+    if level >= logger.screen_log_level
+        printstyled(time_string, color=color)
+        println(message)
+    end
+    if logger.file != nothing && level >= logger.io_log_level
+        write(logger.file, time_string)
+        write(logger.file, message)
+        write(logger.file, "\n")
+        flush(logger.file)
+    end
+end
+
+function setup_logger()
+    initial_time = time()
+    global_logger(TimeLogger(initial_time=initial_time))
+    miplearn = pyimport("miplearn")
+    miplearn.setup_logger(initial_time)
+end
+
+export TimeLogger

src/julia/test/runtests.jl

@@ -3,10 +3,9 @@
 #  Released under the modified BSD license. See COPYING.md for more details.
 
 using Test
-using PyCall
+using MIPLearn
 
-logging = pyimport("logging")
-logging.basicConfig(format="%(levelname)10s %(message)s", level=logging.INFO)
+MIPLearn.setup_logger()
 
 @testset "MIPLearn" begin
     include("jump_solver_test.jl")

src/python/miplearn/__init__.py

@@ -28,3 +28,5 @@ from .solvers.pyomo.gurobi import GurobiPyomoSolver
 from .solvers.guroby import GurobiSolver
 from .solvers.internal import InternalSolver
 from .solvers.learning import LearningSolver
+
+from .log import setup_logger

src/python/miplearn/log.py

@@ -0,0 +1,37 @@
+#  MIPLearn: Extensible Framework for Learning-Enhanced Mixed-Integer Optimization
+#  Copyright (C) 2020, UChicago Argonne, LLC. All rights reserved.
+#  Released under the modified BSD license. See COPYING.md for more details.
+
+from datetime import timedelta
+import logging
+import time
+
+log_colors = {
+    "green":  '\033[92m',
+    "yellow": '\033[93m',
+    "red":    '\033[91m',
+    "reset":  '\033[0m',
+}
+
+class TimeFormatter():
+    def __init__(self, start_time):
+        self.start_time = start_time
+
+    def format(self, record):
+        if record.levelno >= logging.ERROR:
+            color = log_colors["red"]
+        elif record.levelno >= logging.WARNING:
+            color = log_colors["yellow"]
+        else:
+            color = log_colors["green"]
+        return "%s[%12.3f]%s %s" % (color,
+                                    record.created - self.start_time,
+                                    log_colors["reset"],
+                                    record.getMessage())
+
+def setup_logger(start_time):
+    handler = logging.StreamHandler()
+    handler.setFormatter(TimeFormatter(start_time))
+    logging.getLogger().addHandler(handler)
+    logging.getLogger("miplearn").setLevel(logging.INFO)
+    lg = logging.getLogger("miplearn")