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.

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

Add a session timestamp prefix to log files (and retain 7 days of logs) #6063

Merged
merged 8 commits into from
Dec 5, 2023
58 changes: 30 additions & 28 deletions osu.Framework/Logging/Logger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -23,11 +23,19 @@ public class Logger
{
private static readonly object static_sync_lock = new object();

// separate locking object for flushing so that we don't lock too long on the staticSyncLock object, since we have to
// hold this lock for the entire duration of the flush (waiting for I/O etc) before we can resume scheduling logs
// but other operations like GetLogger(), ApplyFilters() etc. can still be executed while a flush is happening.
/// <summary>
/// Separate locking object for flushing so that we don't lock too long on the staticSyncLock object, since we have to
/// hold this lock for the entire duration of the flush (waiting for I/O etc) before we can resume scheduling logs
/// but other operations like GetLogger(), ApplyFilters() etc. can still be executed while a flush is happening.
/// </summary>
private static readonly object flush_sync_lock = new object();

/// <summary>
/// Logs are stored with a consistent unix timestamp prefix per session (across all loggers) for logical grouping of
/// log files on disk.
/// </summary>
private static readonly long session_startup_timestamp = DateTimeOffset.UtcNow.ToUnixTimeSeconds();

/// <summary>
/// Whether logging is enabled. Setting this to false will disable all logging.
/// </summary>
Expand Down Expand Up @@ -60,13 +68,12 @@ public class Logger
/// </summary>
public static Storage Storage
{
private get => storage;
get => storage;
set
{
storage = value ?? throw new ArgumentNullException(nameof(value));

// clear static loggers so they are correctly purged at the new storage location.
static_loggers.Clear();
Copy link
Member

@Susko3 Susko3 Nov 27, 2023

Choose a reason for hiding this comment

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

Just noting this: changing the logger storage when the game is running will no longer write the logger header to the new log files.

Changing the logger storage during runtime is dubious, and the old code is incorrect since it wasn't locking flush_sync_lock when accessing a thread-shared resource (static_loggers).

So I'm not against this change. Maybe change the setter to internal to reflect that we don't support changing the storage.

Copy link
Sponsor Member Author

Choose a reason for hiding this comment

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

Unfortunately the setter is used osu! side:

CleanShot 2023-11-28 at 08 28 22

I actually removed this because it was writing the headers more than once to the same file location. I guess I'll add it back and fix that part instead..

Copy link
Sponsor Member Author

@peppy peppy Nov 28, 2023

Choose a reason for hiding this comment

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

On second thoughts, I guess this depends on what we consider the log header to be. Should it signal the start of a session and therefore not be present on a partial log? I could imagine this being one correct way of looking at it.

Here's a diff to make the log header output correctly after storage changes only, in case that is the preferred direction:

diff --git a/osu.Framework/Logging/Logger.cs b/osu.Framework/Logging/Logger.cs
index fb7301901..ea492be99 100644
--- a/osu.Framework/Logging/Logger.cs
+++ b/osu.Framework/Logging/Logger.cs
@@ -63,6 +63,8 @@ public class Logger
 
         private static Storage storage;
 
+        private static string storageFullPath = string.Empty;
+
         /// <summary>
         /// The storage to place logs inside.
         /// </summary>
@@ -71,8 +73,20 @@ public static Storage Storage
             private get => storage;
             set
             {
+                if (storage == value)
+                    return;
+
                 storage = value ?? throw new ArgumentNullException(nameof(value));
 
+                string newPath = storage.GetFullPath(string.Empty);
+
+                // If the full path has changed, recreate loggers to correctly purge and
+                // repopulate the log's header.
+                if (newPath == storageFullPath)
+                    static_loggers.Clear();
+
+                storageFullPath = newPath;
+
                 cycleLogs();
             }
         }

Copy link
Contributor

Choose a reason for hiding this comment

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

I consider it as the start of a session, but I wouldn't mind it being output every time.

Copy link
Sponsor Member Author

Choose a reason for hiding this comment

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

I think I'd rather it didn't output every time so we know that some logs might be missing from the start.

cycleLogs();
}
}

Expand All @@ -83,7 +90,7 @@ public static Storage Storage
/// <summary>
/// Gets the name of the file that this logger is logging to.
/// </summary>
public string Filename => $@"{Name}.log";
public string Filename { get; }

public int TotalLogOperations => logCount.Value;

Expand All @@ -109,6 +116,7 @@ private Logger(string name, bool checkedReserved)

Name = name;
logCount = GlobalStatistics.Get<int>(nameof(Logger), Name);
Filename = $"{session_startup_timestamp}.{Name}.log";
}

/// <summary>
Expand Down Expand Up @@ -257,10 +265,7 @@ public static Logger GetLogger(string name)
string nameLower = name.ToLowerInvariant();

if (!static_loggers.TryGetValue(nameLower, out Logger l))
{
static_loggers[nameLower] = l = Enum.TryParse(name, true, out LoggingTarget target) ? new Logger(target) : new Logger(name, true);
l.clear();
}

return l;
}
Expand Down Expand Up @@ -409,30 +414,27 @@ private void writePendingLines()
/// </summary>
public static event Action<LogEntry> NewEntry;

/// <summary>
/// Deletes log file from disk.
/// </summary>
private void clear()
private bool headerAdded;

private static void cycleLogs()
{
lock (flush_sync_lock)
try
{
scheduler.Add(() =>
DateTime logCycleCutoff = DateTime.UtcNow.AddDays(-7);
var logFiles = new DirectoryInfo(storage.GetFullPath(string.Empty)).GetFiles("*.log");

foreach (var fileInfo in logFiles)
{
try
{
Storage.Delete(Filename);
}
catch
{
// may fail if the file/directory was already cleaned up, ie. during test runs.
}
});
writer_idle.Reset();
if (fileInfo.CreationTimeUtc < logCycleCutoff)
fileInfo.Delete();
}
}
catch (Exception e)
{
Log($"Cycling logs failed ({e})");
}
}

private bool headerAdded;

private void ensureHeader()
{
if (headerAdded) return;
Expand Down