diff --git a/src/Lithnet.Pan.RAProxy.Setup/Components.wxs b/src/Lithnet.Pan.RAProxy.Setup/Components.wxs index 7ac3b84..acfa342 100644 --- a/src/Lithnet.Pan.RAProxy.Setup/Components.wxs +++ b/src/Lithnet.Pan.RAProxy.Setup/Components.wxs @@ -27,6 +27,8 @@ + + diff --git a/src/Lithnet.Pan.RAProxy/App.config b/src/Lithnet.Pan.RAProxy/App.config index ead8050..57a55c7 100644 --- a/src/Lithnet.Pan.RAProxy/App.config +++ b/src/Lithnet.Pan.RAProxy/App.config @@ -5,8 +5,8 @@ - - + + diff --git a/src/Lithnet.Pan.RAProxy/ConfigSections/Config.cs b/src/Lithnet.Pan.RAProxy/ConfigSections/Config.cs index 1cdf65d..498f068 100644 --- a/src/Lithnet.Pan.RAProxy/ConfigSections/Config.cs +++ b/src/Lithnet.Pan.RAProxy/ConfigSections/Config.cs @@ -72,6 +72,11 @@ public static void Failover() public static bool DebuggingEnabled => Config.section.DebuggingEnabled; + public static int BatchSize => Config.section.PanApi.BatchSize; + + public static int BatchWait => Config.section.PanApi.BatchWait; + + public static string GetSecretForIP(IPAddress address) { string addressStringForm = address.ToString(); diff --git a/src/Lithnet.Pan.RAProxy/ConfigSections/PanApiCollection.cs b/src/Lithnet.Pan.RAProxy/ConfigSections/PanApiCollection.cs index d81a93a..ba0646f 100644 --- a/src/Lithnet.Pan.RAProxy/ConfigSections/PanApiCollection.cs +++ b/src/Lithnet.Pan.RAProxy/ConfigSections/PanApiCollection.cs @@ -25,6 +25,34 @@ public bool DisableCertificateValidation } } + [ConfigurationProperty("batch-size", IsRequired = false, DefaultValue = 150)] + public int BatchSize + { + get + { + return (int)base["batch-size"]; + } + + set + { + base["batch-size"] = value; + } + } + + [ConfigurationProperty("batch-wait", IsRequired = false, DefaultValue = 150)] + public int BatchWait + { + get + { + return (int)base["batch-wait"]; + } + + set + { + base["batch-wait"] = value; + } + } + protected override object GetElementKey(ConfigurationElement element) { return ((PanApiEndpoint)element).ApiUri; diff --git a/src/Lithnet.Pan.RAProxy/Exceptions/AggregateUserMappingException.cs b/src/Lithnet.Pan.RAProxy/Exceptions/AggregateUserMappingException.cs new file mode 100644 index 0000000..67e255d --- /dev/null +++ b/src/Lithnet.Pan.RAProxy/Exceptions/AggregateUserMappingException.cs @@ -0,0 +1,16 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace Lithnet.Pan.RAProxy +{ + public class AggregateUserMappingException : AggregateException + { + public AggregateUserMappingException(string message, IEnumerable exceptions) + : base(message, exceptions) + { + } + } +} diff --git a/src/Lithnet.Pan.RAProxy/Exceptions/UserMappingException.cs b/src/Lithnet.Pan.RAProxy/Exceptions/UserMappingException.cs new file mode 100644 index 0000000..7b569c5 --- /dev/null +++ b/src/Lithnet.Pan.RAProxy/Exceptions/UserMappingException.cs @@ -0,0 +1,22 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace Lithnet.Pan.RAProxy +{ + public class UserMappingException : PanApiException + { + public string Username { get; private set; } + + public string IPAddress { get; private set; } + + public UserMappingException(string message, string username, string ipaddress) + :base (message) + { + this.Username = username; + this.IPAddress = ipaddress; + } + } +} diff --git a/src/Lithnet.Pan.RAProxy/Lithnet.Pan.RAProxy.csproj b/src/Lithnet.Pan.RAProxy/Lithnet.Pan.RAProxy.csproj index b023b8a..748bb9b 100644 --- a/src/Lithnet.Pan.RAProxy/Lithnet.Pan.RAProxy.csproj +++ b/src/Lithnet.Pan.RAProxy/Lithnet.Pan.RAProxy.csproj @@ -54,6 +54,8 @@ + + diff --git a/src/Lithnet.Pan.RAProxy/Logging.cs b/src/Lithnet.Pan.RAProxy/Logging.cs index 3adf63f..fdc7a8c 100644 --- a/src/Lithnet.Pan.RAProxy/Logging.cs +++ b/src/Lithnet.Pan.RAProxy/Logging.cs @@ -15,6 +15,9 @@ internal class Logging public const int EventIDApiEndpointExceptionWillFailover = 3005; public const int EventIDApiEndpointFailover = 3006; + public const int EventIDApiUserIDMappingLoginFailed= 3007; + public const int EventIDApiUserIDMappingLogoutFailed = 3008; + // Accounting Errors public const int EventIDUnknownRadiusHost = 3101; @@ -22,6 +25,7 @@ internal class Logging // Messaging errors public const int EventIDMessageSendFailure = 3201; + public const int EventIDInvalidRadiusPacket = 3202; // Info public const int EventIDAccountingRequestRecieved = 4001; @@ -33,6 +37,9 @@ internal class Logging public static PerformanceCounter CounterItemsInQueue { get; } + public static PerformanceCounter CounterFailedMappingsPerSecond { get; } + + public static void WriteEntry(string message, EventLogEntryType type, int eventID) { Trace.WriteLine(message); @@ -76,6 +83,16 @@ static Logging() MachineName = ".", ReadOnly = false }; + + Logging.CounterFailedMappingsPerSecond = new PerformanceCounter + { + CategoryName = "PANRAProxy", + CounterName = "Failed mappings / second", + MachineName = ".", + ReadOnly = false + }; + + Logging.CounterItemsInQueue.RawValue = 0; } } } diff --git a/src/Lithnet.Pan.RAProxy/PanApi/Message.cs b/src/Lithnet.Pan.RAProxy/PanApi/Message.cs index 1b13535..f86f1af 100644 --- a/src/Lithnet.Pan.RAProxy/PanApi/Message.cs +++ b/src/Lithnet.Pan.RAProxy/PanApi/Message.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Generic; using System.Text; using System.IO; using System.Net; @@ -36,49 +37,116 @@ public void Send() d.LoadXml(response); XmlNode status = d.SelectSingleNode("/response/@status"); + List exceptions = new List(); - if (status != null) + if (status == null) { - if (status.InnerText == "success") + Logging.WriteEntry($"The API called failed with an unknown result\n{response}", EventLogEntryType.Error, Logging.EventIDUnknownApiException); + throw new PanApiException($"The API called failed with an unknown result", response); + } + + if (status.InnerText == "success") + { + return; + } + + if (status.InnerText == "error") + { + XmlNodeList xmlNodeList = d.SelectNodes("/response/msg/line/uid-response/payload/logout/entry"); + + if (xmlNodeList != null) { - return; + foreach (UserMappingException ex in Message.GetExceptions(xmlNodeList)) + { + exceptions.Add(ex); + Logging.WriteEntry($"The logout user mapping for {ex.Username} with ip {ex.IPAddress} failed with message '{ex.Message}'", EventLogEntryType.Error, Logging.EventIDApiUserIDMappingLogoutFailed); + } } - if (status.InnerText == "error") - { - XmlNode message = d.SelectSingleNode("/response/msg/line/uid-response/payload/logout/entry/@message"); + xmlNodeList = d.SelectNodes("/response/msg/line/uid-response/payload/login/entry"); - if (message != null) + if (xmlNodeList != null) + { + foreach (UserMappingException ex in Message.GetExceptions(xmlNodeList)) { - if (message.InnerText.Equals("delete mapping failed", StringComparison.InvariantCultureIgnoreCase)) - { - if (!Config.DebuggingEnabled) - { - return; - } - } + exceptions.Add(ex); + Logging.WriteEntry($"The login user mapping for {ex.Username} with ip {ex.IPAddress} failed with message '{ex.Message}'", EventLogEntryType.Error, Logging.EventIDApiUserIDMappingLoginFailed); } } + } - Logging.WriteEntry($"The API called failed with status {status.InnerText}\n{response}", EventLogEntryType.Error, Logging.EventIDApiException); - throw new PanApiException($"The API called failed with status {status.InnerText}", response); - + if (exceptions.Count == 1) + { + throw exceptions[0]; } - else + + if (exceptions.Count > 1) { - Logging.WriteEntry($"The API called failed with an unknown result\n{response}", EventLogEntryType.Error, Logging.EventIDUnknownApiException); - throw new PanApiException($"The API called failed with an unknown result", response); + throw new AggregateUserMappingException("Multiple user mapping operations failed", exceptions); } } + catch (AggregateException) + { + throw; + } + catch (PanApiException) + { + throw; + } catch { - Logging.WriteEntry($"The API called failed with an unsupported response\n{response}", EventLogEntryType.Error, Logging.EventIDUnknownApiResponse); - throw new PanApiException($"The API called failed with an unsupported response", response); + Logging.WriteEntry($"An error occurred parsing the API response\n{response}", EventLogEntryType.Error, Logging.EventIDUnknownApiResponse); + throw new PanApiException($"An error occurred parsing the API response", response); } } + + private static IList GetExceptions(XmlNodeList xmlNodeList) + { + List exceptions = new List(); + + foreach (XmlNode entry in xmlNodeList) + { + UserMappingException e = GetException(entry); + + if (e != null) + { + exceptions.Add(e); + } + } + + return exceptions; + } + + private static UserMappingException GetException(XmlNode entry) + { + XmlAttributeCollection attributes = entry.Attributes; + + if (attributes == null) + { + return null; + } + + UserMappingException e = new UserMappingException( + attributes["message"]?.InnerText, + attributes["name"]?.InnerText, + attributes["ip"]?.InnerText); + + if (e.Message.Equals("delete mapping failed", StringComparison.InvariantCultureIgnoreCase)) + { + if (!Config.DebuggingEnabled) + { + return null; + } + } + + Logging.CounterFailedMappingsPerSecond.Increment(); + + return e; + } + /*\ - + @@ -90,9 +158,9 @@ public void Send() - + - */ + */ private string Submit() { @@ -131,6 +199,7 @@ private string Submit(PanApiEndpoint ep) builder.Query = queryString.ToString(); HttpWebRequest request = this.GetRequestContent(builder.Uri, messageText); + request.ServicePoint.Expect100Continue = false; using (WebResponse response = request.GetResponse()) { diff --git a/src/Lithnet.Pan.RAProxy/Program.cs b/src/Lithnet.Pan.RAProxy/Program.cs index 8d78013..ba6502c 100644 --- a/src/Lithnet.Pan.RAProxy/Program.cs +++ b/src/Lithnet.Pan.RAProxy/Program.cs @@ -25,14 +25,13 @@ public static class Program private static Task requestTask; - internal const string EventSourceName = "PanRAProxy"; + private static ManualResetEvent gate = new ManualResetEvent(true); - internal const short BatchSize = 100; - internal const long BatchWaitTime = 4000; + internal const string EventSourceName = "PanRAProxy"; public static void Main() { - bool runService = !System.Diagnostics.Debugger.IsAttached; + bool runService = !Debugger.IsAttached; if (runService) { @@ -65,10 +64,14 @@ internal static void Start() Logging.WriteEntry("Server certificate validation has been disabled. The SSL certificate on the Palo Alto device will not be validated", EventLogEntryType.Warning, Logging.EventIDServerCertificateValidationDisabled); } - if (Program.BatchSize > 1) + if (Config.BatchSize > 1) + { Program.StartBatchQueue(); + } else + { Program.StartQueue(); + } Program.listener = new AccountingListener(Config.AccountingPort); Program.listener.Start(Program.cancellationToken.Token); @@ -97,7 +100,7 @@ private static void StartQueue() { try { - + foreach (AccountingRequest request in Program.incomingRequests.GetConsumingEnumerable(Program.cancellationToken.Token)) { Logging.CounterItemsInQueue.Decrement(); @@ -130,8 +133,15 @@ private static void StartQueue() internal static void AddToQueue(AccountingRequest request) { - Program.incomingRequests.Add(request); + lock (Program.incomingRequests) + { + Program.incomingRequests.Add(request); + } + Logging.CounterItemsInQueue.Increment(); + + // Open the gate if its current closed + Program.gate.Set(); } private static void SendMessage(AccountingRequest request) @@ -202,74 +212,71 @@ private static void SendMessage(AccountingRequest request) private static void StartBatchQueue() { - Program.incomingRequests = new BlockingCollection(); + Program.incomingRequests = new BlockingCollection(); Program.requestTask = new Task(() => { try { - Stopwatch timeCounter = new Stopwatch(); - List batchedRequests = new List(); // Keep processing until the task is cancelled while (!Program.cancellationToken.IsCancellationRequested) { - short batchMessageCount = 0; // How many messages are currently batched for send - int msLeftToBatch = (int)Program.BatchWaitTime; // How many milliseconds are left before we try to send the next batch message - - // Start counting down before we send - timeCounter.Reset(); - timeCounter.Start(); - - // Batch all messages received in the next x seconds - while (msLeftToBatch > 0 && batchMessageCount <= Program.BatchSize) + // Batch all messages received + while (batchedRequests.Count <= Config.BatchSize) { AccountingRequest nextRequest; // If we still have time, and there's an item in the queue, block until we get it - if (msLeftToBatch >= 0 && Program.incomingRequests.TryTake(out nextRequest, msLeftToBatch, Program.cancellationToken.Token)) + if (Program.incomingRequests.TryTake(out nextRequest, Config.BatchWait, Program.cancellationToken.Token)) { // Successfully retrieved an item - batchMessageCount += 1; Logging.CounterItemsInQueue.Decrement(); // Store in the list to be sent batchedRequests.Add(nextRequest); // Debug info - Logging.WriteDebugEntry($"Incoming accounting request received\n{nextRequest}", EventLogEntryType.Information, Logging.EventIDAccountingRequestRecieved); + Trace.WriteLine($"Incoming accounting request dequeued\n{nextRequest}"); Trace.WriteLine($"Request queue lenth: {Program.incomingRequests.Count}"); - - // Time left before we send whatever we have - msLeftToBatch = (int)(Program.BatchWaitTime - timeCounter.ElapsedMilliseconds); - } else { // No item to retrieve in elapsed time - timeCounter.Stop(); - msLeftToBatch = 0; + break; } - } // Send what we have - if (batchMessageCount > 0) + if (batchedRequests.Count > 0) { try { Program.SendBatchMessage(batchedRequests); - batchedRequests.Clear(); } catch (Exception ex) { Logging.WriteEntry($"An error occured while submitting the user-id update\n{ex.Message}\n{ex.StackTrace}", EventLogEntryType.Error, Logging.EventIDMessageSendFailure); } + finally + { + batchedRequests.Clear(); + } + } + lock (Program.incomingRequests) + { + if (Program.incomingRequests.Count == 0) + { + // Close the gate. AddToQueue will re-open the gate when a new item comes in + Program.gate.Reset(); + } } - } + // Wait for the gate to open if its closed. + WaitHandle.WaitAny(new[] { Program.cancellationToken.Token.WaitHandle, Program.gate }); + } } catch (OperationCanceledException) { @@ -283,10 +290,15 @@ private static void StartBatchQueue() private static void SendBatchMessage(List requests) { UidMessage message = new UidMessage { Payload = new Payload() }; - int batchedCount = requests.Count; int loginCount = 0; int logoutCount = 0; + if (requests == null || requests.Count <= 0) + { + Trace.WriteLine($"No requests were in the batch to send"); + return; + } + foreach (AccountingRequest request in requests) { try @@ -305,7 +317,10 @@ private static void SendBatchMessage(List requests) case 1: // Accounting start if (message.Payload.Login == null) + { message.Payload.Login = new Login(); + } + message.Payload.Login.Entries.Add(e); loginCount++; break; @@ -313,29 +328,45 @@ private static void SendBatchMessage(List requests) case 2: // Accounting stop if (message.Payload.Logout == null) + { message.Payload.Logout = new Logout(); + } + message.Payload.Logout.Entries.Add(e); logoutCount++; break; default: - // Unknown type error? + Logging.WriteDebugEntry($"A radius accounting packet was discarded because it was of an unknown type.\n{request}", EventLogEntryType.Warning, Logging.EventIDInvalidRadiusPacket); break; } - } catch (MissingValueException mv) { - Logging.WriteDebugEntry($"A radius accounting packet was discarded because it had incomplete information.\n{mv.Message}", EventLogEntryType.Warning, Logging.EventIDMessageSendFailure); + Logging.WriteDebugEntry($"A radius accounting packet was discarded because it had incomplete information.\n{mv.Message}", EventLogEntryType.Warning, Logging.EventIDInvalidRadiusPacket); } - } + int sending = loginCount + logoutCount; + try { - Logging.CounterSentPerSecond.Increment(); + if (sending <= 0) + { + Trace.WriteLine($"Nothing to send in batch. {requests.Count} were discarded"); + return; + } + + Trace.WriteLine($"Sending batch of {sending}"); message.Send(); - Logging.WriteEntry($"UserID API mapping succeeded\nLogins: {loginCount}\nLogouts: {logoutCount}\nErrors: {batchedCount - (loginCount + logoutCount)}", EventLogEntryType.Information, Logging.EventIDUserIDUpdateComplete); + Logging.CounterSentPerSecond.IncrementBy(sending); + Trace.WriteLine($"Batch completed"); + Logging.WriteEntry($"UserID API mapping succeeded\nLogins: {loginCount}\nLogouts: {logoutCount}\n", EventLogEntryType.Information, Logging.EventIDUserIDUpdateComplete); + } + catch (AggregateUserMappingException ex) + { + Logging.WriteEntry($"{ex.Message}\n{ex.InnerExceptions.Count} in batch out of {sending} failed", EventLogEntryType.Error, Logging.EventIDMessageSendFailure); + Logging.CounterSentPerSecond.IncrementBy(sending); } catch (PanApiException ex) { @@ -346,6 +377,5 @@ private static void SendBatchMessage(List requests) Logging.WriteEntry($"An error occured while submitting the user-id update\n{ex.Message}\n{ex.StackTrace}", EventLogEntryType.Error, Logging.EventIDMessageSendFailure); } } - } }