Add logging for cached procedures.

Signed-off-by: Bradley Grainger <[email protected]>

Author: bgrainger

src/MySqlConnector/Core/CachedProcedure.cs

@@ -6,6 +6,7 @@
 using System.Threading;
 using System.Threading.Tasks;
 using MySql.Data.MySqlClient;
+using MySqlConnector.Logging;
 using MySqlConnector.Protocol.Serialization;
 
 namespace MySqlConnector.Core
@@ -48,6 +49,8 @@ FROM information_schema.parameters
 				}
 			}
 
+			if (Log.IsInfoEnabled())
+				Log.Info("Procedure for Schema={0} Component={1} has RoutineCount={2}, ParameterCount={3}", schema, component, routineCount, parameters.Count);
 			return routineCount == 0 ? null : new CachedProcedure(schema, component, parameters.AsReadOnly());
 		}
 
@@ -90,7 +93,9 @@ internal MySqlParameterCollection AlignParamsWithDb(MySqlParameterCollection par
 			return alignedParams;
 		}
 
-		private string FullyQualified => $"`{m_schema}`.`{m_component}`";
+		string FullyQualified => $"`{m_schema}`.`{m_component}`";
+
+		static readonly IMySqlConnectorLogger Log = MySqlConnectorLogManager.CreateLogger(nameof(CachedProcedure));
 
 		readonly string m_schema;
 		readonly string m_component;

src/MySqlConnector/MySql.Data.MySqlClient/MySqlConnection.cs

@@ -322,19 +322,30 @@ internal void Cancel(MySqlCommand command)
 
 		internal async Task<CachedProcedure> GetCachedProcedure(IOBehavior ioBehavior, string name, CancellationToken cancellationToken)
 		{
+			if (Log.IsDebugEnabled())
+				Log.Debug("Session{0} getting cached procedure Name={1}", m_session.Id, name);
 			if (State != ConnectionState.Open)
 				throw new InvalidOperationException("Connection is not open.");
 
 			if (m_session.ServerVersion.Version < ServerVersions.SupportsProcedureCache)
+			{
+				Log.Warn("Session{0} ServerVersion={1} does not support cached procedures", m_session.Id, m_session.ServerVersion.OriginalString);
 				return null;
+			}
 
 			var cachedProcedures = m_session.Pool?.GetProcedureCache() ?? m_cachedProcedures;
 			if (cachedProcedures == null)
+			{
+				Log.Warn("Session{0} pool Pool{1} doesn't have a shared procedure cache; procedure will only be cached on this connection", m_session.Id, m_session.Pool?.Id);
 				cachedProcedures = m_cachedProcedures = new Dictionary<string, CachedProcedure>();
+			}
 
 			var normalized = NormalizedSchema.MustNormalize(name, Database);
 			if (string.IsNullOrEmpty(normalized.Schema))
+			{
+				Log.Warn("Session{0} couldn't normalize Database={1} Name={2}; not caching procedure", m_session.Id, Database, name);
 				return null;
+			}
 
 			CachedProcedure cachedProcedure;
 			bool foundProcedure;
@@ -343,9 +354,24 @@ internal async Task<CachedProcedure> GetCachedProcedure(IOBehavior ioBehavior, s
 			if (!foundProcedure)
 			{
 				cachedProcedure = await CachedProcedure.FillAsync(ioBehavior, this, normalized.Schema, normalized.Component, cancellationToken).ConfigureAwait(false);
+				if (Log.IsWarnEnabled())
+				{
+					if (cachedProcedure != null)
+						Log.Info("Session{0} caching procedure Schema={1} Component={2}", m_session.Id, normalized.Schema, normalized.Component);
+					else
+						Log.Warn("Session{0} failed to cache procedure Schema={1} Component={2}", m_session.Id, normalized.Schema, normalized.Component);
+				}
 				lock (cachedProcedures)
 					cachedProcedures[normalized.FullyQualified] = cachedProcedure;
 			}
+
+			if (Log.IsWarnEnabled())
+			{
+				if (cachedProcedure == null)
+					Log.Warn("Session{0} did not find cached procedure Schema={1} Component={2}", m_session.Id, normalized.Schema, normalized.Component);
+				else
+					Log.Debug("Session{0} returning cached procedure Schema={1} Component={2}", m_session.Id, normalized.Schema, normalized.Component);
+			}
 			return cachedProcedure;
 		}