diff --git a/LogWatcher.cs b/LogWatcher.cs index 3103de06..07937411 100644 --- a/LogWatcher.cs +++ b/LogWatcher.cs @@ -1017,6 +1017,10 @@ namespace VRCX var stringData = line.Substring(lineOffset + check.Length); stringData = stringData.Remove(stringData.Length - 1); + + if (stringData.StartsWith("http://127.0.0.1:22500") || stringData.StartsWith("http://localhost:22500")) + return true; // ignore own requests + AppendLog(new[] { fileInfo.Name, @@ -1040,6 +1044,10 @@ namespace VRCX var imageData = line.Substring(lineOffset + check.Length); imageData = imageData.Remove(imageData.Length - 1); + + if (imageData.StartsWith("http://127.0.0.1:22500") || imageData.StartsWith("http://localhost:22500")) + return true; // ignore own requests + AppendLog(new[] { fileInfo.Name, diff --git a/MainForm.cs b/MainForm.cs index 307d0ab1..1fd66c5e 100644 --- a/MainForm.cs +++ b/MainForm.cs @@ -17,6 +17,7 @@ namespace VRCX public partial class MainForm : WinformBase { public static MainForm Instance; + private static NLog.Logger jslogger = NLog.LogManager.GetLogger("Javascript"); public ChromiumWebBrowser Browser; private int LastLocationX; private int LastLocationY; @@ -58,6 +59,10 @@ namespace VRCX }; Util.ApplyJavascriptBindings(Browser.JavascriptObjectRepository); + Browser.ConsoleMessage += (_, args) => + { + jslogger.Debug(args.Message + " (" + args.Source + ":" + args.Line + ")"); + }; Controls.Add(Browser); } diff --git a/Program.cs b/Program.cs index 47741085..009adef5 100644 --- a/Program.cs +++ b/Program.cs @@ -4,6 +4,8 @@ // This work is licensed under the terms of the MIT license. // For a copy, see . +using NLog; +using NLog.Targets; using System; using System.IO; using System.Threading.Tasks; @@ -19,6 +21,7 @@ namespace VRCX public static string Version { get; private set; } public static bool LaunchDebug; public static bool GPUFix; + private static NLog.Logger logger = NLog.LogManager.GetLogger("VRCX"); static Program() { BaseDirectory = AppDomain.CurrentDomain.BaseDirectory; @@ -43,15 +46,58 @@ namespace VRCX } } + private static void ConfigureLogger() + { + NLog.LogManager.Setup().LoadConfiguration(builder => + { + + var fileTarget = new FileTarget("fileTarget") + { + FileName = Path.Combine(AppDataDirectory, "logs", "VRCX.log"), + //Layout = "${longdate} [${level:uppercase=true}] ${logger} - ${message} ${exception:format=tostring}", + // Layout with padding between the level/logger and message so that the message always starts at the same column + Layout = "${longdate} [${level:uppercase=true:padding=-5}] ${logger:padding=-20} - ${message} ${exception:format=tostring}", + ArchiveFileName = Path.Combine(AppDataDirectory, "VRCX.{#}.log"), + ArchiveNumbering = ArchiveNumberingMode.DateAndSequence, + ArchiveEvery = FileArchivePeriod.Day, + MaxArchiveFiles = 4, + MaxArchiveDays = 7, + ArchiveAboveSize = 10000000, + ArchiveOldFileOnStartup = true, + ConcurrentWrites = true, + KeepFileOpen = true, + AutoFlush = true, + Encoding = System.Text.Encoding.UTF8 + }; + + if (Program.LaunchDebug) + { + builder.ForLogger().FilterMinLevel(LogLevel.Debug).WriteTo(fileTarget); + } + else + { +#if DEBUG + // Archive maximum of 3 files 10MB each, kept for a maximum of 7 days + builder.ForLogger().FilterMinLevel(LogLevel.Debug).WriteTo(fileTarget); +#else + builder.ForLogger().FilterMinLevel(LogLevel.Debug).WriteTo(fileTarget); +#endif + } + }); + } + [STAThread] private static void Main() { + ConfigureLogger(); + try { Run(); } catch (Exception e) { + logger.Fatal(e, "Unhandled Exception, program dying"); MessageBox.Show(e.ToString(), "PLEASE REPORT IN https://vrcx.pypy.moe/discord", MessageBoxButtons.OK, MessageBoxIcon.Error); Environment.Exit(0); } @@ -79,6 +125,8 @@ namespace VRCX Application.EnableVisualStyles(); Application.SetCompatibleTextRenderingDefault(false); + logger.Info("{0} Starting...", Version); + // I'll re-do this whole function eventually I swear var worldDBServer = new WorldDBManager("http://127.0.0.1:22500/"); Task.Run(worldDBServer.Start); @@ -97,6 +145,7 @@ namespace VRCX IPCServer.Instance.Init(); VRCXVR.Instance.Init(); Application.Run(new MainForm()); + logger.Info("{0} Exiting...", Version); WebApi.Instance.SaveCookies(); VRCXVR.Instance.Exit(); CefService.Instance.Exit(); diff --git a/VRCX.csproj b/VRCX.csproj index 1d0526d3..683a3e7c 100644 --- a/VRCX.csproj +++ b/VRCX.csproj @@ -202,6 +202,9 @@ 13.0.3 + + 5.2.0 + 4.2.0 diff --git a/WorldDBManager.cs b/WorldDBManager.cs index 768e963d..cb229af5 100644 --- a/WorldDBManager.cs +++ b/WorldDBManager.cs @@ -16,6 +16,7 @@ namespace VRCX public static WorldDBManager Instance; private readonly HttpListener listener; private readonly WorldDatabase worldDB; + private static NLog.Logger logger = NLog.LogManager.GetCurrentClassLogger(); private string currentWorldId = null; private string lastError = null; @@ -34,49 +35,77 @@ namespace VRCX { listener.Start(); + logger.Info("Listening for requests on {0}", listener.Prefixes.First()); while (true) { var context = await listener.GetContextAsync(); var request = context.Request; var responseData = new WorldDataRequestResponse(false, null, null); - if (MainForm.Instance?.Browser == null || MainForm.Instance.Browser.IsLoading || !MainForm.Instance.Browser.CanExecuteJavascriptInMainFrame) + try { - responseData.Error = "VRCX not yet initialized. Try again in a moment."; - responseData.StatusCode = 503; - SendJsonResponse(context.Response, responseData); - continue; - }; + if (MainForm.Instance?.Browser == null || MainForm.Instance.Browser.IsLoading || !MainForm.Instance.Browser.CanExecuteJavascriptInMainFrame) + { + logger.Warn("Received a request to {0} while VRCX is still initializing the browser window. Responding with error 503.", request.Url); - switch (request.Url.LocalPath) + responseData.Error = "VRCX not yet initialized. Try again in a moment."; + responseData.StatusCode = 503; + SendJsonResponse(context.Response, responseData); + continue; + }; + + logger.Debug("Received a request to '{0}'", request.Url); + + // TODO: Maybe an endpoint for getting a group of arbitrary keys by a group 'name'? eg; /getgroup?name=testgroup1 would return all keys with the column group set to 'testgroup1' + switch (request.Url.LocalPath) + { + case "/vrcx/data/init": + responseData = await HandleInitRequest(context); + SendJsonResponse(context.Response, responseData); + break; + case "/vrcx/data/get": + responseData = await HandleDataRequest(context); + SendJsonResponse(context.Response, responseData); + break; + case "/vrcx/data/getall": + responseData = await HandleAllDataRequest(context); + SendJsonResponse(context.Response, responseData); + break; + case "/vrcx/data/lasterror": + responseData.OK = lastError == null; + responseData.StatusCode = 200; + responseData.Data = lastError; + lastError = null; + SendJsonResponse(context.Response, responseData); + break; + case "/vrcx/data/getbulk": + responseData = await HandleBulkDataRequest(context); + SendJsonResponse(context.Response, responseData); + break; + case "/vrcx/status": + // Send a blank 200 response to indicate that the server is running. + context.Response.StatusCode = 200; + context.Response.Close(); + break; + default: + responseData.Error = "Invalid VRCX endpoint."; + responseData.StatusCode = 404; + SendJsonResponse(context.Response, responseData); + break; + } + + if (context.Response.StatusCode != 200) + { + logger.Warn("Received a request to '{0}' that returned a non-successful response. Error: {1} - {2}", request.Url, responseData.StatusCode, responseData.Error); + } + } + catch (Exception ex) { - case "/vrcx/data/init": - responseData = await HandleInitRequest(context); - SendJsonResponse(context.Response, responseData); - break; - case "/vrcx/data/get": - responseData = await HandleDataRequest(context); - SendJsonResponse(context.Response, responseData); - break; - case "/vrcx/data/lasterror": - responseData.OK = lastError == null; - responseData.Data = lastError; - lastError = null; - SendJsonResponse(context.Response, responseData); - break; - case "/vrcx/data/getbulk": - responseData = await HandleBulkDataRequest(context); - SendJsonResponse(context.Response, responseData); - break; - case "/vrcx/status": - context.Response.StatusCode = 200; - context.Response.Close(); - break; - default: - responseData.Error = "Invalid VRCX endpoint."; - responseData.StatusCode = 404; - SendJsonResponse(context.Response, responseData); - break; + logger.Error(ex, $"Exception while processing the url '{request.Url}'."); + + responseData.Error = $"VRCX has encountered an exception while processing the url '{request.Url}': {ex.Message}"; + responseData.StatusCode = 500; + SendJsonResponse(context.Response, responseData); } } @@ -90,7 +119,6 @@ namespace VRCX private async Task HandleInitRequest(HttpListenerContext context) { var request = context.Request; - var responseData = new WorldDataRequestResponse(false, null, null); if (request.QueryString["debug"] == "true") { @@ -101,19 +129,15 @@ namespace VRCX } currentWorldId = "wrld_12345"; - responseData.OK = true; - responseData.StatusCode = 200; - responseData.Data = "12345"; - return responseData; + + return ConstructSuccessResponse("12345"); } string worldId = await GetCurrentWorldID(); if (String.IsNullOrEmpty(worldId)) { - responseData.Error = "Failed to get/verify current world ID."; - responseData.StatusCode = 500; - return responseData; + return ConstructErrorResponse(500, "Failed to get/verify current world ID."); } currentWorldId = worldId; @@ -131,10 +155,8 @@ namespace VRCX connectionKey = worldDB.GetWorldConnectionKey(currentWorldId); } - responseData.OK = true; - responseData.StatusCode = 200; - responseData.Data = connectionKey; - return responseData; + logger.Info("Initialized connection to world ID '{0}' with connection key '{1}'.", currentWorldId, connectionKey); + return ConstructSuccessResponse(connectionKey); } /// @@ -145,14 +167,11 @@ namespace VRCX private async Task HandleDataRequest(HttpListenerContext context) { var request = context.Request; - var responseData = new WorldDataRequestResponse(false, null, null); var key = request.QueryString["key"]; if (key == null) { - responseData.Error = "Missing key parameter."; - responseData.StatusCode = 400; - return responseData; + return ConstructErrorResponse(400, "Missing key parameter."); } var worldIdOverride = request.QueryString["world"]; @@ -163,20 +182,12 @@ namespace VRCX if (world == null) { - responseData.OK = false; - responseData.Error = $"World ID '{worldIdOverride}' not initialized in this user's database."; - responseData.StatusCode = 200; - responseData.Data = null; - return responseData; + return ConstructErrorResponse(200, $"World ID '{worldIdOverride}' not initialized in this user's database."); } if (!world.AllowExternalRead) { - responseData.OK = false; - responseData.Error = $"World ID '{worldIdOverride}' does not allow external reads."; - responseData.StatusCode = 200; - responseData.Data = null; - return responseData; + return ConstructErrorResponse(200, $"World ID '{worldIdOverride}' does not allow external reads."); } } @@ -187,18 +198,64 @@ namespace VRCX if (worldIdOverride == null && (String.IsNullOrEmpty(currentWorldId) || worldId != currentWorldId)) { - responseData.Error = "World ID not initialized."; - responseData.StatusCode = 400; - return responseData; + return ConstructErrorResponse(400, "World ID not initialized."); } var value = worldDB.GetDataEntry(worldId, key); - responseData.OK = true; - responseData.StatusCode = 200; - responseData.Error = null; - responseData.Data = value?.Value; - return responseData; + logger.Debug("Serving a request for data with key '{0}' from world ID '{1}'.", key, worldId); + // This is intended to be null if the key doesn't exist. + return ConstructSuccessResponse(value?.Value); + } + + /// + /// Handles an HTTP listener request for all data from the world database for a given world. + /// + /// The HTTP listener context object. + /// A object containing the response data. + private async Task HandleAllDataRequest(HttpListenerContext context) + { + var request = context.Request; + + var worldIdOverride = request.QueryString["world"]; + + if (worldIdOverride != null) + { + var world = worldDB.GetWorld(worldIdOverride); + + if (world == null) + { + return ConstructErrorResponse(200, $"World ID '{worldIdOverride}' not initialized in this user's database."); + } + + if (!world.AllowExternalRead) + { + return ConstructErrorResponse(200, $"World ID '{worldIdOverride}' does not allow external reads."); + } + } + + if (currentWorldId == "wrld_12345" && worldIdOverride == null) + worldIdOverride = "wrld_12345"; + + var worldId = worldIdOverride ?? await GetCurrentWorldID(); + + if (worldIdOverride == null && (String.IsNullOrEmpty(currentWorldId) || worldId != currentWorldId)) + { + return ConstructErrorResponse(400, "World ID not initialized."); + } + + var entries = worldDB.GetAllDataEntries(worldId); + + logger.Debug("Serving a request for all data from world ID '{0}'.", worldId); + + var data = new Dictionary(); + foreach (var entry in entries) + { + data.Add(entry.Key, entry.Value); + } + + // This is intended to be null if the key doesn't exist. + return ConstructSuccessResponse(JsonConvert.SerializeObject(data)); } /// @@ -209,14 +266,11 @@ namespace VRCX private async Task HandleBulkDataRequest(HttpListenerContext context) { var request = context.Request; - var responseData = new WorldDataRequestResponse(false, null, null); var keys = request.QueryString["keys"]; if (keys == null) { - responseData.Error = "Missing/invalid keys parameter."; - responseData.StatusCode = 400; - return responseData; + return ConstructErrorResponse(400, "Missing/invalid keys parameter."); } var keyArray = keys.Split(','); @@ -225,9 +279,7 @@ namespace VRCX if (String.IsNullOrEmpty(currentWorldId) || (worldId != currentWorldId && currentWorldId != "wrld_12345")) { - responseData.Error = "World ID not initialized."; - responseData.StatusCode = 400; - return responseData; + return ConstructErrorResponse(400, "World ID not initialized."); } var values = worldDB.GetDataEntries(currentWorldId, keyArray).ToList(); @@ -249,11 +301,8 @@ namespace VRCX data.Add(dataKey, dataValue); } - responseData.OK = true; - responseData.StatusCode = 200; - responseData.Error = null; - responseData.Data = JsonConvert.SerializeObject(data); - return responseData; + logger.Debug("Serving a request for bulk data with keys '{0}' from world ID '{1}'.", keys, currentWorldId); + return ConstructSuccessResponse(JsonConvert.SerializeObject(data)); } /// @@ -274,7 +323,7 @@ namespace VRCX /// The ID of the current world as a string, or null if it could not be retrieved. private async Task GetCurrentWorldID() { - JavascriptResponse funcResult = await MainForm.Instance.Browser.EvaluateScriptAsync("$app.API.actuallyGetCurrentLocation();", TimeSpan.FromSeconds(5)); + JavascriptResponse funcResult; try { @@ -282,6 +331,7 @@ namespace VRCX } catch (Exception ex) { + logger.Error(ex, "Failed to evaluate actuallyGetCurrentLocation JS function to get current world ID."); return null; } @@ -292,12 +342,36 @@ namespace VRCX // implement // wait what was i going to do here again // seriously i forgot, hope it wasn't important + logger.Warn("actuallyGetCurrentLocation returned null or empty."); return null; } return worldId; } + private WorldDataRequestResponse ConstructSuccessResponse(string data = null) + { + var responseData = new WorldDataRequestResponse(true, null, null); + + responseData.StatusCode = 200; + responseData.Error = null; + responseData.OK = true; + responseData.Data = data; + return responseData; + } + + private WorldDataRequestResponse ConstructErrorResponse(int statusCode, string error) + { + var responseData = new WorldDataRequestResponse(true, null, null); + + responseData.StatusCode = statusCode; + responseData.Error = error; + responseData.OK = false; + responseData.Data = null; + + return responseData; + } + /// /// Sends a JSON response to an HTTP listener request with the specified response data and status code. /// @@ -346,12 +420,14 @@ namespace VRCX } catch (JsonReaderException ex) { + logger.Error(ex, json.ToString()); this.lastError = ex.Message; // invalid json return; } catch (Exception ex) { + logger.Error(ex, json.ToString()); this.lastError = ex.Message; // something else happened lol return; @@ -359,18 +435,21 @@ namespace VRCX if (String.IsNullOrEmpty(request.Key)) { + logger.Warn("World {0} tried to store data with no key provided", request.Key); this.lastError = "`key` is missing or null"; return; } if (String.IsNullOrEmpty(request.Value)) { + logger.Warn("World {0} tried to store data with no value provided", request.Key); this.lastError = "`value` is missing or null"; return; } if (String.IsNullOrEmpty(request.ConnectionKey)) { + logger.Warn("World {0} tried to store data with no connection key provided", request.Key); this.lastError = "`connectionKey` is missing or null"; return; } @@ -378,6 +457,7 @@ namespace VRCX // Make sure the connection key is a valid GUID. No point in doing anything else if it's not. if (!Guid.TryParse(request.ConnectionKey, out Guid _)) { + logger.Warn("World {0} tried to store data with an invalid GUID as a connection key {1}", request.Key, request.ConnectionKey); this.lastError = "Invalid GUID provided as connection key"; // invalid guid return; @@ -387,6 +467,7 @@ namespace VRCX string worldId = worldDB.GetWorldByConnectionKey(request.ConnectionKey); if (worldId == null) { + logger.Warn("World {0} tried to store data with invalid connection key {1}", request.Key, request.ConnectionKey); this.lastError = "Invalid connection key"; // invalid connection key return; @@ -402,6 +483,7 @@ namespace VRCX // This works, I tested it. Hopefully this prevents/limits any possible abuse. if (newTotalDataSize > 1024 * 1024 * 10) { + logger.Warn("World {0} exceeded 10MB total data size trying to store key {0}. {1}:{2} + {3} = {4}", request.Key, worldId, oldTotalDataSize - oldDataSize, newDataSize, newTotalDataSize); this.lastError = $"You have hit the 10MB total data cap. The previous data entry was *not* stored. Your request was {newDataSize} bytes, your current shared byte total is {oldTotalDataSize} and you went over the table limit by {newTotalDataSize - (1024 * 1024 * 10)} bytes."; // too much data //throw new Exception("Too much data"); @@ -411,6 +493,8 @@ namespace VRCX worldDB.AddDataEntry(worldId, request.Key, request.Value, newDataSize); worldDB.UpdateWorldDataSize(worldId, newTotalDataSize); + logger.Info("World {0} stored data entry {1} with size {2} bytes", worldId, request.Key, newDataSize); + logger.Debug("{0} : {1}", request.Key, request.Value); } public void Stop() diff --git a/WorldDatabase.cs b/WorldDatabase.cs index 34030371..993e4d00 100644 --- a/WorldDatabase.cs +++ b/WorldDatabase.cs @@ -249,6 +249,17 @@ END;"; return query.ToList(); } + /// + /// Gets all data entries for the world with the specified ID from the database. + /// + /// The ID of the world to get the data entries for. + /// An enumerable collection of all data entries for the world with the specified ID. + public IEnumerable GetAllDataEntries(string worldId) + { + var query = sqlite.Table().Where(w => w.WorldId == worldId); + return query.ToList(); + } + /// /// Gets the size of the data entry, in bytes, with the specified world ID and key from the database. /// diff --git a/html/src/app.js b/html/src/app.js index 20e7b00d..33626d0e 100644 --- a/html/src/app.js +++ b/html/src/app.js @@ -2071,19 +2071,17 @@ speechSynthesis.getVoices(); // TODO: traveling to world checks API.actuallyGetCurrentLocation = async function () { - const gameLogLocation = $app.lastLocation.location; - console.log('gameLog Location', gameLogLocation); + let gameLogLocation = $app.lastLocation.location; + if (gameLogLocation === 'traveling') { + gameLogLocation = $app.lastLocationDestination; + } + console.log('PWI: gameLog Location:', gameLogLocation); - const presence = this.currentUser.presence; let presenceLocation = this.currentUser.$locationTag; if (presenceLocation === 'traveling') { - console.log( - 'User is traveling, using $travelingToLocation', - this.currentUser.$travelingToLocation - ); presenceLocation = this.currentUser.$travelingToLocation; } - console.log('presence Location', presenceLocation); + console.log('PWI: presence Location:', presenceLocation); // We want to use presence if it's valid to avoid extra API calls, but its prone to being outdated when this function is called. // So we check if the presence location is the same as the gameLog location; If it is, the presence is (probably) valid and we can use it. @@ -2091,25 +2089,40 @@ speechSynthesis.getVoices(); // If the user happens to be offline or the api is just being dumb, we assume that the user logged into VRCX is different than the one in-game and return the gameLog location. // This is really dumb. if (presenceLocation === gameLogLocation) { - console.log('ok presence return'); - return presence.world; + console.log('PWI: locations match:', presenceLocation); + const L = this.parseLocation(presenceLocation); + return L.worldId; } - let args = await this.getUser({ userId: this.currentUser.id }); - let user = args.json; - console.log('presence bad, got user', user); - if (!$app.isRealInstance(user.location)) { - console.warn( - 'presence invalid, user offline and/or instance invalid. returning gamelog location: ', - gameLogLocation - ); - return gameLogLocation; + const args = await this.getUser({ userId: this.currentUser.id }); + const user = args.json; + let userLocation = user.location; + if (userLocation === 'traveling') { + userLocation = user.travelingToLocation; } console.warn( - 'presence outdated, got user api location instead: ', - user.location + "PWI: location didn't match, fetched user location", + userLocation ); - return this.parseLocation(user.location).worldId; + + if ($app.isRealInstance(userLocation)) { + console.warn('PWI: returning user location', userLocation); + const L = this.parseLocation(userLocation); + return L.worldId; + } + + if ($app.isRealInstance(gameLogLocation)) { + console.warn(`PWI: returning gamelog location: `, gameLogLocation); + const L = this.parseLocation(gameLogLocation); + return L.worldId; + } + + console.error( + `PWI: all locations invalid: `, + gameLogLocation, + userLocation + ); + return null; }; API.applyWorld = function (json) {