log watcher rework

This commit is contained in:
pypy
2020-11-01 19:20:36 +09:00
parent 7e84977ace
commit 9877e52d67
3 changed files with 462 additions and 261 deletions
+364 -227
View File
@@ -12,20 +12,21 @@ using System.Threading;
namespace VRCX namespace VRCX
{ {
public class LogWatcherFile
{
public long Length;
public long Position;
public string Tag;
}
public class LogWatcher public class LogWatcher
{ {
private class LogContext
{
public long Length;
public long Position;
}
public static LogWatcher Instance { get; private set; } public static LogWatcher Instance { get; private set; }
private static readonly ReaderWriterLockSlim m_Lock = new ReaderWriterLockSlim(); private readonly DirectoryInfo m_LogDirectoryInfo;
private static List<string[]> m_GameLog = new List<string[]>(); private readonly Dictionary<string, LogContext> m_LogContextMap; // <FileName, LogContext>
private static Thread m_Thread; private readonly ReaderWriterLockSlim m_LogListLock;
private static bool m_Reset; private readonly List<string[]> m_LogList;
private Thread m_WatchThread;
private bool m_ResetLog;
// NOTE // NOTE
// FileSystemWatcher() is unreliable // FileSystemWatcher() is unreliable
@@ -35,218 +36,145 @@ namespace VRCX
Instance = new LogWatcher(); Instance = new LogWatcher();
} }
public static void Init() public LogWatcher()
{ {
m_Thread = new Thread(() => var logPath = Environment.GetFolderPath(Environment.SpecialFolder.LocalApplicationData) + @"Low\VRChat\VRChat";
{ m_LogDirectoryInfo = new DirectoryInfo(logPath);
var D = new Dictionary<string, LogWatcherFile>(); m_LogContextMap = new Dictionary<string, LogContext>();
var di = new DirectoryInfo(Environment.GetFolderPath(Environment.SpecialFolder.LocalApplicationData) + @"Low\VRChat\VRChat"); m_LogListLock = new ReaderWriterLockSlim();
while (m_Thread != null) m_LogList = new List<string[]>();
{ m_WatchThread = new Thread(WatchLoop)
try
{
Thread.Sleep(1000);
}
catch
{
// ThreadInterruptedException
}
if (m_Reset)
{
m_Reset = false;
D.Clear();
m_Lock.EnterWriteLock();
try
{
m_GameLog.Clear();
}
finally
{
m_Lock.ExitWriteLock();
}
}
var S = new HashSet<string>(D.Keys);
di.Refresh();
if (di.Exists)
{
var files = di.GetFiles("output_log_*.txt", SearchOption.TopDirectoryOnly);
Array.Sort(files, (A, B) => A.CreationTimeUtc.CompareTo(B.CreationTimeUtc));
var bias = DateTime.UtcNow.AddMinutes(-5d);
foreach (var fi in files)
{
if (bias.CompareTo(fi.LastWriteTimeUtc) <= 0)
{
fi.Refresh();
}
if (D.TryGetValue(fi.Name, out LogWatcherFile F))
{
S.Remove(fi.Name);
if (F.Length == fi.Length)
{
continue;
}
}
else
{
F = new LogWatcherFile();
D.Add(fi.Name, F);
}
F.Length = fi.Length;
Parse(fi, F);
}
}
foreach (var key in S)
{
D.Remove(key);
}
}
})
{ {
IsBackground = true IsBackground = true
}; };
m_Thread.Start();
} }
public static void Exit() public void Init()
{ {
var T = m_Thread; m_WatchThread.Start();
m_Thread = null;
T.Interrupt();
T.Join();
} }
public static void Parse(FileInfo info, LogWatcherFile F) public void Exit()
{
var watchThread = m_WatchThread;
m_WatchThread = null;
watchThread.Interrupt();
watchThread.Join();
}
private void WatchLoop()
{
while (m_WatchThread != null)
{
try
{
Thread.Sleep(1000);
}
catch
{
// ThreadInterruptedException
}
Update();
}
}
private void Update()
{
if (m_ResetLog == true)
{
m_ResetLog = false;
m_LogContextMap.Clear();
m_LogListLock.EnterWriteLock();
try
{
m_LogList.Clear();
}
finally
{
m_LogListLock.ExitWriteLock();
}
}
var deletedNameSet = new HashSet<string>(m_LogContextMap.Keys);
m_LogDirectoryInfo.Refresh();
if (m_LogDirectoryInfo.Exists == true)
{
var fileInfos = m_LogDirectoryInfo.GetFiles("output_log_*.txt", SearchOption.TopDirectoryOnly);
// sort by creation time
Array.Sort(fileInfos, (a, b) => a.CreationTimeUtc.CompareTo(b.CreationTimeUtc));
var bias = DateTime.UtcNow.AddMinutes(-3d);
foreach (var fileInfo in fileInfos)
{
if (bias.CompareTo(fileInfo.LastWriteTimeUtc) <= 0)
{
fileInfo.Refresh();
if (fileInfo.Exists == false)
{
continue;
}
}
if (m_LogContextMap.TryGetValue(fileInfo.Name, out LogContext logContext) == true)
{
deletedNameSet.Remove(fileInfo.Name);
}
else
{
logContext = new LogContext();
m_LogContextMap.Add(fileInfo.Name, logContext);
}
if (logContext.Length == fileInfo.Length)
{
continue;
}
logContext.Length = fileInfo.Length;
ParseLog(fileInfo, logContext);
}
}
foreach (var name in deletedNameSet)
{
m_LogContextMap.Remove(name);
}
}
private void ParseLog(FileInfo fileInfo, LogContext logContext)
{ {
try try
{ {
using (var stream = info.Open(FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) using (var fileStream = fileInfo.Open(FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
{ {
stream.Position = F.Position; fileStream.Position = logContext.Position;
using (var reader = new StreamReader(stream, Encoding.UTF8)) using (var streamReader = new StreamReader(fileStream, Encoding.UTF8))
{ {
var s = string.Empty; while (true)
while ((s = reader.ReadLine()) != null)
{ {
s = s.Trim(); var line = streamReader.ReadLine();
if (s.Length <= 35) if (line == null)
{
logContext.Position = fileStream.Position;
break;
}
if (line.Length <= 34 ||
line[31] != '-' ||
ParseLogOnPlayerJoined(fileInfo, line) == true ||
ParseLogOnPlayerLeft(fileInfo, line) == true ||
ParseLogNotification(fileInfo, line) == true ||
ParseLogLocation(fileInfo, line) == true ||
ParseLogHMDModel(fileInfo, line) == true ||
ParseLogAuth(fileInfo, line) == true)
{ {
continue; continue;
} }
var c = s[35];
if (c == 'N')
{
if (s.Length > 66 &&
string.Compare(s, 34, "[NetworkManager] OnPlayerJoined ", 0, 32, StringComparison.Ordinal) == 0)
{
// 2020.10.28 22:57:04 Log - [NetworkManager] OnPlayerJoined pypy
var time = ConvertLogTimeToISO8601(s);
var data = s.Substring(66);
m_Lock.EnterWriteLock();
try
{
m_GameLog.Add(new[]
{
time,
"OnPlayerJoined",
data
});
}
finally
{
m_Lock.ExitWriteLock();
}
}
else if (s.Length > 64 &&
string.Compare(s, 34, "[NetworkManager] OnPlayerLeft ", 0, 30, StringComparison.Ordinal) == 0)
{
// 2020.10.28 22:57:42 Log - [NetworkManager] OnPlayerLeft pypy
var time = ConvertLogTimeToISO8601(s);
var data = s.Substring(64);
m_Lock.EnterWriteLock();
try
{
m_GameLog.Add(new[]
{
time,
"OnPlayerLeft",
data
});
}
finally
{
m_Lock.ExitWriteLock();
}
}
}
else if (c == 'R')
{
if (s.Length > 56 &&
string.Compare(s, 34, "[RoomManager] Joining ", 0, 22, StringComparison.Ordinal) == 0)
{
if (string.Compare(s, 56, "or ", 0, 3, StringComparison.Ordinal) == 0)
{
// 2019.07.31 22:26:24 Log - [RoomManager] Joining or Creating Room: VRChat Home
var time = ConvertLogTimeToISO8601(s);
var data = string.Empty;
if (s.Length > 74)
{
data = s.Substring(74);
}
m_Lock.EnterWriteLock();
try
{
m_GameLog.Add(new[]
{
time,
"Location",
F.Tag ?? string.Empty,
data
});
}
finally
{
m_Lock.ExitWriteLock();
}
}
else
{
// 2019.07.31 22:26:24 Log - [RoomManager] Joining wrld_4432ea9b-729c-46e3-8eaf-846aa0a37fdd:6974~private(usr_4f76a584-9d4b-46f6-8209-8305eb683661)~nonce(0000000000000000000000000000000000000000000000000000000000000000)
F.Tag = s.Substring(56);
}
}
}
else if (c == 'e')
{
if (s.Length > 82 &&
string.Compare(s, 34, "Received Message of type: notification content: ", 0, 48, StringComparison.Ordinal) == 0)
{
// 2020.06.28 06:28:18 Log - Received Message of type: notification content: {{"id":"not_7ba7c14f-e9e4-4e2f-a2e7-f5ccb7ffdad5","type":"invite","senderUserId":"usr_4f76a584-9d4b-46f6-8209-8305eb683661","senderUsername":"pypy","receiverUserId":"usr_f38006b4-eab5-4243-bcb1-206138e629d8","message":"This is a generated invite","details":{{"worldId":"wrld_03f52086-965c-456f-a5e9-4ba6df473173:72562~friends(usr_8a2f5b19-4f97-4642-b0fe-d8b338691b47)~nonce(1158A2215996CF893F29D270E47681DED8B6C226BCEF9B767F66EB7B55144E58)","worldName":"Shy Avatars"}},"created_at":"2020-06-27T21:28:18.520Z"}} received at 2020-06-27 PM 9:28:18 UTC
// 2020.06.28 06:28:18 Log - Received Notification: <Notification from username:pypy, sender user id:usr_4f76a584-9d4b-46f6-8209-8305eb683661 to usr_f38006b4-eab5-4243-bcb1-206138e629d8 of type: invite, id: not_7ba7c14f-e9e4-4e2f-a2e7-f5ccb7ffdad5, created at: 2020-06-27 PM 9:28:18 UTC, details: {{worldId=wrld_03f52086-965c-456f-a5e9-4ba6df473173:72562~friends(usr_8a2f5b19-4f97-4642-b0fe-d8b338691b47)~nonce(1158A2215996CF893F29D270E47681DED8B6C226BCEF9B767F66EB7B55144E58), worldName=Shy Avatars}}, type:invite, m seen:False, message: "This is a generated invite"> received at 2020-06-27 PM 9:28:18 UTC
var time = ConvertLogTimeToISO8601(s);
var data = s.Substring(82);
var pos = data.LastIndexOf('}');
if (pos >= 0)
{
data = data.Substring(0, pos + 1); // including brace
}
m_Lock.EnterWriteLock();
try
{
m_GameLog.Add(new[]
{
time,
"Notification",
data
});
}
finally
{
m_Lock.ExitWriteLock();
}
}
}
} }
F.Position = stream.Position;
} }
} }
} }
@@ -255,55 +183,264 @@ namespace VRCX
} }
} }
private static string ConvertLogTimeToISO8601(string s) private void AppendLog(string[] item)
{ {
// 2019.07.31 22:26:24 m_LogListLock.EnterWriteLock();
if (!DateTime.TryParseExact(s.Substring(0, 19), try
{
m_LogList.Add(item);
}
finally
{
m_LogListLock.ExitWriteLock();
}
}
private string ConvertLogTimeToISO8601(string line)
{
// 2020.10.31 23:36:22
if (DateTime.TryParseExact(
line.Substring(0, 19),
"yyyy.MM.dd HH:mm:ss", "yyyy.MM.dd HH:mm:ss",
CultureInfo.InvariantCulture, CultureInfo.InvariantCulture,
DateTimeStyles.AdjustToUniversal | DateTimeStyles.AssumeLocal, DateTimeStyles.AdjustToUniversal | DateTimeStyles.AssumeLocal,
out DateTime dt)) out DateTime dt
) == false)
{ {
dt = DateTime.UtcNow; dt = DateTime.UtcNow;
} }
return $"{dt:yyyy'-'MM'-'dd'T'HH':'mm':'ss'Z'}"; return $"{dt:yyyy'-'MM'-'dd'T'HH':'mm':'ss'Z'}";
} }
private bool ParseLogHMDModel(FileInfo fileInfo, string line)
{
// 2020.10.31 23:36:23 Log - STEAMVR HMD Model: VIVE_Pro MV
if (line.Length <= 53 ||
line[34] != 'S' ||
string.Compare(line, 34, "STEAMVR HMD Model: ", 0, 19, StringComparison.Ordinal) != 0)
{
return false;
}
var hmdModel = line.Substring(53);
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"hmd-model",
hmdModel
});
return true;
}
private bool ParseLogAuth(FileInfo fileInfo, string line)
{
// 2020.10.31 23:36:26 Log - [VRCFlowNetworkManager] Sending token from provider vrchat as user zetyx
if (line.Length <= 86 ||
line[35] != 'V' ||
string.Compare(line, 34, "[VRCFlowNetworkManager] Sending token from provider ", 0, 41, StringComparison.Ordinal) != 0)
{
return false;
}
var pos = line.IndexOf(" as user ", 86);
if (pos < 0)
{
return false;
}
var loginProvider = line.Substring(86, pos - 86);
var loginUser = line.Substring(pos + 9);
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"auth",
loginProvider,
loginUser
});
return true;
}
private bool ParseLogLocation(FileInfo fileInfo, string line)
{
// 2020.10.31 23:36:28 Log - [VRCFlowManagerVRC] Destination fetching: wrld_4432ea9b-729c-46e3-8eaf-846aa0a37fdd
// 2020.10.31 23:36:28 Log - [VRCFlowManagerVRC] Destination set: wrld_4432ea9b-729c-46e3-8eaf-846aa0a37fdd
// 2020.10.31 23:36:31 Log - [RoomManager] Entering Room: VRChat Home
// 2020.10.31 23:36:31 Log - [RoomManager] Joining wrld_4432ea9b-729c-46e3-8eaf-846aa0a37fdd:67646~private(usr_4f76a584-9d4b-46f6-8209-8305eb683661)~nonce(D9298A536FEEEDDBB61633661A4BDAA09717C5178DEF865C4C09372FE12E09A6)
// 2020.10.31 23:36:31 Log - [RoomManager] Joining or Creating Room: VRChat Home
// 2020.10.31 23:36:31 Log - [RoomManager] Successfully joined room
if (line.Length <= 56 ||
line[35] != 'R' ||
string.Compare(line, 34, "[RoomManager] Joining ", 0, 22, StringComparison.Ordinal) != 0)
{
return false;
}
if (string.Compare(line, 56, "or ", 0, 3, StringComparison.Ordinal) != 0)
{
var location = line.Substring(56);
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"location",
location
});
return true;
}
var worldName = (line.Length <= 74)
? string.Empty
: line.Substring(74);
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"world",
worldName
});
return true;
}
private bool ParseLogOnPlayerJoined(FileInfo fileInfo, string line)
{
// 2020.10.31 23:36:58 Log - [NetworkManager] OnPlayerJoined pypy
// 2020.10.31 23:36:58 Log - [Player] Initialized PlayerAPI "pypy" is local
// 2020.10.31 23:36:58 Log - [NetworkManager] OnPlayerJoined Rize♡
// 2020.10.31 23:36:58 Log - [Player] Initialized PlayerAPI "Rize♡" is remote
if (line.Length <= 66 ||
line[35] != 'N' ||
string.Compare(line, 34, "[NetworkManager] OnPlayerJoined ", 0, 32, StringComparison.Ordinal) != 0)
{
return false;
}
var userDisplayName = line.Substring(66);
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"player-joined",
userDisplayName
});
return true;
}
private bool ParseLogOnPlayerLeft(FileInfo fileInfo, string line)
{
// 2020.11.01 00:07:01 Log - [NetworkManager] OnPlayerLeft Rize♡
// 2020.11.01 00:07:01 Log - [PlayerManager] Removed player 2 / Rize♡
// 2020.11.01 00:07:02 Log - [Player] Unregistering Rize♡
if (line.Length <= 64 ||
line[35] != 'N' ||
string.Compare(line, 34, "[NetworkManager] OnPlayerLeft ", 0, 30, StringComparison.Ordinal) != 0)
{
return false;
}
var userDisplayName = line.Substring(64);
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"player-left",
userDisplayName
});
return true;
}
private bool ParseLogNotification(FileInfo fileInfo, string line)
{
// 2020.10.31 23:36:28 Log - Received Message of type: notification content: {{"id":"not_3a8f66eb-613c-4351-bee3-9980e6b5652c","senderUserId":"usr_4f76a584-9d4b-46f6-8209-8305eb683661","senderUsername":"pypy","type":"friendRequest","message":"","details":"{{}}","seen":false,"created_at":"2020-08-16T11:03:59.291Z"}} received at 10/31/2020 14:36:28 UTC
if (line.Length <= 82 ||
line[34] != 'R' ||
string.Compare(line, 34, "Received Message of type: notification content: ", 0, 48, StringComparison.Ordinal) != 0)
{
return false;
}
var pos = line.LastIndexOf("}} received at");
if (pos < 0)
{
return false;
}
var json = line.Substring(82, pos - 82 + 2); // including brace
json = json.Replace("{{", "{");
json = json.Replace("}}", "}");
AppendLog(new[]
{
fileInfo.Name,
ConvertLogTimeToISO8601(line),
"notification",
json
});
return true;
}
public void Reset() public void Reset()
{ {
if (m_Thread != null) m_ResetLog = true;
if (m_WatchThread != null)
{ {
m_Reset = true; m_WatchThread.Interrupt();
m_Thread.Interrupt();
} }
} }
public string[][] Get() public string[][] Get()
{ {
m_Lock.EnterUpgradeableReadLock(); if (m_ResetLog == false &&
try m_LogList.Count > 0)
{ {
if (m_Reset || m_LogListLock.EnterWriteLock();
m_GameLog.Count == 0)
{
return new string[][] { };
}
var array = m_GameLog.ToArray();
m_Lock.EnterWriteLock();
try try
{ {
m_GameLog.Clear(); string[][] array;
if (m_LogList.Count > 100)
{
array = new string[100][];
m_LogList.CopyTo(0, array, 0, 100);
m_LogList.RemoveRange(0, 100);
}
else
{
array = m_LogList.ToArray();
m_LogList.Clear();
}
return array;
} }
finally finally
{ {
m_Lock.ExitWriteLock(); m_LogListLock.ExitWriteLock();
} }
return array;
}
finally
{
m_Lock.ExitUpgradeableReadLock();
} }
return new string[][] { };
} }
} }
} }
+2 -2
View File
@@ -60,11 +60,11 @@ namespace VRCX
SQLite.Init(); SQLite.Init();
CpuMonitor.Init(); CpuMonitor.Init();
Discord.Init(); Discord.Init();
LogWatcher.Init(); LogWatcher.Instance.Init();
VRCXVR.Init(); VRCXVR.Init();
Application.Run(new MainForm()); Application.Run(new MainForm());
VRCXVR.Exit(); VRCXVR.Exit();
LogWatcher.Exit(); LogWatcher.Instance.Exit();
Discord.Exit(); Discord.Exit();
CpuMonitor.Exit(); CpuMonitor.Exit();
SQLite.Exit(); SQLite.Exit();
+96 -32
View File
@@ -3288,6 +3288,7 @@ CefSharp.BindObjectAsync(
API.$on('SHOW_WORLD_DIALOG', (tag) => this.showWorldDialog(tag)); API.$on('SHOW_WORLD_DIALOG', (tag) => this.showWorldDialog(tag));
API.$on('SHOW_LAUNCH_DIALOG', (tag) => this.showLaunchDialog(tag)); API.$on('SHOW_LAUNCH_DIALOG', (tag) => this.showLaunchDialog(tag));
setInterval(() => this.update(), 1000); setInterval(() => this.update(), 1000);
setInterval(() => this.refreshGameLog(), 100);
this.update(); this.update();
this.$nextTick(function () { this.$nextTick(function () {
this.$el.style.display = ''; this.$el.style.display = '';
@@ -3378,7 +3379,6 @@ CefSharp.BindObjectAsync(
}); });
} }
this.checkActiveFriends(); this.checkActiveFriends();
this.refreshGameLog();
VRCX.CheckGameRunning().then(([isGameRunning, isGameNoVR]) => { VRCX.CheckGameRunning().then(([isGameRunning, isGameNoVR]) => {
if (isGameRunning !== this.isGameRunning) { if (isGameRunning !== this.isGameRunning) {
this.isGameRunning = isGameRunning; this.isGameRunning = isGameRunning;
@@ -4417,6 +4417,8 @@ CefSharp.BindObjectAsync(
// App: gameLog // App: gameLog
var gameLogContextMap = new Map();
$app.data.lastLocation = ''; $app.data.lastLocation = '';
$app.data.lastLocation$ = {}; $app.data.lastLocation$ = {};
$app.data.discordActive = VRCXStorage.GetBool('discordActive'); $app.data.discordActive = VRCXStorage.GetBool('discordActive');
@@ -4468,38 +4470,100 @@ CefSharp.BindObjectAsync(
}); });
}; };
$app.methods.refreshGameLog = function () { $app.methods.refreshGameLog = async function () {
LogWatcher.Get().then((logs) => { if (API.isLoggedIn !== true) {
if (logs.length) { return;
var { data } = this.gameLogTable; }
for (var log of logs) {
var ctx = { var currentUser = API.currentUser.username;
created_at: String(log[0]),
type: String(log[1]), for (var [fileName, dt, type, ...args] of await LogWatcher.Get()) {
data: String(log[2]) var gameLogContext = gameLogContextMap.get(fileName);
}; if (gameLogContext === undefined) {
if (ctx.data === API.currentUser.displayName) { gameLogContext = {
continue; // auth
} loginProvider: null,
if (ctx.type === 'Location') { loginUser: null,
var tag = ctx.data;
if (tag.endsWith(':')) { // hmd
tag = tag.substr(0, tag.length - 1); hmdModel: null,
ctx.data = tag;
} // location
this.lastLocation = tag; location: null,
} };
data.push(ctx); gameLogContextMap.set(fileName, gameLogContext);
}
this.sweepGameLog();
// sweepGameLog로 기록이 삭제되면
// 아무 것도 없는데 알림이 떠서 이상함
if (data.length) {
this.notifyMenu('gameLog');
}
} }
this.updateSharedFeed();
}); var gameLogTableData = null;
switch (type) {
case 'auth':
gameLogContext.loginProvider = args[0];
gameLogContext.loginUser = args[1];
break;
case 'hmd-model':
gameLogContext.hmdModel = args[0];
break;
case 'location':
var location = args[0];
gameLogContext.location = location;
if (gameLogContext.loginUser === currentUser) {
this.lastLocation = location;
}
break;
case 'world':
// var worldName = params[0];
gameLogTableData = {
created_at: dt,
type: 'Location',
data: gameLogContext.location
};
break;
case 'player-join':
var userDisplayName = args[0];
gameLogTableData = {
created_at: dt,
type: 'OnPlayerJoined',
data: userDisplayName
};
break;
case 'player-left':
var userDisplayName = args[0];
gameLogTableData = {
created_at: dt,
type: 'OnPlayerLeft',
data: userDisplayName
};
break;
case 'notification':
var json = args[0];
gameLogTableData = {
created_at: dt,
type: 'Notification',
data: json
};
break;
}
if (gameLogTableData !== null &&
gameLogContext.loginUser === currentUser) {
this.gameLogTable.data.push(gameLogTableData);
}
}
this.sweepGameLog();
if (this.gameLogTable.data.length > 0) {
this.notifyMenu('gameLog');
}
this.updateSharedFeed();
}; };
$app.methods.sweepGameLog = function () { $app.methods.sweepGameLog = function () {