// Copyright Keysight Technologies 2012-2019
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, you can obtain one at http://mozilla.org/MPL/2.0/.
using System;
using System.Collections.Generic;
using System.Linq;
using System.IO;
using System.Threading.Tasks;
using System.Runtime.InteropServices;
using System.Reflection;
using System.Threading;
using System.Diagnostics;
namespace OpenTap
{
///
/// SessionLogs are logs of all events that occur during startup/shutdown of a OpenTAP session and of all the session's TestPlan runs.
/// A new session log is created at the start of each session, which starts when a process is launched and ends when it closes.
/// Only 10 session logs are allowed to exist, with the oldest deleted as new logs are created.
/// By comparison, a result log typically shows only the log activity for a single run of a TestPlan.
///
public static class SessionLogs
{
[DllImport("Kernel32.dll", CharSet = CharSet.Unicode, EntryPoint = "CreateHardLink")]
static extern bool CreateHardLinkWin(
string lpFileName,
string lpExistingFileName,
IntPtr lpSecurityAttributes
);
[DllImport("libc", EntryPoint = "link")]
static unsafe extern bool CreateHardLinkLin(
char *target,
char *linkpath
);
static unsafe void CreateHardLink(string targetFile, string linkName)
{
if (OperatingSystem.Current == OperatingSystem.Windows)
{
CreateHardLinkWin(linkName, targetFile, IntPtr.Zero);
}
else if (OperatingSystem.Current == OperatingSystem.Linux)
{
IntPtr target = Marshal.StringToCoTaskMemAnsi(targetFile);
IntPtr link = Marshal.StringToCoTaskMemAnsi(linkName);
CreateHardLinkLin((char*)target, (char*)link);
Marshal.FreeCoTaskMem(target);
Marshal.FreeCoTaskMem(link);
}
else if (OperatingSystem.Current == OperatingSystem.MacOS)
{
Process.Start("ln", $"\"{targetFile}\" \"{linkName}\"");
}
else
{
// Platform hardlinks not implemented.
}
}
private static readonly TraceSource log = Log.CreateSource("Session");
/// The number of files kept at a time.
internal const int MaxNumberOfTraceFiles = 20;
/// The maximally allowed size of trace files.
internal static long MaxTotalSizeOfSessionLogFiles = 2_000_000_000L;
/// The maximally allowed size of individual log files.
internal static ulong LogFileMaxSize = 100_000_000;
///
/// If two sessions needs the same log file name, an integer is added to the name.
/// This is the max number of times that we are going to test new names.
///
const int maxNumberOfConcurrentSessions = MaxNumberOfTraceFiles;
private static FileTraceListener traceListener;
///
/// File path to the current log file. Path is updated upon UI launch.
///
public static string GetSessionLogFilePath() => traceListener?.FileName ?? currentLogFile;
///
/// The current log file base name. This might not be accurate if the log has rolled over due to size.
///
static string currentLogFile;
// This controls whether or not session logs should keep files locked
private static bool NoExclusiveWriteLock = false;
///
/// Initializes the logging. Uses the following file name formatting: SessionLogs\\[Application Name]\\[Application Name] [yyyy-MM-dd HH-mm-ss].txt.
///
public static void Initialize()
{
if (currentLogFile != null) return;
var timestamp = System.Diagnostics.Process.GetCurrentProcess().StartTime.ToString("yyyy-MM-dd HH-mm-ss");
// Path example: /SessionLogs/SessionLog .txt
string pathEnding = $"SessionLog {timestamp}";
if (Assembly.GetEntryAssembly() != null && !String.IsNullOrWhiteSpace(Assembly.GetEntryAssembly().Location))
{
string exeName = Path.GetFileNameWithoutExtension(Assembly.GetEntryAssembly().Location);
// Path example: /SessionLogs/tap/tap .txt
pathEnding = $"{exeName} {timestamp}";
}
Initialize($"{FileSystemHelper.GetCurrentInstallationDirectory()}/SessionLogs/{pathEnding}.txt");
}
///
/// Initializes the logging.
///
public static void Initialize(string logFileName)
{
// We can't just add this as a parameter with a default value because
// it isn't backwards compatible with plugins compiled against older versions.
// On the IL level, this would be equivalent to removing this method and adding
// a new method with a different signature.
Initialize(logFileName, NoExclusiveWriteLock);
}
internal static bool SkipStartupInfo { get; set; }
///
/// Initializes the logging.
///
/// The name of the log file
///
/// Controls whether or not the file should have an exclusive write lock.
/// If true, the log file may be deleted while it is in use, in which case
/// session logs will be written into the void.
///
public static void Initialize(string logFileName, bool noExclusiveWriteLock)
{
NoExclusiveWriteLock = noExclusiveWriteLock;
if (currentLogFile == null)
{
Rename(logFileName);
SystemInfoTask = Task.Factory
// Ensure that the plugin manager is loaded before running SystemInfo.
// this ensures that System.Runtime.InteropServices.RuntimeInformation.dll is loaded. (issue #4000).
.StartNew(PluginManager.Load)
// then get the system info on a separate thread (it takes ~1s)
.ContinueWith(tsk =>
{
if(!SkipStartupInfo)
LogStartupInfo();
});
AppDomain.CurrentDomain.ProcessExit += FlushOnExit;
AppDomain.CurrentDomain.UnhandledException += FlushOnExit;
}
else
{
if (currentLogFile != logFileName)
Rename(logFileName);
}
currentLogFile = logFileName;
// Log debugging information of the current process.
log.Debug($"Running '{Environment.CommandLine}' in '{Directory.GetCurrentDirectory()}'.");
}
private static void FlushOnExit(object sender, EventArgs e)
{
try
{
SystemInfoTask.Wait(); // wait for the task if we are crashing to make sure the info is in the log
}
catch (Exception ex)
{
if (ex is ThreadAbortException == false)
log.Debug("Unexpected error while printing system information.");
}
Flush();
}
///
/// Class for managing a hidden file containing a list of recent files. This can be accessed by multiple processes, so possible race conditions needs to be handled.
///
class RecentFilesList
{
IEnumerable names;
private string name = null;
public RecentFilesList(List filenameoptions)
{
names = filenameoptions;
}
static string[] readLinesSafe(string name)
{
for (int i = 0; i < 5; i++)
{
try
{
return File.ReadAllLines(name);
}
catch (Exception) when (i < 4)
{
Thread.Sleep(100);
}
}
return null;
}
static void setHidden(string name)
{
if (OperatingSystem.Current == OperatingSystem.Windows)
File.SetAttributes(name, FileAttributes.Hidden | FileAttributes.Archive);
}
string[] ensureFileExistsAndReadLines()
{
var _names = names;
if (name != null)
_names = new[] {name}; // a name was already decided.
foreach (var name in _names)
{
try
{
if (!File.Exists(name))
{
File.Create(name).Close();
try
{
setHidden(name);
}
catch
{
// The file could not be made hidden. This is probably ok.
}
this.name = name;
return Array.Empty();
}
if(readLinesSafe(name) is string[] str)
{
this.name = name;
return str;
}
}
catch
{
// ignore exceptions throws. Try a different file.
}
}
return Array.Empty();
}
static RecentFilesList()
{
var mutexName = "opentap_recent_logs_mutex";
const int retries = 5;
Exception ex = null;
for (int i = 0; i < retries; i++)
{
try
{
recentLock = new Mutex(false, mutexName);
break;
}
catch (Exception e)
{
ex = e;
Thread.Sleep(10);
}
}
if (recentLock == null)
log.Debug($"Error creating mutex '{mutexName}': {ex.Message}");
}
private static readonly Mutex recentLock;
private static bool recentFilesValid => recentLock != null;
public string[] GetRecent()
{
if (!recentFilesValid)
return Array.Empty();
try
{
recentLock.WaitOne();
}
catch (AbandonedMutexException)
{
// recover from abandoned mutex
}
try
{
return ensureFileExistsAndReadLines();
}
finally
{
recentLock.ReleaseMutex();
}
}
public void AddRecent(string newname)
{
// Don't write to the file if we can't get the mutex
if (!recentFilesValid)
return;
// Important to lock the file and to re-read if the file was changed since last checked.
// otherwise there is a risk that a log file will be forgotten and never cleaned up.
try
{
recentLock.WaitOne();
}
catch (AbandonedMutexException)
{
// recover from abandoned mutex
}
try
{
var currentFiles = ensureFileExistsAndReadLines().Append(newname).DistinctLast();
currentFiles.RemoveIf(x => File.Exists(x) == false);
using (var f = File.Open(name, FileMode.Open, FileAccess.ReadWrite, FileShare.ReadWrite))
{
f.SetLength(0);
using (var sw = new StreamWriter(f))
{
currentFiles.ForEach(sw.WriteLine);
}
}
}
finally
{
recentLock.ReleaseMutex();
}
}
}
private const string RecentFilesName = ".opentap_recent_logs";
static List getLogRecentFilesName()
{
// If the tap installation folder is write-protected by the user,
// we'll try to find some other valid location instead.
List options = new List();
void addOption(Func f)
{
try
{
string option = f();
if(option != null)
options.Add(option);
}
catch
{
}
}
if (ExecutorClient.IsRunningIsolated)
{ // Use the recent system logs from original directory to avoid leaking log files.
addOption(() => Path.Combine(ExecutorClient.ExeDir, RecentFilesName));
}
addOption(() => Path.Combine(Path.GetDirectoryName(typeof(SessionLogs).Assembly.Location), RecentFilesName));
addOption(() => Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData), RecentFilesName));
addOption(() => RecentFilesName);
return options;
}
static readonly RecentFilesList recentSystemLogs = new RecentFilesList(getLogRecentFilesName());
static void RemoveOldLogFiles()
{
List recentFiles = recentSystemLogs.GetRecent().Where(File.Exists).ToList();
long CalcTotalSize()
{
return recentFiles.Select(x => new FileInfo(x).Length).Sum();
}
bool ConditionViolated()
{
bool tooManyFiles = recentFiles.Count > MaxNumberOfTraceFiles;
if (tooManyFiles) return true;
if (recentFiles.Count <= 2) return false; // Do not remove the last couple of log files, event though they might exceed limits.
var totalSize = CalcTotalSize();
bool filesTooBig = totalSize > MaxTotalSizeOfSessionLogFiles;
if (filesTooBig) return true;
return false;
}
int ridx = 0;
while (ConditionViolated() && ridx < recentFiles.Count)
{
try
{
if (File.Exists(recentFiles[ridx]))
{
log.Debug("Deleting log file: {0}", recentFiles[ridx]);
File.Delete(recentFiles[ridx]);
}
recentFiles.RemoveAt(ridx);
}
catch (Exception)
{
ridx++;
}
}
}
///
/// Renames a previously initialized temporary log file.
///
static void rename(string path, bool newLogFile = false)
{
var sw = System.Diagnostics.Stopwatch.StartNew();
string name = Path.GetFileNameWithoutExtension(path);
string dir = Path.GetDirectoryName(path);
string ext = Path.GetExtension(path);
bool fileNameChanged = false;
for (int idx = 0; idx < maxNumberOfConcurrentSessions; idx++)
{
try
{
path = Path.Combine(dir, name + (idx == 0 ? "" : idx.ToString()) + ext);
if (traceListener == null)
{
if (string.IsNullOrWhiteSpace(dir) == false)
Directory.CreateDirectory(Path.GetDirectoryName(path));
if (NoExclusiveWriteLock)
{
// Initialize a stream where the underlying file can be deleted. If the file is deleted, writes just go into the void.
var stream = new FileStream(path, FileMode.Append, FileAccess.Write, FileShare.Read | FileShare.Delete);
traceListener = new FileTraceListener(stream);
}
else
{
traceListener = new FileTraceListener(path);
}
traceListener.FileSizeLimit = LogFileMaxSize;
traceListener.FileSizeLimitReached += TraceListener_FileSizeLimitReached;
Log.AddListener(traceListener);
}
else
{
traceListener.ChangeFileName(path, NoExclusiveWriteLock, startNewLog: newLogFile);
traceListener.FileSizeLimit = LogFileMaxSize;
}
fileNameChanged = true;
break;
}
catch
{
// File was probably locked by another process.
}
}
if (!fileNameChanged)
{
log.Debug("Unable to rename log file. Continuing with log '{0}'.", currentLogFile);
}
else
{
currentLogFile = path;
log.Debug(sw, "Session log loaded as '{0}'.", currentLogFile);
recentSystemLogs.AddRecent(Path.GetFullPath(path));
}
MakeLatest(path);
RemoveOldLogFiles();
}
static void MakeLatest(string path)
{
// Create a hardlink to a file called 'Latest.txt' next to the file specified by 'path'
try
{
var latestPath = Path.Combine(Path.GetDirectoryName(path), "Latest.txt");
if (File.Exists(latestPath))
File.Delete(latestPath);
CreateHardLink(path, latestPath);
}
catch
{
// Ignore in case of race conditions.
}
}
static int sessionLogCount = 0;
static readonly object sessionLogRotateLock = new object();
static void TraceListener_FileSizeLimitReached(object sender, EventArgs e)
{
lock (sessionLogRotateLock)
{
var newName = currentLogFile.Replace("__" + sessionLogCount, "");
sessionLogCount += 1;
var nextFile = addLogRotateNumber(newName, sessionLogCount);
((FileTraceListener)sender).ChangeFileName(nextFile, false, true);
log.Info("Switching log to file {0}", nextFile);
recentSystemLogs.AddRecent(Path.GetFullPath(nextFile));
MakeLatest(nextFile);
RemoveOldLogFiles();
}
}
static string addLogRotateNumber(string fullname, int cnt)
{
if (cnt == 0) return fullname;
var dir = Path.GetDirectoryName(fullname);
var filename = Path.GetFileNameWithoutExtension(fullname);
if (Path.HasExtension(fullname))
{
var ext = Path.GetExtension(fullname);
return Path.Combine(dir, filename + "__" + cnt.ToString() + ext);
}
else
{
return Path.Combine(dir, filename + "__" + cnt.ToString());
}
}
///
/// Renames a previously initialized temporary log file.
///
public static void Rename(string path) => Rename(path, false);
///
///
///
///
/// If a new log file should be created or we should rename the existing one.
internal static void Rename(string path, bool newLogFile)
{
try
{
rename(path, newLogFile: newLogFile);
}
catch (UnauthorizedAccessException e)
{
log.Warning("Unable to rename log file to {0} as permissions was denied.", path);
log.Debug(e);
}
catch (IOException e)
{ // This could also be an error the the user does not have permissions. E.g OpenTAP installed in C:\\
log.Warning("Unable to rename log file to {0} as the file could not be created.", path);
log.Debug(e);
}
}
static Task SystemInfoTask;
private static void LogStartupInfo()
{
TapThread.Sleep(200);
foreach (var td in TypeData.GetDerivedTypes().Where(td => td.CanCreateInstance))
{
IStartupInfo si = null;
try
{
si = td.CreateInstance() as IStartupInfo;
if (si == null)
{
log.Debug($"Failed to instantiate '{td.Name}'.");
continue;
}
}
catch (Exception ex)
{
log.Debug($"Failed to instantiate '{td.Name}': {ex.Message}");
log.Debug(ex);
continue;
}
try
{
si.LogStartupInfo();
}
catch (Exception ex)
{
log.Debug($"Unhandled exception in '{td.Name}.{nameof(si.LogStartupInfo)}': {ex.Message}");
log.Debug(ex);
}
}
}
///
/// Flushes the buffered logs. Useful as the last thing to do in case of crash.
///
public static void Flush()
{
if (traceListener != null)
traceListener.Flush();
}
}
}