Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Standardise logging calls #6099

Open
wants to merge 3 commits into
base: master
Choose a base branch
from
Open

Standardise logging calls #6099

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
e6320b2
Log the calling class, and values, and value changes
3047256 Dec 31, 2023
a486022
Add tests for the new logs
3047256 Dec 31, 2023
8a2da3b
Include quotes for values
3047256 Dec 31, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
66 changes: 66 additions & 0 deletions osu.Framework.Tests/IO/TestLogging.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
#nullable disable

using System;
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using NUnit.Framework;
Expand Down Expand Up @@ -79,6 +80,71 @@ void logTest(LogEntry entry)
Logger.NewEntry -= logTest;
}

[Test]
public void TestClassNameLogging()
{
void logTest(LogEntry entry)
{
Assert.That(entry.Message, Does.StartWith(nameof(TestLogging)));
}

using (var storage = new TemporaryNativeStorage(nameof(TestExceptionLogging)))
{
Logger.Storage = storage;
Logger.Enabled = true;

Logger.NewEntry += logTest;
Logger.Error(new TestException(), "message");
Logger.Error(new TestException(), "message", "test");
Logger.Log("message");
Logger.Log("message", "test");
Logger.LogPrint("message");
Logger.LogPrint("message", "test");
Logger.NewEntry -= logTest;

Logger.Enabled = false;
Logger.Flush();
}
}

[Test]
public void TestValueLogging()
{
Dictionary<object, object> valueChanges = new Dictionary<object, object>() { [""] = "osu!", ["EnteringMode"] = "TopLevel" };
Dictionary<string, object> values = new Dictionary<string, object>() { ["beatmap"] = 186, ["ruleset"] = 0, };

void logTest(LogEntry entry)
{
foreach (var valueChange in valueChanges)
{
Assert.That(entry.Message, Contains.Substring($"from: \"{valueChange.Key}\" to: \"{valueChange.Value}\""));
}

foreach (var value in values)
{
Assert.That(entry.Message, Contains.Substring($"{value.Key}:\"{value.Value}\""));
}
}

using (var storage = new TemporaryNativeStorage(nameof(TestExceptionLogging)))
{
Logger.Storage = storage;
Logger.Enabled = true;

Logger.NewEntry += logTest;
Logger.Error(new TestException(), "message", valueChanges: valueChanges, values: values);
Logger.Error(new TestException(), "message", "test", valueChanges: valueChanges, values: values);
Logger.Log("message", valueChanges: valueChanges, values: values);
Logger.Log("message", "test", valueChanges: valueChanges, values: values);
Logger.LogPrint("message", valueChanges: valueChanges, values: values);
Logger.LogPrint("message", "test", valueChanges: valueChanges, values: values);
Logger.NewEntry -= logTest;
Comment on lines +137 to +141
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

dunno this is all a mess to me dunno what anything means in the args.

I have doubts about how useful this change is.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, to clarify I followed the suggestion made here: ppy/osu#10682 (comment) to try and enforce the standard through the logger in the Framework.

Assuming you were referring to the functionality itself and not the test, looking back, I can see why the new arguments do not convey what it's supposed to be for (I guess the namings and/or having two separate dictionary arguments for similar but different purposes). Therefore, perhaps for the sake of the issue, I could simply just manually change up the relevant log lines in osu to follow the said standard without having anything additional in Framework?

Please advise. Thank you


Logger.Enabled = false;
Logger.Flush();
}
}

[Test]
public void TestUnhandledIgnoredException()
{
Expand Down
101 changes: 78 additions & 23 deletions osu.Framework/Logging/Logger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Globalization;
using System.IO;
using System.Linq;
Expand Down Expand Up @@ -155,9 +156,11 @@ public static string ApplyFilters(string message)
/// <param name="description">The description of the error that should be logged with the exception.</param>
/// <param name="target">The logging target (file).</param>
/// <param name="recursive">Whether the inner exceptions of the given exception <paramref name="e"/> should be logged recursively.</param>
public static void Error(Exception e, string description, LoggingTarget target = LoggingTarget.Runtime, bool recursive = false)
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public static void Error(Exception e, string description, LoggingTarget target = LoggingTarget.Runtime, bool recursive = false, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
error(e, description, target, null, recursive);
error(e, description, target, null, recursive, valueChanges: valueChanges, values: values);
}

/// <summary>
Expand All @@ -167,17 +170,29 @@ public static void Error(Exception e, string description, LoggingTarget target =
/// <param name="description">The description of the error that should be logged with the exception.</param>
/// <param name="name">The logger name (file).</param>
/// <param name="recursive">Whether the inner exceptions of the given exception <paramref name="e"/> should be logged recursively.</param>
public static void Error(Exception e, string description, string name, bool recursive = false)
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public static void Error(Exception e, string description, string name, bool recursive = false, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
error(e, description, null, name, recursive);
error(e, description, null, name, recursive, valueChanges: valueChanges, values: values);
}

private static void error(Exception e, string description, LoggingTarget? target, string name, bool recursive)
/// <summary>
/// Logs the given exception with the given description to the logger with the given name.
/// </summary>
/// <param name="e">The exception that should be logged.</param>
/// <param name="description">The description of the error that should be logged with the exception.</param>
/// <param name="target">The logging target (file).</param>
/// <param name="name">The logger name (file).</param>
/// <param name="recursive">Whether the inner exceptions of the given exception <paramref name="e"/> should be logged recursively.</param>
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
private static void error(Exception e, string description, LoggingTarget? target, string name, bool recursive, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
log($@"{description}", target, name, LogLevel.Error, e);
log($@"{description}", target, name, LogLevel.Error, e, valueChanges: valueChanges, values: values);

if (recursive && e.InnerException != null)
error(e.InnerException, $"{description} (inner)", target, name, true);
error(e.InnerException, $"{description} (inner)", target, name, true, valueChanges: valueChanges, values: values);
}

/// <summary>
Expand All @@ -187,9 +202,11 @@ private static void error(Exception e, string description, LoggingTarget? target
/// <param name="target">The logging target (file).</param>
/// <param name="level">The verbosity level.</param>
/// <param name="outputToListeners">Whether the message should be sent to listeners of <see cref="Debug"/> and <see cref="Console"/>. True by default.</param>
public static void Log(string message, LoggingTarget target = LoggingTarget.Runtime, LogLevel level = LogLevel.Verbose, bool outputToListeners = true)
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public static void Log(string message, LoggingTarget target = LoggingTarget.Runtime, LogLevel level = LogLevel.Verbose, bool outputToListeners = true, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
log(message, target, null, level, outputToListeners: outputToListeners);
log(message, target, null, level, outputToListeners: outputToListeners, valueChanges: valueChanges, values: values);
}

/// <summary>
Expand All @@ -199,19 +216,32 @@ public static void Log(string message, LoggingTarget target = LoggingTarget.Runt
/// <param name="name">The logger name (file).</param>
/// <param name="level">The verbosity level.</param>
/// <param name="outputToListeners">Whether the message should be sent to listeners of <see cref="Debug"/> and <see cref="Console"/>. True by default.</param>
public static void Log(string message, string name, LogLevel level = LogLevel.Verbose, bool outputToListeners = true)
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public static void Log(string message, string name, LogLevel level = LogLevel.Verbose, bool outputToListeners = true, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
log(message, null, name, level, outputToListeners: outputToListeners);
log(message, null, name, level, outputToListeners: outputToListeners, valueChanges: valueChanges, values: values);
}

private static void log(string message, LoggingTarget? target, string loggerName, LogLevel level, Exception exception = null, bool outputToListeners = true)
/// <summary>
/// Log an arbitrary string to the specified logging target.
/// </summary>
/// <param name="message">The message to log. Can include newline (\n) characters to split into multiple lines.</param>
/// <param name="target">The logging target (file).</param>
/// <param name="loggerName">The logger name (file).</param>
/// <param name="level">The verbosity level.</param>
/// <param name="exception">An optional related exception.</param>
/// <param name="outputToListeners">Whether the message should be sent to listeners of <see cref="Debug"/> and <see cref="Console"/>. True by default.</param>
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
private static void log(string message, LoggingTarget? target, string loggerName, LogLevel level, Exception exception = null, bool outputToListeners = true, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
try
{
if (target.HasValue)
GetLogger(target.Value).Add(message, level, exception, outputToListeners);
GetLogger(target.Value).Add(message, level, exception, outputToListeners, valueChanges, values);
else
GetLogger(loggerName).Add(message, level, exception, outputToListeners);
GetLogger(loggerName).Add(message, level, exception, outputToListeners, valueChanges, values);
}
catch
{
Expand All @@ -224,12 +254,14 @@ private static void log(string message, LoggingTarget? target, string loggerName
/// <param name="message">The message to log. Can include newline (\n) characters to split into multiple lines.</param>
/// <param name="target">The logging target (file).</param>
/// <param name="level">The verbosity level.</param>
public static void LogPrint(string message, LoggingTarget target = LoggingTarget.Runtime, LogLevel level = LogLevel.Verbose)
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public static void LogPrint(string message, LoggingTarget target = LoggingTarget.Runtime, LogLevel level = LogLevel.Verbose, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
if (Enabled && DebugUtils.IsDebugBuild)
System.Diagnostics.Debug.Print(message);

Log(message, target, level);
Log(message, target, level, valueChanges: valueChanges, values: values);
}

/// <summary>
Expand All @@ -238,12 +270,14 @@ public static void LogPrint(string message, LoggingTarget target = LoggingTarget
/// <param name="message">The message to log. Can include newline (\n) characters to split into multiple lines.</param>
/// <param name="name">The logger name (file).</param>
/// <param name="level">The verbosity level.</param>
public static void LogPrint(string message, string name, LogLevel level = LogLevel.Verbose)
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public static void LogPrint(string message, string name, LogLevel level = LogLevel.Verbose, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
if (Enabled && DebugUtils.IsDebugBuild)
System.Diagnostics.Debug.Print(message);

Log(message, name, level);
Log(message, name, level, valueChanges: valueChanges, values: values);
}

/// <summary>
Expand Down Expand Up @@ -275,12 +309,14 @@ public static Logger GetLogger(string name)
/// Logs a new message with the <see cref="LogLevel.Debug"/> and will only be logged if your project is built in the Debug configuration. Please note that the default setting for <see cref="Level"/> is <see cref="LogLevel.Verbose"/> so unless you increase the <see cref="Level"/> to <see cref="LogLevel.Debug"/> messages printed with this method will not appear in the output.
/// </summary>
/// <param name="message">The message that should be logged.</param>
public void Debug(string message = @"")
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public void Debug(string message = @"", Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
if (!DebugUtils.IsDebugBuild)
return;

Add(message, LogLevel.Debug);
Add(message, LogLevel.Debug, valueChanges: valueChanges, values: values);
}

/// <summary>
Expand All @@ -290,14 +326,16 @@ public void Debug(string message = @"")
/// <param name="level">The verbosity level.</param>
/// <param name="exception">An optional related exception.</param>
/// <param name="outputToListeners">Whether the message should be sent to listeners of <see cref="Debug"/> and <see cref="Console"/>. True by default.</param>
public void Add(string message = @"", LogLevel level = LogLevel.Verbose, Exception exception = null, bool outputToListeners = true) =>
add(message, level, exception, outputToListeners && OutputToListeners);
/// <param name="valueChanges">Value changes to be indicated in the logs</param>
/// <param name="values">Value to be shown in the logs</param>
public void Add(string message = @"", LogLevel level = LogLevel.Verbose, Exception exception = null, bool outputToListeners = true, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null) =>
add(message, level, exception, outputToListeners && OutputToListeners, valueChanges, values);

private readonly RollingTime debugOutputRollingTime = new RollingTime(50, 10000);

private readonly Queue<string> pendingFileOutput = new Queue<string>();

private void add(string message = @"", LogLevel level = LogLevel.Verbose, Exception exception = null, bool outputToListeners = true)
private void add(string message = @"", LogLevel level = LogLevel.Verbose, Exception exception = null, bool outputToListeners = true, Dictionary<object, object> valueChanges = null, Dictionary<string, object> values = null)
{
if (!Enabled || level < Level)
return;
Expand All @@ -308,6 +346,23 @@ private void add(string message = @"", LogLevel level = LogLevel.Verbose, Except

message = ApplyFilters(message);

Type callingClass = new StackTrace().GetFrames().Where(sf => sf.HasMethod()).Select(sf => sf.GetMethod()).FirstOrDefault(m => m != null && m.DeclaringType != typeof(Logger))?.DeclaringType;

if (callingClass != null)
{
message = $"{callingClass.Name}, {message}";
}

if (valueChanges != null)
{
message = $"{message}, {string.Join(" ", valueChanges.Select(kvp => $"from: \"{kvp.Key}\" to: \"{kvp.Value}\""))}";
}

if (values != null)
{
message = $"{message}, {string.Join(" ", values.Select(kvp => $"{kvp.Key}:\"{kvp.Value}\""))}";
}

string logOutput = message;

if (exception != null)
Expand Down