From a28cd8b0c7c0066364106322576b58c9187e2d4b Mon Sep 17 00:00:00 2001
From: NATSUME Hiroaki <hiroaki@nature-architects.com>
Date: Tue, 30 Jan 2024 21:27:06 +0900
Subject: [PATCH] Add PythonEngine logging and Serilog console sink

---
 Tunny/Solver/Algorithm.cs      | 21 ++++++++++++++++++---
 Tunny/Solver/Optuna.cs         |  2 +-
 Tunny/Tunny.csproj             |  1 +
 Tunny/UI/LoadingInstruction.cs |  7 ++++++-
 4 files changed, 26 insertions(+), 5 deletions(-)

diff --git a/Tunny/Solver/Algorithm.cs b/Tunny/Solver/Algorithm.cs
index 3b843441..439d8698 100644
--- a/Tunny/Solver/Algorithm.cs
+++ b/Tunny/Solver/Algorithm.cs
@@ -20,6 +20,7 @@
 using Tunny.Storage;
 using Tunny.Type;
 using Tunny.UI;
+using Tunny.Util;
 
 namespace Tunny.Solver
 {
@@ -58,10 +59,12 @@ public void Solve()
             string[] directions = SetDirectionValues(Objective.Length);
             Log.Information($"Optimization started with {nTrials} trials and {timeout} seconds timeout and {samplerType} sampler.");
 
-            PythonEngine.Initialize();
-            IntPtr allowThreadsPtr = PythonEngine.BeginAllowThreads();
+            InitializePythonEngine();
             using (Py.GIL())
             {
+                Log.Debug("Wake Python GIL.");
+                PythonEngine.Exec("a == 1");
+
                 dynamic optuna = Py.Import("optuna");
                 dynamic sampler = SetSamplerSettings(samplerType, optuna, HasConstraints);
                 dynamic storage = Settings.Storage.CreateNewOptunaStorage(false);
@@ -88,8 +91,20 @@ public void Solve()
                     SetResultValues(Objective.Length, study, parameter);
                 }
             }
-            PythonEngine.EndAllowThreads(allowThreadsPtr);
             PythonEngine.Shutdown();
+            Log.Debug("Shutdown PythonEngine.");
+        }
+
+        private static void InitializePythonEngine()
+        {
+            Log.Debug("Check PythonEngine status.");
+            if (PythonEngine.IsInitialized)
+            {
+                PythonEngine.Shutdown();
+                Log.Warning("PythonEngine is unintentionally initialized and therefore shut it down.");
+            }
+            PythonEngine.Initialize();
+            Log.Debug("Initialize PythonEngine.");
         }
 
         private void PreferentialOptimization(int nBatch, dynamic storage, dynamic artifactBackend, out double[] parameter, out TrialGrasshopperItems result, out dynamic study)
diff --git a/Tunny/Solver/Optuna.cs b/Tunny/Solver/Optuna.cs
index d569cb32..9918a337 100644
--- a/Tunny/Solver/Optuna.cs
+++ b/Tunny/Solver/Optuna.cs
@@ -97,7 +97,7 @@ private static void ShowEndMessages(EndState endState)
 
         private static void ShowErrorMessages(Exception e)
         {
-            Log.Error(e.Message);
+            Log.Error("Optimization end with exception: {0}", e.Message);
             TunnyMessageBox.Show(
                 "Tunny runtime error:\n" +
                 "Please send below message (& gh file if possible) to Tunny support.\n" +
diff --git a/Tunny/Tunny.csproj b/Tunny/Tunny.csproj
index 263b3b4f..e5e1463a 100644
--- a/Tunny/Tunny.csproj
+++ b/Tunny/Tunny.csproj
@@ -31,6 +31,7 @@
 
   <ItemGroup>
     <PackageReference Include="Serilog" Version="3.1.1" />
+    <PackageReference Include="Serilog.Sinks.Console" Version="5.0.1" />
     <PackageReference Include="Serilog.Sinks.File" Version="5.0.0" />
     <PackageReference Include="Grasshopper" Version="7.13.21348.13001" IncludeAssets="compile;build" />
     <PackageReference Include="Microsoft.Data.Sqlite.Core" Version="7.0.0" />
diff --git a/Tunny/UI/LoadingInstruction.cs b/Tunny/UI/LoadingInstruction.cs
index 8e9ef21d..31eee30e 100644
--- a/Tunny/UI/LoadingInstruction.cs
+++ b/Tunny/UI/LoadingInstruction.cs
@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using System.Drawing;
+using System.Globalization;
 using System.IO;
 using System.Windows.Forms;
 
@@ -8,6 +9,8 @@
 using Grasshopper.GUI.Canvas;
 using Grasshopper.Kernel;
 
+using Python.Runtime;
+
 using Serilog;
 
 using Tunny.Resources;
@@ -32,7 +35,9 @@ public override GH_LoadingInstruction PriorityLoad()
         private static void InitializeLogger()
         {
             Log.Logger = new LoggerConfiguration()
-                .WriteTo.File(path: TunnyVariables.LogPath + "/log_.txt", rollingInterval: RollingInterval.Day, formatProvider: System.Globalization.CultureInfo.InvariantCulture)
+                .MinimumLevel.Verbose()
+                .WriteTo.Console(formatProvider: CultureInfo.InvariantCulture)
+                .WriteTo.File(path: TunnyVariables.LogPath + "/log_.txt", rollingInterval: RollingInterval.Day, formatProvider: CultureInfo.InvariantCulture)
                 .CreateLogger();
             Log.Information("Tunny is loaded.");
             CheckAndDeleteOldLogFiles();