diff --git a/LibreMetaverse/Capabilities/EventQueueClient.cs b/LibreMetaverse/Capabilities/EventQueueClient.cs index 1dd35534..c861dbd9 100644 --- a/LibreMetaverse/Capabilities/EventQueueClient.cs +++ b/LibreMetaverse/Capabilities/EventQueueClient.cs @@ -1,6 +1,6 @@ /* * Copyright (c) 2006-2016, openmetaverse.co - * Copyright (c) 2022-2023, Sjofn LLC. + * Copyright (c) 2022-2024, Sjofn LLC. * All rights reserved. * * - Redistribution and use in source and binary forms, with or without @@ -27,6 +27,7 @@ using System; using System.Collections; +using System.IO; using System.Net; using System.Net.Http; using System.Threading; @@ -50,267 +51,351 @@ namespace OpenMetaverse.Http public bool Running { get; private set; } - private readonly Uri _Address; - private readonly Simulator _Simulator; - private readonly CancellationTokenSource _queueCts; - private bool _Dead; - private OSD _AckPayload; - + protected readonly Uri Address; + protected readonly Simulator Simulator; + protected string LastError = "Undefined"; + private CancellationTokenSource _httpCts; + protected bool Dead; /// Number of times we've received an unknown CAPS exception in series. private int _errorCount; public EventQueueClient(Uri eventQueueLocation, Simulator sim) { - _Address = eventQueueLocation; - _Simulator = sim; - _queueCts = new CancellationTokenSource(); + Address = eventQueueLocation; + Simulator = sim; + _httpCts = new CancellationTokenSource(); + } + + public void RestartIfDead() + { + if (Dead) + { + Start(); + } } public void Start() { - _Dead = false; + Dead = false; Running = true; - Task.Factory.StartNew(() => - { - // Initial request - _AckPayload = new OSDMap { ["ack"] = new OSD(), ["done"] = OSD.FromBoolean(false) }; - var initialTimeoutCts = CancellationTokenSource.CreateLinkedTokenSource(_queueCts.Token); - initialTimeoutCts.CancelAfter(TimeSpan.FromSeconds(30)); - - Task initialReq = _Simulator.Client.HttpCapsClient.PostRequestAsync(_Address, OSDFormat.Xml, _AckPayload, - initialTimeoutCts.Token, RequestCompletedHandler, null, ConnectedResponseHandler); - - initialReq.Wait(initialTimeoutCts.Token); - initialTimeoutCts.Dispose(); - - while (Running && !_queueCts.Token.IsCancellationRequested) - { - if (_errorCount > 0) - { // Exponentially back off, so we don't hammer the CPU - while (!_queueCts.Token.IsCancellationRequested) - { - _queueCts.Token.WaitHandle.WaitOne( - Math.Min(REQUEST_BACKOFF_SECONDS + _errorCount * REQUEST_BACKOFF_SECONDS_INC, - REQUEST_BACKOFF_SECONDS_MAX)); - } - } - // Resume the connection. - if (!_queueCts.Token.IsCancellationRequested) - { - using (CancellationTokenSource timeoutCts = - CancellationTokenSource.CreateLinkedTokenSource(_queueCts.Token)) - { - timeoutCts.CancelAfter(TimeSpan.FromSeconds(30)); - - try - { - Task req = _Simulator.Client.HttpCapsClient.PostRequestAsync(_Address, OSDFormat.Xml, - _AckPayload, timeoutCts.Token, RequestCompletedHandler); - req.Wait(timeoutCts.Token); - } - catch (OperationCanceledException) - { - /*no-op*/ - } - } - } - - - // If the event queue is dead at this point, turn it off since - // that was the last thing we want to do - if (_Dead) - { - Running = false; - Logger.DebugLog($"Sent event queue shutdown message for {_Simulator}"); - } - } - - }, _queueCts.Token); // TOOD: TaskCreationOptions.LongRunning? + // Create an EventQueueGet request + OSDMap payload = new OSDMap { ["ack"] = new OSD(), ["done"] = OSD.FromBoolean(false) }; + _httpCts = new CancellationTokenSource(); + Task req = Simulator.Client.HttpCapsClient.PostRequestAsync(Address, OSDFormat.Xml, payload, + _httpCts.Token, + RequestCompletedHandler, null, + ConnectedResponseHandler); } public void Stop(bool immediate) { - _Dead = true; + Dead = true; if (immediate) { Running = false; } - _queueCts.Cancel(); + _httpCts.Cancel(); } void ConnectedResponseHandler(HttpResponseMessage response) { - if (!response.IsSuccessStatusCode) { return; } + if (!response.IsSuccessStatusCode) + { + return; + } Running = true; // The event queue is starting up for the first time if (OnConnected != null) { - try { OnConnected(); } - catch (Exception ex) { Logger.Log(ex.Message, Helpers.LogLevel.Error, ex); } + try + { + OnConnected(); + } + catch (Exception ex) + { + Logger.Log(ex.Message, Helpers.LogLevel.Error, ex); + } } } void RequestCompletedHandler(HttpResponseMessage response, byte[] responseData, Exception error) { - OSDArray events = null; - int ack = 0; + // Ignore anything if we're no longer connected to the sim. + if (!Simulator.Connected) { return; } - if (responseData != null) + try { - _errorCount = 0; - // Got a response - if (OSDParser.DeserializeLLSDXml(responseData) is OSDMap result) + OSDArray events = null; + var ack = 0; + + if (responseData != null) { - events = result["events"] as OSDArray; - ack = result["id"].AsInteger(); - } - else - { - Logger.Log($"Received an invalid response from {_Simulator} event queue: \"" + - System.Text.Encoding.UTF8.GetString(responseData) + "\"", Helpers.LogLevel.Warning); - } - } - else if (response != null && error != null) - { - #region Error handling - - switch (response.StatusCode) - { - case HttpStatusCode.NotFound: - case HttpStatusCode.Gone: - Logger.Log($"Closing event queue at {_Simulator} due to missing caps URI", Helpers.LogLevel.Info, _Simulator.Client); + _errorCount = 0; + // Got a response + if (OSDParser.DeserializeLLSDXml(responseData) is OSDMap result) + { + events = result["events"] as OSDArray; + ack = result["id"].AsInteger(); + } + else + { + var responseString = System.Text.Encoding.UTF8.GetString(responseData); - Running = false; - _Dead = true; - break; - case (HttpStatusCode)499: // weird error returned occasionally, ignore for now - // I believe this is the timeout error invented by LL for LSL HTTP-out requests (gwyneth 20220413) - Logger.Log($"Possible HTTP-out timeout error from {_Simulator}, no need to continue", Helpers.LogLevel.Debug, _Simulator.Client); - - Running = false; - _Dead = true; - break; - case HttpStatusCode.InternalServerError: - // As per LL's instructions, we ought to consider this a - // 'request to close client' (gwyneth 20220413) - Logger.Log($"Grid sent a {response.StatusCode} at {_Simulator}, closing connection", Helpers.LogLevel.Debug, _Simulator.Client); - - // ... but do we happen to have an InnerException? Log it! - if (error.InnerException != null) - { - // unravel the whole inner error message, so we finally figure out what it is! - // (gwyneth 20220414) - Logger.Log($"Unrecognized internal caps exception from {_Simulator}: '{error.InnerException.Message}'", - Helpers.LogLevel.Warning, _Simulator.Client); - Logger.Log($"\nMessage ---\n{error.Message}", Helpers.LogLevel.Warning, _Simulator.Client); - if (error.Data.Count > 0) - { - Logger.Log(" Extra details:", Helpers.LogLevel.Warning); - foreach (DictionaryEntry de in error.Data) - { - Logger.Log(String.Format(" Key: {0,-20} Value: '{1}'", - de.Key, de.Value), - Helpers.LogLevel.Warning, _Simulator.Client); - } - } - // but we'll nevertheless close this connection (gwyneth 20220414) - } - - Running = false; - _Dead = true; - break; - case HttpStatusCode.BadGateway: - // This is not good (server) protocol design, but it's normal. - // The EventQueue server is a proxy that connects to a Squid - // cache which will time out periodically. The EventQueue server - // interprets this as a generic error and returns a 502 to us - // that we ignore - // - // Note: if this condition persists, it _might_ be the grid trying to request - // that the client closes the connection, as per LL's specs (gwyneth 20220414) - Logger.Log($"Grid sent a Bad Gateway Error at {_Simulator}; " + - $"probably a time-out from the grid's EventQueue server (normal) -- ignoring and continuing", - Helpers.LogLevel.Debug, _Simulator.Client); - break; - default: - ++_errorCount; - - // Try to log a meaningful error message - if (response.StatusCode != HttpStatusCode.OK) + if (responseString.Contains("502 Proxy Error")) { - Logger.Log($"Unrecognized caps connection problem from {_Simulator}: {response.StatusCode} {response.ReasonPhrase}", - Helpers.LogLevel.Warning, _Simulator.Client); - } - else if (error.InnerException != null) + // LL's "go ask again" message. + } + else if (responseString.Contains("")) { - // see comment above (gwyneth 20220414) - Logger.Log($"Unrecognized internal caps exception from {_Simulator}: '{error.InnerException.Message}'", - Helpers.LogLevel.Warning, _Simulator.Client); - Logger.Log($"Message ---\n{error.Message}", Helpers.LogLevel.Warning, _Simulator.Client); - if (error.Data.Count > 0) - { - Logger.Log(" Extra details:", Helpers.LogLevel.Warning, _Simulator.Client); - foreach (DictionaryEntry de in error.Data) - { - Logger.Log(string.Format(" Key: {0,-20} Value: {1}", - "'" + de.Key + "'", de.Value), - Helpers.LogLevel.Warning, _Simulator.Client); - } - } + Running = false; + Dead = true; + LastError = responseString; } else { - Logger.Log($"Unrecognized caps exception from {_Simulator}: {error.Message}", - Helpers.LogLevel.Warning, _Simulator.Client); + Logger.Log($"Got an unparseable response (1) from {Simulator} event queue: \"" + + responseString + "\"", Helpers.LogLevel.Warning); } - break; - } // end switch + } + } + else if (error != null) + { + #region Error handling - #endregion Error handling + if (response == null) // This happens during a timeout (i.e. normal eventqueue operation.) + { + if (error is IOException || error is HttpRequestException) + { + // Ignore. + } + else + { + Logger.Log($"Got an unparseable response (2) from {Simulator} event queue: \"{error}\"", Helpers.LogLevel.Error); + } + } + else switch (response.StatusCode) + { + case HttpStatusCode.NotFound: + case HttpStatusCode.Gone: + Logger.Log($"Closing event queue at {Simulator} due to missing caps URI", + Helpers.LogLevel.Info); + + Running = false; + Dead = true; + LastError = "Missing Caps URI"; + break; + case (HttpStatusCode)499: // weird error returned occasionally, ignore for now + // I believe this is the timeout error invented by LL for LSL HTTP-out requests (gwyneth 20220413) + Logger.Log($"Possible HTTP-out timeout error from {Simulator}, no need to continue", + Helpers.LogLevel.Debug); + + Running = false; + Dead = true; + LastError = "HTTP Timeout"; + break; + + case HttpStatusCode.InternalServerError: + if (error != null) + { + var responseString = (responseData == null) ? string.Empty : System.Text.Encoding.UTF8.GetString(responseData); + if (responseData == null || responseData.Length == 0) + { + try + { + responseString = response.Content.ReadAsStringAsync().Result; + } + catch (Exception) { /* no-op */ } + } + + if (!responseString.Contains("502 Proxy Error")) + { + Logger.Log($"Grid sent a {response.StatusCode} : {response.ReasonPhrase} at {Simulator}", Helpers.LogLevel.Debug, Simulator.Client); + + if (!string.IsNullOrEmpty(responseString)) + { + Logger.Log("Full response was: " + responseString, Helpers.LogLevel.Debug, Simulator.Client); + } + + if (error.InnerException != null) + { + if (!error.InnerException.Message.Contains("502 Proxy Error")) + { + Running = false; + Dead = true; + LastError = error.ToString(); + } + } + else + { + const bool WILLFULLY_IGNORE_LL_SPECS_ON_EVENT_QUEUE = true; + + if (!WILLFULLY_IGNORE_LL_SPECS_ON_EVENT_QUEUE || !Simulator.Connected) + { + Running = false; + Dead = true; + LastError = error.ToString(); + } + } + } + else + { + // It's the typical re-queue for event queue get + } + } + else + { + Logger.Log($"Grid sent a {response.StatusCode} at {Simulator}", Helpers.LogLevel.Debug); + } + + break; + + case HttpStatusCode.BadGateway: + // This is not good (server) protocol design, but it's normal. + // The EventQueue server is a proxy that connects to a Squid + // cache which will time out periodically. The EventQueue server + // interprets this as a generic error and returns a 502 to us + // that we ignore + // + // Note: if this condition persists, it _might_ be the grid trying to request + // that the client closes the connection, as per LL's specs (gwyneth 20220414) + Logger.Log($"Grid sent a Bad Gateway Error at {Simulator}; " + + $"probably a time-out from the grid's EventQueue server (normal) -- ignoring and continuing", + Helpers.LogLevel.Debug); + break; + default: + ++_errorCount; + + // Try to log a meaningful error message + if (response.StatusCode != HttpStatusCode.OK) + { + Logger.Log($"Unrecognized caps connection problem from {Simulator}: {response.StatusCode} {response.ReasonPhrase}", + Helpers.LogLevel.Warning); + } + else if (error.InnerException != null) + { + // see comment above (gwyneth 20220414) + Logger.Log($"Unrecognized internal caps exception from {Simulator}: '{error.InnerException.Message}'", + Helpers.LogLevel.Warning); + Logger.Log($"Message ---\n{error.Message}", Helpers.LogLevel.Warning); + if (error.Data.Count > 0) + { + Logger.Log(" Extra details:", Helpers.LogLevel.Warning); + foreach (DictionaryEntry de in error.Data) + { + Logger.Log(string.Format(" Key: {0,-20} Value: {1}", + "'" + de.Key + "'", de.Value), + Helpers.LogLevel.Warning); + } + } + } + else + { + Logger.Log($"Unrecognized caps exception from {Simulator}: {error.Message}", + Helpers.LogLevel.Warning); + } + + break; + } // end switch + + #endregion Error handling + } + else + { + ++_errorCount; + + Logger.Log($"No response from {Simulator} event queue but no reported error either", + Helpers.LogLevel.Warning); + } + +#pragma warning disable CS0164 // This label has not been referenced + HandlingDone: + + #region Resume the connection + + if (Running) + { + OSDMap payload = new OSDMap(); + if (ack != 0) + { + payload["ack"] = OSD.FromInteger(ack); + } + else + { + payload["ack"] = new OSD(); + } + + bool simShutdown = Simulator.Connected; + + payload["done"] = OSD.FromBoolean(!simShutdown /*_Dead*/); + + if (_errorCount > 0) + { + // Exponentially back off, so we don't hammer the CPU + Thread.Sleep(Math.Min(REQUEST_BACKOFF_SECONDS + _errorCount * REQUEST_BACKOFF_SECONDS_INC, + REQUEST_BACKOFF_SECONDS_MAX)); + } + + // Resume the connection. + Task req = Simulator.Client.HttpCapsClient.PostRequestAsync(Address, OSDFormat.Xml, payload, + _httpCts.Token, + RequestCompletedHandler); + + // If the event queue is dead at this point, turn it off since + // that was the last thing we want to do + if (Dead) + { + Running = false; + Logger.DebugLog($"Sent event queue shutdown message for {Simulator}"); + } + } + else + { + //if (Dead && Simulator.Connected && false) + //{ + // Thread.Sleep(5000); + // if (Dead && Simulator.Connected) + // { + // RestartIfDead(); + // } + //} + } + + #endregion Resume the connection + + #region Handle incoming events + + if (OnEvent == null || events == null || events.Count <= 0) return; + // Fire callbacks for each event received + foreach (var osd in events) + { + var evt = (OSDMap)osd; + string msg = evt["message"].AsString(); + OSDMap body = (OSDMap)evt["body"]; + + try + { + OnEvent(msg, body); + } + catch (Exception ex) + { + Logger.Log(ex.Message, Helpers.LogLevel.Error, ex); + } + } + + #endregion Handle incoming events } - else if (error != null) + + catch (Exception e) { - ++_errorCount; - Logger.Log($"Exception thrown from {_Simulator} event queue: " + - $"{(error.InnerException != null ? error.InnerException.Message : error.Message)}", Helpers.LogLevel.Warning, _Simulator.Client); + Logger.Log($"Exception in EventQueueGet handler; {e.Message}", Helpers.LogLevel.Error, e); } - else - { - ++_errorCount; - Logger.Log($"No response from {_Simulator} event queue with no reported error", Helpers.LogLevel.Warning, _Simulator.Client); - } - - if (Running) - { - OSDMap payload = new OSDMap(); - if (ack != 0) { payload["ack"] = OSD.FromInteger(ack); } - else { payload["ack"] = new OSD(); } - payload["done"] = OSD.FromBoolean(_Dead); - _AckPayload = payload; - } - - #region Handle incoming events - - if (OnEvent == null || events == null || events.Count <= 0) return; - // Fire callbacks for each event received - foreach (var osd in events) - { - var evt = (OSDMap) osd; - string msg = evt["message"].AsString(); - OSDMap body = (OSDMap)evt["body"]; - - try { OnEvent(msg, body); } - catch (Exception ex) { Logger.Log(ex.Message, Helpers.LogLevel.Error, ex); } - } - - #endregion Handle incoming events } } } diff --git a/LibreMetaverse/Capabilities/HttpCapsClient.cs b/LibreMetaverse/Capabilities/HttpCapsClient.cs index 9f31663f..884a116a 100644 --- a/LibreMetaverse/Capabilities/HttpCapsClient.cs +++ b/LibreMetaverse/Capabilities/HttpCapsClient.cs @@ -1,5 +1,5 @@ /* - * Copyright (c) 2022-2023, Sjofn, LLC. + * Copyright (c) 2022-2024, Sjofn, LLC. * All rights reserved. * * - Redistribution and use in source and binary forms, with or without @@ -30,6 +30,7 @@ using System.Net.Http; using System.Net.Http.Headers; using System.Threading; using System.Threading.Tasks; +using OpenMetaverse; using OpenMetaverse.StructuredData; namespace LibreMetaverse @@ -95,9 +96,16 @@ namespace LibreMetaverse SerializeData(format, payload, out var serialized, out var contentType); using (var request = new HttpRequestMessage(HttpMethod.Post, uri)) { - request.Content = new ByteArrayContent(serialized); - request.Content.Headers.ContentType = contentType; - await SendRequestAsync(request, cancellationToken, completeHandler, progressHandler, connectedHandler); + try + { + request.Content = new ByteArrayContent(serialized); + request.Content.Headers.ContentType = contentType; + await SendRequestAsync(request, cancellationToken, completeHandler, progressHandler, connectedHandler); + } + catch (Exception e) + { + Logger.Log("Error in HTTP request; " + e, Helpers.LogLevel.Error, null, e); + } } } @@ -237,13 +245,15 @@ namespace LibreMetaverse try { using (var response = (cancellationToken.HasValue) - ? await SendAsync(request, HttpCompletionOption.ResponseHeadersRead, cancellationToken.Value) - : await SendAsync(request, HttpCompletionOption.ResponseHeadersRead)) + ? await SendAsync(request, HttpCompletionOption.ResponseHeadersRead, + cancellationToken.Value) + : await SendAsync(request, HttpCompletionOption.ResponseHeadersRead)) { if (!response.IsSuccessStatusCode) { completeHandler?.Invoke(response, null, - new HttpRequestException(response.StatusCode + " " + response.ReasonPhrase)); + new HttpRequestException(response.StatusCode + " " + + response.ReasonPhrase)); } connectedHandler?.Invoke(response); @@ -251,9 +261,17 @@ namespace LibreMetaverse await ProcessResponseAsync(response, cancellationToken, completeHandler, progressHandler); } } - catch (HttpRequestException ex) + catch (TaskCanceledException) { - completeHandler?.Invoke(null, null, ex); + /* noop */ + } + catch (HttpRequestException httpReqEx) + { + completeHandler?.Invoke(null, null, httpReqEx); + } + catch (IOException ioex) + { + completeHandler?.Invoke(null, null, ioex); } } diff --git a/LibreMetaverse/Caps.cs b/LibreMetaverse/Caps.cs index a2b0aa50..920ede08 100644 --- a/LibreMetaverse/Caps.cs +++ b/LibreMetaverse/Caps.cs @@ -73,6 +73,8 @@ namespace OpenMetaverse /// listening for incoming events public bool IsEventQueueRunning => _EventQueueCap != null && _EventQueueCap.Running; + public EventQueueClient EventQueue => _EventQueueCap; + /// /// Default constructor /// @@ -282,32 +284,37 @@ namespace OpenMetaverse return; } - OSD result = OSDParser.Deserialize(responseData); - if (result is OSDMap respMap) + try { - foreach (var cap in respMap.Keys) + OSD result = OSDParser.Deserialize(responseData); + if (result is OSDMap respMap) { - _Caps[cap] = respMap[cap].AsUri(); + foreach (var cap in respMap.Keys) + { + _Caps[cap] = respMap[cap].AsUri(); + } + + if (_Caps.ContainsKey("EventQueueGet")) + { + Logger.DebugLog($"Starting event queue for {Simulator}", Simulator.Client); + + _EventQueueCap = new EventQueueClient(_Caps["EventQueueGet"], Simulator); + _EventQueueCap.OnConnected += EventQueueConnectedHandler; + _EventQueueCap.OnEvent += EventQueueEventHandler; + _EventQueueCap.Start(); + } + + OnCapabilitiesReceived(Simulator); } - - if (_Caps.ContainsKey("EventQueueGet")) - { - Logger.DebugLog($"Starting event queue for {Simulator}", Simulator.Client); - - _EventQueueCap = new EventQueueClient(_Caps["EventQueueGet"], Simulator); - _EventQueueCap.OnConnected += EventQueueConnectedHandler; - _EventQueueCap.OnEvent += EventQueueEventHandler; - _EventQueueCap.Start(); - } - - OnCapabilitiesReceived(Simulator); + } + catch (LitJson.JsonException) + { + Logger.Log("Invalid caps response; '" + System.Text.Encoding.UTF8.GetString(responseData) + "' for seed request.", Helpers.LogLevel.Warning, Simulator.Client); } } private void EventQueueConnectedHandler() { - Logger.DebugLog($"Event queue for {Simulator} is connected", Simulator.Client); - Simulator.DisconnectCandidate = false; Simulator.Client.Network.RaiseConnectedEvent(Simulator); }