Replace Console.WriteLine with proper logging (#195)

This closes #54 by replacing the calls to Console.WriteLine with calls
to calls into Serilog. In cases where Yafc currently produces console
output, it should not change that output.

I was briefly tempted to write the logs to a SQLite database, but
decided not to do that so the logs would be somewhat user-readable. The
log files will look something like this, and will be deleted is they're
over a week old:
[yafc20240717.zip](https://github.com/user-attachments/files/16262567/yafc20240717.zip)

This was prompted by
#178 (comment),
which made me think that it might be useful to log the transitions to
and from the UI thread, along with their call stacks.

@Dorus, I used Serilog instead of Microsoft.Extensions.Logging because
there does not appear to be a Microsoft.Extensions.Logging.File nuget
package. If I'm wrong there, I'm happy to use a
Microsoft.Extensions.Logging-based package instead, as long as it
provides structured logging. That is, something where I can easily
distinguish between ["Disk quota {} set for user {}" and "Disk quota {}
exceed by user
{}"](https://softwareengineering.stackexchange.com/a/312586).

Author: shpaass

Yafc.Model/Analysis/AutomationAnalysis.cs

@@ -1,13 +1,15 @@
-using System;
-using System.Collections.Generic;
+using System.Collections.Generic;
 using System.Diagnostics;
+using Serilog;
+using Yafc.UI;
 
 namespace Yafc.Model {
     public enum AutomationStatus : sbyte {
         NotAutomatable = -1, AutomatableLater = 2, AutomatableNow = 3,
     }
 
     public class AutomationAnalysis : Analysis {
+        private static readonly ILogger logger = Logging.GetLogger<AutomationAnalysis>();
         public static readonly AutomationAnalysis Instance = new AutomationAnalysis();
         public Mapping<FactorioObject, AutomationStatus> automatable;
 
@@ -107,7 +109,7 @@ public override void Compute(Project project, ErrorCollector warnings) {
             }
             state[Database.voidEnergy] = AutomationStatus.NotAutomatable;
 
-            Console.WriteLine("Automation analysis (first pass) finished in " + time.ElapsedMilliseconds + " ms. Unknowns left: " + unknowns);
+            logger.Information("Automation analysis (first pass) finished in {ElapsedTime}ms. Unknowns left: {unknownsRemaining}", time.ElapsedMilliseconds, unknowns);
             if (unknowns > 0) {
                 // TODO run graph analysis if there are any unknowns left... Right now assume they are not automatable
                 foreach (var (k, v) in state) {

Yafc.Model/Analysis/CostAnalysis.cs

@@ -4,9 +4,13 @@
 using System.Linq;
 using System.Text;
 using Google.OrTools.LinearSolver;
+using Serilog;
+using Yafc.UI;
 
 namespace Yafc.Model {
     public class CostAnalysis(bool onlyCurrentMilestones) : Analysis {
+        private readonly ILogger logger = Logging.GetLogger<CostAnalysis>();
+
         public static readonly CostAnalysis Instance = new CostAnalysis(false);
         public static readonly CostAnalysis InstanceAtMilestones = new CostAnalysis(true);
         public static CostAnalysis Get(bool atCurrentMilestones) {
@@ -254,12 +258,12 @@ public override void Compute(Project project, ErrorCollector warnings) {
             }
 
             var result = workspaceSolver.TrySolveWithDifferentSeeds();
-            Console.WriteLine("Cost analysis completed in " + time.ElapsedMilliseconds + " ms. with result " + result);
+            logger.Information("Cost analysis completed in {ElapsedTime}ms with result {result}", time.ElapsedMilliseconds, result);
             float sumImportance = 1f;
             int totalRecipes = 0;
             if (result is Solver.ResultStatus.OPTIMAL or Solver.ResultStatus.FEASIBLE) {
                 float objectiveValue = (float)objective.Value();
-                Console.WriteLine("Estimated modpack cost: " + DataUtils.FormatAmount(objectiveValue * 1000f, UnitOfMeasure.None));
+                logger.Information("Estimated modpack cost: {EstimatedCost}", DataUtils.FormatAmount(objectiveValue * 1000f, UnitOfMeasure.None));
                 foreach (Goods g in Database.goods.all.ExceptExcluded(this)) {
                     if (variables[g] == null) {
                         continue;

Yafc.Model/Analysis/Milestones.cs

@@ -2,11 +2,15 @@
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Linq;
+using Serilog;
+using Yafc.UI;
 
 namespace Yafc.Model {
     public class Milestones : Analysis {
         public static readonly Milestones Instance = new Milestones();
 
+        private static readonly ILogger logger = Logging.GetLogger<Milestones>();
+
         public FactorioObject[] currentMilestones = [];
         private Mapping<FactorioObject, Bits> milestoneResult;
         public Bits lockedMask { get; private set; } = new();
@@ -170,7 +174,7 @@ public void ComputeWithParameters(Project project, ErrorCollector warnings, Fact
                         Array.Resize(ref currentMilestones, nextMilestoneIndex);
                         break;
                     }
-                    Console.WriteLine("Processing milestone " + milestone.locName);
+                    logger.Information("Processing milestone {Milestone}", milestone.locName);
                     processingQueue.Enqueue(milestone.id);
                     processing[milestone] = ProcessingFlags.Initial | ProcessingFlags.InQueue;
                 }
@@ -228,7 +232,7 @@ public void ComputeWithParameters(Project project, ErrorCollector warnings, Fact
 
                     accessibleObjects++;
                     //var obj = Database.objects[elem];
-                    //Console.WriteLine("Added object " + obj.locName + " [" + obj.GetType().Name + "] with mask " + elementFlags.ToString() + " (was " + cur.ToString() + ")");
+                    //logger.Information("Added object {LocalizedName} [{Type}] with mask {MilestoneMask} (was {PreviousMask})", obj.locName, obj.GetType().Name, elementFlags, cur);
                     if (processing[elem] == ProcessingFlags.MilestoneNeedOrdering) {
                         processing[elem] = 0;
                         elementFlags |= nextMilestoneMask;
@@ -270,7 +274,7 @@ public void ComputeWithParameters(Project project, ErrorCollector warnings, Fact
                 warnings.Error("There are some milestones that are not accessible: " + string.Join(", ", milestonesNotReachable.Select(x => x.locName)) + ". You may remove these from milestone list," +
                                MaybeBug + MilestoneAnalysisIsImportant + UseDependencyExplorer, ErrorSeverity.AnalysisWarning);
             }
-            Console.WriteLine("Milestones calculation finished in " + time.ElapsedMilliseconds + " ms.");
+            logger.Information("Milestones calculation finished in {ElapsedTime}ms.", time.ElapsedMilliseconds);
             milestoneResult = result;
         }
 

Yafc.Model/Analysis/TechnologyLoopsFinder.cs

@@ -1,8 +1,11 @@
-using System;
-using System.Linq;
+using System.Linq;
+using Serilog;
+using Yafc.UI;
 
 namespace Yafc.Model {
     public static class TechnologyLoopsFinder {
+        private static readonly ILogger logger = Logging.GetLogger(typeof(TechnologyLoopsFinder));
+
         public static void FindTechnologyLoops() {
             Graph<Technology> graph = new Graph<Technology>();
             foreach (var technology in Database.technologies.all) {
@@ -15,12 +18,12 @@ public static void FindTechnologyLoops() {
             bool loops = false;
             foreach (var m in merged) {
                 if (m.userData.list != null) {
-                    Console.WriteLine("Technology loop: " + string.Join(", ", m.userData.list.Select(x => x.locName)));
+                    logger.Error("Technology loop: {LoopMembers}", string.Join(", ", m.userData.list.Select(x => x.locName)));
                     loops = true;
                 }
             }
             if (!loops) {
-                Console.WriteLine("No technology loops found");
+                logger.Information("No technology loops found.");
             }
         }
     }

Yafc.Model/Data/DataUtils.cs

@@ -8,10 +8,13 @@
 using System.Text;
 using System.Text.RegularExpressions;
 using Google.OrTools.LinearSolver;
+using Serilog;
 using Yafc.UI;
 
 namespace Yafc.Model {
     public static partial class DataUtils {
+        private static readonly ILogger logger = Logging.GetLogger(typeof(DataUtils));
+
         public static readonly FactorioObjectComparer<FactorioObject> DefaultOrdering = new FactorioObjectComparer<FactorioObject>((x, y) => {
             float yFlow = y.ApproximateFlow();
             float xFlow = x.ApproximateFlow();
@@ -183,7 +186,7 @@ public static Solver.ResultStatus TrySolveWithDifferentSeeds(this Solver solver)
             for (int i = 0; i < 3; i++) {
                 Stopwatch time = Stopwatch.StartNew();
                 var result = solver.Solve();
-                Console.WriteLine("Solution completed in " + time.ElapsedMilliseconds + " ms with result " + result);
+                logger.Information("Solution completed in {ElapsedTime}ms with result {result}", time.ElapsedMilliseconds, result);
                 if (result == Solver.ResultStatus.ABNORMAL) {
                     _ = solver.SetSolverSpecificParametersAsString("random_seed:" + random.Next());
                     continue;
@@ -197,12 +200,12 @@ public static Solver.ResultStatus TrySolveWithDifferentSeeds(this Solver solver)
         public static void VerySlowTryFindBadObjective(Solver solver) {
             var vars = solver.variables();
             var obj = solver.Objective();
-            Console.WriteLine(solver.ExportModelAsLpFormat(false));
+            logger.Information(solver.ExportModelAsLpFormat(false));
             foreach (var v in vars) {
                 obj.SetCoefficient(v, 0);
                 var result = solver.Solve();
                 if (result == Solver.ResultStatus.OPTIMAL) {
-                    Console.WriteLine("Infeasibility candidate: " + v.Name());
+                    logger.Warning("Infeasibility candidate: {candidate}", v.Name());
                     return;
                 }
             }

Yafc.Model/Model/AutoPlanner.cs

@@ -3,6 +3,7 @@
 using System.Linq;
 using System.Threading.Tasks;
 using Google.OrTools.LinearSolver;
+using Serilog;
 using Yafc.UI;
 
 #nullable disable warnings // Disabling nullable in legacy code.
@@ -27,6 +28,7 @@ public class AutoPlannerRecipe {
     }
 
     public class AutoPlanner(ModelObject page) : ProjectPageContents(page) {
+        private static readonly ILogger logger = Logging.GetLogger<AutoPlanner>();
         public List<AutoPlannerGoal> goals { get; } = [];
         public HashSet<Recipe> done { get; } = [];
         public HashSet<Goods> roots { get; } = [];
@@ -105,11 +107,11 @@ public override async Task<string> Solve(ProjectPage page) {
             }
 
             var solverResult = bestFlowSolver.Solve();
-            Console.WriteLine("Solution completed with result " + solverResult);
+            logger.Information("Solution completed with result {result}", solverResult);
             if (solverResult is not Solver.ResultStatus.OPTIMAL and not Solver.ResultStatus.FEASIBLE) {
-                Console.WriteLine(bestFlowSolver.ExportModelAsLpFormat(false));
+                logger.Information(bestFlowSolver.ExportModelAsLpFormat(false));
                 this.tiers = null;
-                return "Model have no solution";
+                return "Model has no solution";
             }
 
             Graph<Recipe> graph = new Graph<Recipe>();
@@ -225,7 +227,7 @@ public override async Task<string> Solve(ProjectPage page) {
                         }
                     }
                     remainingNodes.Clear();
-                    Console.WriteLine("Tier creation failure");
+                    logger.Information("Tier creation failure");
                 }
                 tiers.Add(currentTier.Select(x => new AutoPlannerRecipe {
                     recipe = x,

Yafc.Model/Model/ProductionTable.cs

@@ -6,6 +6,7 @@
 using System.Runtime.CompilerServices;
 using System.Threading.Tasks;
 using Google.OrTools.LinearSolver;
+using Serilog;
 using Yafc.UI;
 
 namespace Yafc.Model {
@@ -16,6 +17,7 @@ public struct ProductionTableFlow(Goods goods, float amount, ProductionLink? lin
     }
 
     public class ProductionTable : ProjectPageContents, IComparer<ProductionTableFlow>, IElementGroup<RecipeRow> {
+        private static readonly ILogger logger = Logging.GetLogger<ProductionTable>();
         [SkipSerialization] public Dictionary<Goods, ProductionLink> linkMap { get; } = [];
         List<RecipeRow> IElementGroup<RecipeRow>.elements => recipes;
         [NoUndo]
@@ -408,7 +410,7 @@ private static void AddLinkCoef(Constraint cst, Variable var, ProductionLink lin
 
                 result = productionTableSolver.Solve();
 
-                Console.WriteLine("Solver finished with result " + result);
+                logger.Information("Solver finished with result {result}", result);
                 await Ui.EnterMainThread();
 
                 if (result is Solver.ResultStatus.OPTIMAL or Solver.ResultStatus.FEASIBLE) {

Yafc.Model/Serialization/ErrorCollector.cs

@@ -2,6 +2,8 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Text.Json;
+using Serilog;
+using Yafc.UI;
 
 namespace Yafc.Model {
     public enum ErrorSeverity {
@@ -14,6 +16,7 @@ public enum ErrorSeverity {
     }
 
     public class ErrorCollector {
+        private static readonly ILogger logger = Logging.GetLogger<ErrorCollector>();
         private readonly Dictionary<(string message, ErrorSeverity severity), int> allErrors = [];
         public ErrorSeverity severity { get; private set; }
         public void Error(string message, ErrorSeverity severity) {
@@ -24,7 +27,7 @@ public void Error(string message, ErrorSeverity severity) {
 
             _ = allErrors.TryGetValue(key, out int prevC);
             allErrors[key] = prevC + 1;
-            Console.WriteLine(message);
+            logger.Information(message);
         }
 
         public (string error, ErrorSeverity severity)[] GetArrErrors() {
@@ -54,7 +57,7 @@ public void Exception(Exception exception, string message, ErrorSeverity errorSe
             }
 
             Error(s, errorSeverity);
-            Console.Error.WriteLine(exception.StackTrace);
+            logger.Error(exception, "Exception encountered");
         }
     }
 }

Yafc.Model/Serialization/SerializationMap.cs

@@ -3,6 +3,8 @@
 using System.Diagnostics.CodeAnalysis;
 using System.Reflection;
 using System.Text.Json;
+using Serilog;
+using Yafc.UI;
 
 namespace Yafc.Model {
     [AttributeUsage(AttributeTargets.Property)]
@@ -12,6 +14,7 @@ public class SkipSerializationAttribute : Attribute { }
     public class NoUndoAttribute : Attribute { }
 
     internal abstract class SerializationMap {
+        private static readonly ILogger logger = Logging.GetLogger<SerializationMap>();
         public UndoSnapshot MakeUndoSnapshot(ModelObject target) {
             UndoSnapshotBuilder snapshotBuilder = new(target);
             BuildUndo(target, snapshotBuilder);
@@ -40,6 +43,7 @@ public static SerializationMap GetSerializationMap(Type type) {
     }
 
     internal static class SerializationMap<T> where T : class {
+        private static readonly ILogger logger = Logging.GetLogger(typeof(SerializationMap<T>));
         private static readonly Type? parentType;
         private static readonly ConstructorInfo constructor;
         private static readonly PropertySerializer<T>[] properties;
@@ -308,7 +312,7 @@ public static void PopulateFromJson(T obj, ref Utf8JsonReader reader, Deserializ
                 var property = FindProperty(ref reader, ref lastMatch);
                 if (property == null || lastMatch < constructorProperties) {
                     if (property == null) {
-                        Console.Error.WriteLine("Json has extra property: " + reader.GetString());
+                        logger.Error("Json has extra property: " + reader.GetString());
                     }
 
                     reader.Skip();

Yafc.Parser/Data/FactorioDataDeserializer.cs

@@ -5,13 +5,14 @@
 using System.Runtime.CompilerServices;
 using System.Text;
 using System.Threading.Tasks;
-using System.Xml.Linq;
 using SDL2;
+using Serilog;
 using Yafc.Model;
 using Yafc.UI;
 
 namespace Yafc.Parser {
     internal partial class FactorioDataDeserializer {
+        private static readonly ILogger logger = Logging.GetLogger<FactorioDataDeserializer>();
         private LuaTable raw = null!; // null-forgiving: Initialized at the beginning of LoadData.
         private bool GetRef<T>(LuaTable table, string key, [MaybeNullWhen(false)] out T result) where T : FactorioObject, new() {
             result = null;
@@ -393,7 +394,7 @@ private void DeserializeItem(LuaTable table, ErrorCollector _) {
         }
 
         private Fluid SplitFluid(Fluid basic, int temperature) {
-            Console.WriteLine("Splitting fluid " + basic.name + " at " + temperature);
+            logger.Information("Splitting fluid {FluidName} at {Temperature}", basic.name, temperature);
             basic.variants ??= [basic];
             var copy = basic.Clone();
             copy.SetTemperature(temperature);