DYN-6412 fix performance issue with feature flags, and deadlock with CLI wrapper.

src/DynamoUtilities/DynamoFeatureFlagsManager.cs

@@ -24,6 +24,16 @@ internal class DynamoFeatureFlagsManager : CLIWrapper
         private Dictionary<string, object> AllFlagsCache { get; set; }//TODO lock is likely overkill.
         private SynchronizationContext syncContext;
         internal static event Action FlagsRetrieved;
+
+        //TODO(DYN-6464)- remove this field!.
+        /// <summary>
+        /// set to true after some FF issue is logged. For now we only log once to avoid clients overwhelming the logger.
+        /// </summary>
+        private bool loggedFFIssueOnce = false;
+        /// <summary>
+        /// Timeout in ms for feature flag communication with CLI process.
+        /// </summary>
+        private const int featureFlagTimeoutMs = 5000;
 
         /// <summary>
         /// Constructor
@@ -54,18 +64,18 @@ internal void CacheAllFlags()
         {
 
             //wait for response
-            var dataFromCLI = GetData();
+            var dataFromCLI = GetData(featureFlagTimeoutMs).Result;    
             //convert from json string to dictionary.
             try
-            {  
+            {
                 AllFlagsCache = JsonConvert.DeserializeObject<Dictionary<string, object>>(dataFromCLI);
                 //invoke the flags retrieved event on the sync context which should be the main ui thread.
                 syncContext?.Send((_) =>
-                {   
+                {
                     FlagsRetrieved?.Invoke();
 
-                },null);
-                
+                }, null);
+
             }
             catch (Exception e)
             {
@@ -74,34 +84,45 @@ internal void CacheAllFlags()
         }
 
         /// <summary>
-        /// Check feature flag value, if not exist, return defaultval
+        /// Check feature flag value, if it does not exist, return the defaultval.
         /// </summary>
-        /// <typeparam name="T"></typeparam>
-        /// <param name="featureFlagKey"></param>
-        /// <param name="defaultval"></param>
+        /// <typeparam name="T">Must be a bool or string, only bool or string flags should be created unless this implementation is improved.</typeparam>
+        /// <param name="featureFlagKey">feature flag name</param>
+        /// <param name="defaultval">Currently the flag and default val MUST be a bool or string.</param>
         /// <returns></returns>
         internal T CheckFeatureFlag<T>(string featureFlagKey, T defaultval)
         {
             if(!(defaultval is bool || defaultval is string)){
-                RaiseMessageLogged("unsupported flag type");
-                return defaultval;
+                throw new ArgumentException("unsupported flag type", defaultval.GetType().ToString());
             }
             // if we have not retrieved flags from the cli return empty
-            // and log.
+            // and log once.
 
             if(AllFlagsCache == null)
-            {
-                RaiseMessageLogged("the flags cache is null, something went wrong retrieving feature flags," +
-                  " or you need to wait longer for the cache to populate, you can use the static FlagsRetrieved event for this purpose. ");
+            {   //TODO(DYN-6464) Revisit this and log more when the logger is not easily overwhelmed.
+                if (!loggedFFIssueOnce)
+                {
+                    RaiseMessageLogged(
+                        $"The flags cache was null while checking {featureFlagKey}, something went wrong retrieving feature flags," +
+                        " or you need to wait longer for the cache to populate before checking for flags, you can use the static FlagsRetrieved event for this purpose." +
+                        "This message will not be logged again, and future calls to CheckFeatureFlags will return default values!!!");
+                }
+
+                loggedFFIssueOnce = true;
                 return defaultval;
             }
-            if (AllFlagsCache.ContainsKey(featureFlagKey))
+            if (AllFlagsCache.TryGetValue(featureFlagKey, out var flagVal))
             {
-                return (T)AllFlagsCache[featureFlagKey];
+                return (T)flagVal;
             }
             else
             {
-                RaiseMessageLogged($"failed to get value for feature flag key ex: {featureFlagKey},{System.Environment.NewLine} returning default value: {defaultval}");
+                if (!loggedFFIssueOnce)
+                {
+                    RaiseMessageLogged(
+                        $"failed to get value for feature flag key ex: {featureFlagKey},{System.Environment.NewLine} returning default value: {defaultval}");
+                }
+                loggedFFIssueOnce = true;
                 return defaultval;
             }
         }

src/DynamoUtilities/Md2Html.cs

@@ -3,7 +3,10 @@
 using System.Diagnostics;
 using System.IO;
 using System.Reflection;
+using System.Threading;
+using System.Threading.Tasks;
 using DynamoUtilities.Properties;
+using Newtonsoft.Json.Linq;
 
 namespace Dynamo.Utilities
 {
@@ -49,7 +52,7 @@ protected virtual void StartProcess(string relativeEXEPath, string argString)
             {
                 process.Start();
                 started = true;
-                //the only purspose here is to avoid deadlocks when std err gets filled up 4kb
+                //the only purpose here is to avoid deadlocks when std err gets filled up 4kb
                 //in long running processes.
                 process.ErrorDataReceived += Process_ErrorDataReceived;
                 process.BeginErrorReadLine();
@@ -93,53 +96,63 @@ protected static string GetToolPath(string relativePath)
             var toolPath = Path.Combine(rootPath,relativePath);
             return toolPath;
         }
-        //TODO if we see any issues with deadlocks we can try using a timeout on another thread.
         /// <summary>
         /// Read data from CLI tool
-        /// <returns>Returns data read from CLI tool</returns>
         /// </summary>
-        protected virtual string GetData()
+        /// <param name="timeoutms">will return empty string if we don't finish reading all data in the timeout provided in milliseconds.</param>
+        /// <returns></returns>
+        protected virtual async Task<string> GetData(int timeoutms)
         {
-            if (process.HasExited)
+            var readStdOutTask = Task.Run(() =>
             {
-                return string.Empty;
-            }
-            using (var writer = new StringWriter())
-            {
-                var done = false;
-                var start = false;
-                while (!done)
+                if (process.HasExited)
+                {
+                    return string.Empty;
+                }
+
+                using (var writer = new StringWriter())
                 {
-                    try
+                    var done = false;
+                    var start = false;
+                    while (!done)
                     {
-                        var line = process.StandardOutput.ReadLine();
-                        MessageLogged?.Invoke(line);
-                        if (line == null || line == startofDataToken)
+                        try
                         {
-                            start = true;
-                            continue;//don't record start token to stream.
-                        }
-                        if (line == null || line == endOfDataToken)
-                        {
-                            done = true;
-                        }
-                        else
-                        {   //if we have started recieving valid data, start recording
-                            if (!string.IsNullOrWhiteSpace(line) && start)
+                            var line = process.StandardOutput.ReadLine();
+                            MessageLogged?.Invoke(line);
+                            if (line == null || line == startofDataToken)
+                            {
+                                start = true;
+                                continue; //don't record start token to stream.
+                            }
+
+                            if (line == null || line == endOfDataToken)
                             {
-                                writer.WriteLine(line);
+                                done = true;
+                            }
+                            else
+                            {
+                                //if we have started recieving valid data, start recording
+                                if (!string.IsNullOrWhiteSpace(line) && start)
+                                {
+                                    writer.WriteLine(line);
+                                }
                             }
                         }
+                        catch (Exception)
+                        {
+                            KillProcess();
+                            return GetCantCommunicateErrorMessage();
+                        }
                     }
-                    catch (Exception)
-                    {
-                        KillProcess();
-                        return GetCantCommunicateErrorMessage();
-                    }
-                }
 
-                return writer.ToString();
-            }
+                    return writer.ToString();
+                }
+            });
+            var completedTask = await Task.WhenAny(readStdOutTask, Task.Delay(TimeSpan.FromMilliseconds(timeoutms)));
+            //if the completed task was our read std out task, then return the data
+            //else we timed out, so return an empty string.
+            return completedTask == readStdOutTask ? readStdOutTask.Result : string.Empty;
         }
 
         protected void RaiseMessageLogged(string message)
@@ -175,6 +188,8 @@ protected void RaiseMessageLogged(string message)
     internal class Md2Html : CLIWrapper
     {
         private string relativePath = Path.Combine(@"Md2Html", @"Md2Html.exe");
+        private int processCommunicationTimeoutms = 5000;
+
         /// <summary>
         /// Constructor
         /// Start the CLI tool and keep it around
@@ -228,9 +243,9 @@ internal string ParseMd2Html(string mdString, string mdPath)
                 return GetCantCommunicateErrorMessage();
             }
 
-            var output = GetData();
+            var output = GetData(processCommunicationTimeoutms);
 
-            return output;
+            return output.Result;
         }
 
         /// <summary>
@@ -257,9 +272,9 @@ internal string SanitizeHtml(string content)
                 return GetCantCommunicateErrorMessage();
             }
 
-            var output = GetData();
+            var output = GetData(processCommunicationTimeoutms);
 
-           return output;
+           return output.Result;
         }
 
         /// <summary>

src/DynamoUtilities/Properties/AssemblyInfo.cs

@@ -24,3 +24,5 @@
 [assembly: InternalsVisibleTo("DynamoApplications")]
 [assembly: InternalsVisibleTo("DynamoCLI")]
 [assembly: InternalsVisibleTo("NodeDocumentationMarkdownGenerator")]
+[assembly: InternalsVisibleTo("DynamoUtilitiesTests")]
+

test/DynamoCoreTests/Logging/FeatureFlagTests.cs

@@ -1,7 +1,9 @@
 using Dynamo.Utilities;
 using NUnit.Framework;
+using NUnit.Framework.Internal;
 using System;
 using System.Diagnostics;
+using System.Text.RegularExpressions;
 using System.Threading;
 
 namespace Dynamo.Tests.Logging
@@ -69,6 +71,42 @@ public void FeatureFlagsShouldMessageLoggedShouldContainAllLogs()
             StringAssert.EndsWith("<<<<<Eod>>>>>", log);
 
         }
+        //TODO(DYN-6464) Revisit this and log more when the logger is not easily overwhelmed.
+        [Test]
+        public void FeatureFlagsShouldMessageLoggedShouldOnlyContainNullFlagErrorOnce()
+        {
+            var testflagsManager = new DynamoUtilities.DynamoFeatureFlagsManager("testkey", new SynchronizationContext(), true);
+            testflagsManager.MessageLogged += TestflagsManager_MessageLogged;
+            testflagsManager.CheckFeatureFlag("TestFlag2", "na");
+            testflagsManager.CheckFeatureFlag("TestFlag2", "na");
+            testflagsManager.CheckFeatureFlag("TestFlag2", "na");
+            testflagsManager.MessageLogged -= TestflagsManager_MessageLogged;
+            var matches = Regex.Matches(log, "wait longer for the cache").Count;
+            Assert.AreEqual(1,matches);
+        }
+        //TODO(DYN-6464) Revisit this and log more when the logger is not easily overwhelmed.
+        [Test]
+        public void FeatureFlagsShouldMessageLoggedShouldOnlyContainMissingFlagErrorOnce()
+        {
+            var testflagsManager = new DynamoUtilities.DynamoFeatureFlagsManager("testkey", new SynchronizationContext(), true);
+            testflagsManager.MessageLogged += TestflagsManager_MessageLogged;
+            testflagsManager.CacheAllFlags();
+            testflagsManager.CheckFeatureFlag("MissingFlag", "na");
+            testflagsManager.CheckFeatureFlag("MissingFlag", "na");
+            testflagsManager.CheckFeatureFlag("MissingFlag", "na");
+            testflagsManager.MessageLogged -= TestflagsManager_MessageLogged;
+            var matches = Regex.Matches(log, "failed to get value").Count;
+            Assert.AreEqual(1, matches);
+        }
+        [Test]
+        public void FeatureFlagsThrowsIfCheckIngNonSupportedType()
+        {
+            var testflagsManager = new DynamoUtilities.DynamoFeatureFlagsManager("testkey", new SynchronizationContext(), true);
+            Assert.Throws<ArgumentException>(() =>
+            {
+                testflagsManager.CheckFeatureFlag("NumericTypeNotSupported", 10);
+            });
+        }
 
         private void DynamoFeatureFlagsManager_FlagsRetrieved()
         {

test/Libraries/DynamoUtilitiesTests/CLIWrapperTests.cs

@@ -0,0 +1,58 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using NUnit.Framework;
+
+namespace DynamoUtilitiesTests
+{
+    [TestFixture]
+    public class CLIWrapperTests
+    {
+        /// <summary>
+        /// A test class that starts up the DynamoFF CLI and then kills it to cause a deadlock.
+        /// </summary>
+        private class HangingCLIWrapper: Dynamo.Utilities.CLIWrapper
+        {
+            private string relativePath = Path.Combine("DynamoFeatureFlags", "DynamoFeatureFlags.exe");
+            protected override string GetCantStartErrorMessage()
+            {
+                throw new NotImplementedException();
+            }
+
+            protected override string GetCantCommunicateErrorMessage()
+            {
+                throw new NotImplementedException();
+            }
+            internal HangingCLIWrapper()
+            {
+                StartProcess(relativePath, null);
+            }
+
+            internal string GetData()
+            {
+                //wait a bit, and then kill the process
+                //this will cause GetData to hang and timeout.
+                Task.Run(() =>
+                {   System.Threading.Thread.Sleep(100);
+                    process.Kill();
+                });
+                return GetData(2000).Result;
+            }
+        }
+
+        [Test]
+        public void CLIWrapperDoesNotHangIfProcessDoesNotWriteToStdOut()
+        {
+            var sw = new System.Diagnostics.Stopwatch();
+            sw.Start();
+            var wrapper = new HangingCLIWrapper();
+            Assert.AreEqual(string.Empty,wrapper.GetData());
+            sw.Stop();
+            Assert.GreaterOrEqual(sw.ElapsedMilliseconds,2000);
+
+        }
+    }
+}