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

Self-Diagnostics: include datetimestamp in filename #2325

Merged
merged 6 commits into from
Jul 10, 2021
Merged
Show file tree
Hide file tree
Changes from 4 commits
Commits
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
Original file line number Diff line number Diff line change
Expand Up @@ -15,15 +15,16 @@ public class MemoryMappedFileHandlerTest
[TestMethod]
public void MemoryMappedFileHandler_Success()
{
var fileName = Path.GetFileName(Process.GetCurrentProcess().MainModule.FileName) + "."
+ Process.GetCurrentProcess().Id + ".log";
string filePath;
var fileSize = 1024;
using (var handler = new MemoryMappedFileHandler())
{
handler.CreateLogFile(".", fileSize);

filePath = handler.CurrentFilePath;
}

var actualBytes = ReadFile(fileName, MessageOnNewFile.Length);
var actualBytes = ReadFile(filePath, MessageOnNewFile.Length);

CollectionAssert.AreEqual(MessageOnNewFile, actualBytes);
}
Expand All @@ -36,27 +37,29 @@ public void MemoryMappedFileHandler_Circular_Success()
var messageToOverflow = Encoding.UTF8.GetBytes("1234567");
var expectedBytesAtEnd = Encoding.UTF8.GetBytes("1234");
var expectedBytesAtStart = Encoding.UTF8.GetBytes("567cessfully opened file.\n");
string filePath;

using (var handler = new MemoryMappedFileHandler())
{
handler.CreateLogFile(".", fileSize);

handler.Write(buffer, fileSize - MessageOnNewFile.Length - expectedBytesAtEnd.Length);

handler.Write(messageToOverflow, messageToOverflow.Length);

filePath = handler.CurrentFilePath;
}

var fileName = Path.GetFileName(Process.GetCurrentProcess().MainModule.FileName) + "."
+ Process.GetCurrentProcess().Id + ".log";
var actualBytes = ReadFile(fileName, buffer.Length);
var actualBytes = ReadFile(filePath, buffer.Length);

CollectionAssert.AreEqual(expectedBytesAtStart, SubArray(actualBytes, 0, expectedBytesAtStart.Length));
CollectionAssert.AreEqual(expectedBytesAtEnd, SubArray(actualBytes, actualBytes.Length - expectedBytesAtEnd.Length, expectedBytesAtEnd.Length));
}

private static byte[] ReadFile(string fileName, int byteCount)
private static byte[] ReadFile(string filePath, int byteCount)
{
byte[] actualBytes = new byte[byteCount];
using (var file = File.Open(fileName, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
using (var file = File.Open(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
{
file.Read(actualBytes, 0, byteCount);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -27,8 +27,10 @@ public void SelfDiagnosticsConfigRefresher_OmitAsConfigured()
// Emitting event of EventLevel.Warning
CoreEventSource.Log.OperationIsNullWarning();

var filePath = configRefresher.CurrentFilePath;

int bufferSize = 512;
byte[] actualBytes = ReadFile(bufferSize);
byte[] actualBytes = ReadFile(filePath, bufferSize);
string logText = Encoding.UTF8.GetString(actualBytes);
Assert.IsTrue(logText.StartsWith(MessageOnNewFileString));

Expand All @@ -52,8 +54,10 @@ public void SelfDiagnosticsConfigRefresher_CaptureAsConfigured()
// Emitting event of EventLevel.Error
CoreEventSource.Log.InvalidOperationToStopError();

var filePath = configRefresher.CurrentFilePath;

int bufferSize = 512;
byte[] actualBytes = ReadFile(bufferSize);
byte[] actualBytes = ReadFile(filePath, bufferSize);
string logText = Encoding.UTF8.GetString(actualBytes);
Assert.IsTrue(logText.StartsWith(MessageOnNewFileString));

Expand All @@ -77,12 +81,9 @@ private static string ParseLogMessage(string logLine)
return logLine.Substring(timestampPrefixLength);
}

private static byte[] ReadFile(int byteCount)
private static byte[] ReadFile(string filePath, int byteCount)
{
var outputFileName = Path.GetFileName(Process.GetCurrentProcess().MainModule.FileName) + "."
+ Process.GetCurrentProcess().Id + ".log";
var outputFilePath = Path.Combine(".", outputFileName);
using (var file = File.Open(outputFilePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
using (var file = File.Open(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
{
byte[] actualBytes = new byte[byteCount];
file.Read(actualBytes, 0, byteCount);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ namespace Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing.Sel
{
using System;
using System.Diagnostics;
using System.Globalization;
using System.IO;
using System.IO.MemoryMappedFiles;
using System.Text;
Expand Down Expand Up @@ -38,6 +39,8 @@ internal class MemoryMappedFileHandler : IDisposable

public int LogFileSize { get => this.logFileSize; private set => this.logFileSize = value; }

public string CurrentFilePath => this.underlyingFileStreamForMemoryMappedFile?.Name;

/// <summary>
/// Create a log file. If the file already exists, it will be overwritten.
/// </summary>
Expand All @@ -48,8 +51,7 @@ public void CreateLogFile(string logDirectory, int fileSize)
try
{
Directory.CreateDirectory(logDirectory);
var fileName = Path.GetFileName(Process.GetCurrentProcess().MainModule.FileName) + "."
+ Process.GetCurrentProcess().Id + ".log";
var fileName = GenerateFileName();
TimothyMothra marked this conversation as resolved.
Show resolved Hide resolved
var filePath = Path.Combine(logDirectory, fileName);

// Because the API [MemoryMappedFile.CreateFromFile][1](the string version) behaves differently on
Expand Down Expand Up @@ -162,6 +164,17 @@ public virtual void Write(byte[] buffer, int byteCount)
}
}

private static string GenerateFileName()
{
var dateTimeStamp = DateTime.UtcNow.ToString("yyyyMMdd-HHmmss", CultureInfo.InvariantCulture);

var currentProcess = Process.GetCurrentProcess();
var processFileName = Path.GetFileName(currentProcess.MainModule.FileName);
var processId = currentProcess.Id;

return $"{dateTimeStamp}.{processFileName}.{processId}.log";
Copy link
Member

Choose a reason for hiding this comment

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

  1. I was inclined to not start with timestamp. However I like this idea too which can sort even across different processes.
  2. The timestamp might look like (indicate) log partition by time to customers (creating multiple log files by the hour or by size limit to avoid single file getting too large). It would be helpful if the Readme could clear customer's potential questions before they come to us.
  3. I noticed just now that in the readme I didn't mention anything about circular write or how come the log file is fix-size. Can you also add this?

Copy link
Member Author

Choose a reason for hiding this comment

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

Regarding 2: Testing this locally... I don't see multiple files being created unless the config file is changed during runtime.

Copy link
Member Author

Choose a reason for hiding this comment

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

Regarding 3: please see my changes to the Readme and let me know if that makes sense :)

Copy link
Member

@xiang17 xiang17 Jul 9, 2021

Choose a reason for hiding this comment

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

Regarding 2: Testing this locally... I don't see multiple files being created unless the config file is changed during runtime.

I meant it might give customers an impression that we do partition into multiple files. In fact, as we understand, our code only writes in single file.

}

/// <summary>
/// Try to get the log stream which is seeked to the position where the next line of log should be written.
/// </summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,8 @@ public SelfDiagnosticsConfigRefresher()
this.worker = Task.Run(() => this.Worker(this.cancellationTokenSource.Token), this.cancellationTokenSource.Token);
}

public string CurrentFilePath => this.memoryMappedFileHandler.CurrentFilePath;

/// <inheritdoc/>
public void Dispose()
{
Expand Down
7 changes: 5 additions & 2 deletions troubleshooting/ETW/Readme.md
Original file line number Diff line number Diff line change
Expand Up @@ -122,7 +122,8 @@ As of version 2.18.0, this SDK ships a "self-diagnostics feature" which captures

The self-diagnostics feature can be enabled/changed/disabled while the process is running.
The SDK will attempt to read the configuration file every 10 seconds, using a non-exclusive read-only mode.
The SDK will create or overwrite a file with new logs according to the configuration.
Each time this configuration file changes, a new log file will be created according to the configuration.
xiang17 marked this conversation as resolved.
Show resolved Hide resolved
This file will not exceed the configured max size and will be circularly overwritten.

#### Configuration

Expand Down Expand Up @@ -150,13 +151,15 @@ Example:

#### Configuration Parameters

A `FileSize`-KiB log file named as `ExecutableName.ProcessId.log` (e.g. `foobar.exe.12345.log`) will be generated at the specified directory `LogDirectory`.
A `FileSize`-KiB log file named as `YearMonthDay-HourMinuteSecond.ExecutableName.ProcessId.log` (e.g. `20010101-120000.foobar.exe.12345.log`) will be generated at the specified directory `LogDirectory`.
The file name starts with the `DateTime.UtcNow` timestamp of when the file was created.

1. `LogDirectory` is the directory where the output log file will be stored.
It can be an absolute path or a relative path to the current directory.

2. `FileSize` is a positive integer, which specifies the log file size in [KiB](https://en.wikipedia.org/wiki/Kibibyte).
This value must be between 1 MiB and 128 MiB (inclusive), or it will be rounded to the closest upper or lower limit.
The log file will never exceed this configured size, and will be circularly rewriten.

3. `LogLevel` is the lowest level of the events to be captured.
This value must match one of the [fields](https://docs.microsoft.com/dotnet/api/system.diagnostics.tracing.eventlevel#fields) of the `EventLevel` enum.
Expand Down