Merge pull request #396 from bgrainger/logging

Add logging API. Fixes #390

Author: bgrainger

MySqlConnector.sln

@@ -1,6 +1,6 @@
 Microsoft Visual Studio Solution File, Format Version 12.00
 # Visual Studio 15
-VisualStudioVersion = 15.0.27004.2009
+VisualStudioVersion = 15.0.27004.2010
 MinimumVisualStudioVersion = 10.0.40219.1
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "MySqlConnector", "src\MySqlConnector\MySqlConnector.csproj", "{F82378AF-274E-4FBA-8E45-27126D607B85}"
 EndProject
@@ -12,6 +12,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "MySqlConnector.Performance"
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Conformance.Tests", "tests\Conformance.Tests\Conformance.Tests.csproj", "{CC0DA702-43E8-471E-9320-F36685C540A1}"
 EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "MySqlConnector.Logging.log4net", "src\MySqlConnector.Logging.log4net\MySqlConnector.Logging.log4net.csproj", "{A15647B8-FA3F-4536-BF4E-4F93F2FBFC75}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -38,6 +40,10 @@ Global
 		{CC0DA702-43E8-471E-9320-F36685C540A1}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{CC0DA702-43E8-471E-9320-F36685C540A1}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{CC0DA702-43E8-471E-9320-F36685C540A1}.Release|Any CPU.Build.0 = Release|Any CPU
+		{A15647B8-FA3F-4536-BF4E-4F93F2FBFC75}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{A15647B8-FA3F-4536-BF4E-4F93F2FBFC75}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{A15647B8-FA3F-4536-BF4E-4F93F2FBFC75}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{A15647B8-FA3F-4536-BF4E-4F93F2FBFC75}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE

appveyor.yml

@@ -10,13 +10,15 @@ before_test:
 test_script:
 - ps: .\.ci\test.ps1
 after_test:
-- cmd: dotnet pack src\MySqlConnector\MySqlConnector.csproj -c Release -p:SourceLinkCreate=true -p:SourceLinkTest=true
+- cmd: |-
+    dotnet pack src\MySqlConnector\MySqlConnector.csproj -c Release -p:SourceLinkCreate=true -p:SourceLinkTest=true
+    dotnet pack src\MySqlConnector.Logging.log4net\MySqlConnector.Logging.log4net.csproj -c Release -p:SourceLinkCreate=true -p:SourceLinkTest=true
 notifications:
 - provider: Slack
   incoming_webhook:
     secure: SRJ5fYQE4tvelyqeX3Lkv0gXta3O2pl4/+wNaqmqmcFkmYBe+U31T5YCGhipBOVhHBIZLevihOJZ78sFVJrmAFV5bHgtX/VPIKEXN+7ytis=
 artifacts:
-- path: src\MySqlConnector\bin\Release\MySqlConnector.*.nupkg
+- path: src\*\bin\Release\*.nupkg
 deploy:
 - provider: NuGet
   api_key:

src/Directory.Build.props

@@ -0,0 +1,30 @@
+<Project>
+
+  <PropertyGroup>
+    <VersionPrefix>0.32.0</VersionPrefix>
+    <SignAssembly>true</SignAssembly>
+    <PublicSign Condition=" '$(OS)' != 'Windows_NT' ">true</PublicSign>
+    <AssemblyOriginatorKeyFile>..\..\MySqlConnector.snk</AssemblyOriginatorKeyFile>
+    <TargetFrameworks>net45;net46;netstandard1.3;netstandard2.0</TargetFrameworks>
+    <TreatWarningsAsErrors>true</TreatWarningsAsErrors>
+    <PackageReleaseNotes>https://mysql-net.github.io/MySqlConnector/overview/version-history/</PackageReleaseNotes>
+    <PackageProjectUrl>https://mysql-net.github.io/MySqlConnector/</PackageProjectUrl>
+    <PackageLicenseUrl>https://opensource.org/licenses/MIT</PackageLicenseUrl>
+    <PackageIconUrl>https://mysql-net.github.io/MySqlConnector/img/logo.png</PackageIconUrl>
+    <RepositoryType>git</RepositoryType>
+    <RepositoryUrl>https://github.com/mysql-net/MySqlConnector.git</RepositoryUrl>
+    <DebugType>embedded</DebugType>
+    <LangVersion>latest</LangVersion>
+  </PropertyGroup>
+
+  <ItemGroup Condition=" '$(OS)' == 'Windows_NT' ">
+    <PackageReference Include="SourceLink.Create.CommandLine" Version="2.5.0" PrivateAssets="All" />
+    <DotNetCliToolReference Include="dotnet-sourcelink" Version="2.5.0" />
+    <PackageReference Include="SourceLink.Test" Version="2.5.0" PrivateAssets="all" />
+  </ItemGroup>
+
+  <PropertyGroup Condition=" '$(Configuration)' == 'Debug' ">
+    <DefineConstants>DEBUG</DefineConstants>
+  </PropertyGroup>
+
+</Project>

src/MySqlConnector.Logging.log4net/Log4netLoggerProvider.cs

@@ -0,0 +1,54 @@
+using System;
+using System.Globalization;
+using System.Reflection;
+using log4net;
+using log4net.Core;
+
+namespace MySqlConnector.Logging
+{
+    public sealed class Log4netLoggerProvider : IMySqlConnectorLoggerProvider
+    {
+		public IMySqlConnectorLogger CreateLogger(string name) => new Log4netLogger(LogManager.GetLogger(s_loggerAssembly, "MySqlConnector." + name));
+
+		static readonly Assembly s_loggerAssembly = typeof(Log4netLogger).GetTypeInfo().Assembly;
+		static readonly Type s_loggerType = typeof(Log4netLogger);
+
+		private class Log4netLogger : IMySqlConnectorLogger
+		{
+			public Log4netLogger(ILoggerWrapper log) => m_logger = log.Logger;
+
+			public bool IsEnabled(MySqlConnectorLogLevel level) => m_logger.IsEnabledFor(GetLevel(level));
+
+			public void Log(MySqlConnectorLogLevel level, string message, object[] args = null, Exception exception = null)
+			{
+				if (args == null || args.Length == 0)
+					m_logger.Log(s_loggerType, GetLevel(level), message, exception);
+				else
+					m_logger.Log(s_loggerType, GetLevel(level), string.Format(CultureInfo.InvariantCulture, message, args), exception);
+			}
+
+			private static Level GetLevel(MySqlConnectorLogLevel level)
+			{
+				switch (level)
+				{
+				case MySqlConnectorLogLevel.Trace:
+					return Level.Trace;
+				case MySqlConnectorLogLevel.Debug:
+					return Level.Debug;
+				case MySqlConnectorLogLevel.Info:
+					return Level.Info;
+				case MySqlConnectorLogLevel.Warn:
+					return Level.Warn;
+				case MySqlConnectorLogLevel.Error:
+					return Level.Error;
+				case MySqlConnectorLogLevel.Fatal:
+					return Level.Fatal;
+				default:
+					throw new ArgumentOutOfRangeException(nameof(level), level, "Invalid value for 'level'.");
+				}
+			}
+
+			readonly ILogger m_logger;
+		}
+	}
+}

src/MySqlConnector.Logging.log4net/MySqlConnector.Logging.log4net.csproj

@@ -0,0 +1,19 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <TargetFrameworks>net45;net46;netstandard1.3;netstandard2.0</TargetFrameworks>
+    <Title>MySQL Connector Logging Adapter for log4net</Title>
+    <Copyright>Copyright 2017 Bradley Grainger</Copyright>
+    <Authors>Bradley Grainger</Authors>
+    <PackageTags>mysql;mysqlconnector;async;ado.net;database;netcore</PackageTags>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <PackageReference Include="log4net" Version="2.0.8" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\MySqlConnector\MySqlConnector.csproj" />
+  </ItemGroup>
+
+</Project>

src/MySqlConnector/Core/ConnectionPool.cs

@@ -4,12 +4,16 @@
 using System.Threading;
 using System.Threading.Tasks;
 using MySql.Data.MySqlClient;
+using MySqlConnector.Logging;
 using MySqlConnector.Protocol.Serialization;
+using MySqlConnector.Utilities;
 
 namespace MySqlConnector.Core
 {
 	internal sealed class ConnectionPool
 	{
+		public int Id { get; }
+
 		public async Task<ServerSession> GetSessionAsync(MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken)
 		{
 			cancellationToken.ThrowIfCancellationRequested();
@@ -18,12 +22,16 @@ public async Task<ServerSession> GetSessionAsync(MySqlConnection connection, IOB
 			// check at most once per second (although this isn't enforced via a mutex so multiple threads might block
 			// on the lock in RecoverLeakedSessions in high-concurrency situations
 			if (m_sessionSemaphore.CurrentCount == 0 && unchecked(((uint) Environment.TickCount) - m_lastRecoveryTime) >= 1000u)
+			{
+				Log.Warn("{0} is empty; recovering leaked sessions", m_logArguments);
 				RecoverLeakedSessions();
+			}
 
 			if (m_connectionSettings.MinimumPoolSize > 0)
 				await CreateMinimumPooledSessions(ioBehavior, cancellationToken).ConfigureAwait(false);
 
 			// wait for an open slot (until the cancellationToken is cancelled, which is typically due to timeout)
+			Log.Debug("{0} waiting for an available session", m_logArguments);
 			if (ioBehavior == IOBehavior.Asynchronous)
 				await m_sessionSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false);
 			else
@@ -43,10 +51,12 @@ public async Task<ServerSession> GetSessionAsync(MySqlConnection connection, IOB
 				}
 				if (session != null)
 				{
+					Log.Debug("{0} found an existing session; checking it for validity", m_logArguments);
 					bool reuseSession;
 
 					if (session.PoolGeneration != m_generation)
 					{
+						Log.Debug("{0} discarding session due to wrong generation", m_logArguments);
 						reuseSession = false;
 					}
 					else
@@ -64,26 +74,41 @@ public async Task<ServerSession> GetSessionAsync(MySqlConnection connection, IOB
 					if (!reuseSession)
 					{
 						// session is either old or cannot communicate with the server
+						Log.Warn("{0} Session{1} is unusable; destroying it", m_logArguments[0], session.Id);
 						AdjustHostConnectionCount(session, -1);
 						await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
 					}
 					else
 					{
 						// pooled session is ready to be used; return it
 						session.OwningConnection = new WeakReference<MySqlConnection>(connection);
+						int leasedSessionsCountPooled;
 						lock (m_leasedSessions)
+						{
 							m_leasedSessions.Add(session.Id, session);
+							leasedSessionsCountPooled = m_leasedSessions.Count;
+						}
+						if (Log.IsDebugEnabled())
+							Log.Debug("{0} returning pooled Session{1} to caller; m_leasedSessions.Count={2}", m_logArguments[0], session.Id, leasedSessionsCountPooled);
 						return session;
 					}
 				}
 
 				// create a new session
-				session = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastId));
+				session = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastSessionId));
+				if (Log.IsInfoEnabled())
+					Log.Info("{0} no pooled session available; created new Session{1}", m_logArguments[0], session.Id);
 				await session.ConnectAsync(m_connectionSettings, m_loadBalancer, ioBehavior, cancellationToken).ConfigureAwait(false);
 				AdjustHostConnectionCount(session, 1);
 				session.OwningConnection = new WeakReference<MySqlConnection>(connection);
+				int leasedSessionsCountNew;
 				lock (m_leasedSessions)
+				{
 					m_leasedSessions.Add(session.Id, session);
+					leasedSessionsCountNew = m_leasedSessions.Count;
+				}
+				if (Log.IsDebugEnabled())
+					Log.Debug("{0} returning new Session{1} to caller; m_leasedSessions.Count={2}", m_logArguments[0], session.Id, leasedSessionsCountNew);
 				return session;
 			}
 			catch
@@ -110,6 +135,9 @@ private bool SessionIsHealthy(ServerSession session)
 
 		public void Return(ServerSession session)
 		{
+			if (Log.IsDebugEnabled())
+				Log.Debug("{0} receiving Session{1} back", m_logArguments[0], session.Id);
+
 			try
 			{
 				lock (m_leasedSessions)
@@ -122,6 +150,7 @@ public void Return(ServerSession session)
 				}
 				else
 				{
+					Log.Warn("{0} received invalid Session{1}; destroying it", m_logArguments[0], session.Id);
 					AdjustHostConnectionCount(session, -1);
 					session.DisposeAsync(IOBehavior.Synchronous, CancellationToken.None).GetAwaiter().GetResult();
 				}
@@ -135,13 +164,15 @@ public void Return(ServerSession session)
 		public async Task ClearAsync(IOBehavior ioBehavior, CancellationToken cancellationToken)
 		{
 			// increment the generation of the connection pool
+			Log.Info("{0} clearing connection pool", m_logArguments);
 			Interlocked.Increment(ref m_generation);
 			RecoverLeakedSessions();
 			await CleanPoolAsync(ioBehavior, session => session.PoolGeneration != m_generation, false, cancellationToken).ConfigureAwait(false);
 		}
 
 		public async Task ReapAsync(IOBehavior ioBehavior, CancellationToken cancellationToken)
 		{
+			Log.Debug("{0} reaping connection pool", m_logArguments);
 			RecoverLeakedSessions();
 			if (m_connectionSettings.ConnectionIdleTimeout == 0)
 				return;
@@ -165,6 +196,10 @@ private void RecoverLeakedSessions()
 						recoveredSessions.Add(session);
 				}
 			}
+			if (recoveredSessions.Count == 0)
+				Log.Debug("{0} recovered no sessions", m_logArguments);
+			else
+				Log.Warn("{0} recovered {1} sessions", m_logArguments[0], recoveredSessions.Count);
 			foreach (var session in recoveredSessions)
 				session.ReturnToPool();
 		}
@@ -218,6 +253,7 @@ private async Task CleanPoolAsync(IOBehavior ioBehavior, Func<ServerSession, boo
 						if (shouldCleanFn(session))
 						{
 							// session should be cleaned; dispose it and keep iterating
+							Log.Info("{0} found Session{1} to clean up", m_logArguments[0], session.Id);
 							await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
 						}
 						else
@@ -266,7 +302,8 @@ private async Task CreateMinimumPooledSessions(IOBehavior ioBehavior, Cancellati
 
 				try
 				{
-					var session = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastId));
+					var session = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastSessionId));
+					Log.Info("{0} created Session{1} to reach minimum pool size", m_logArguments[0], session.Id);
 					await session.ConnectAsync(m_connectionSettings, m_loadBalancer, ioBehavior, cancellationToken).ConfigureAwait(false);
 					AdjustHostConnectionCount(session, 1);
 					lock (m_sessions)
@@ -343,7 +380,7 @@ private ConnectionPool(ConnectionSettings cs)
 			m_cleanSemaphore = new SemaphoreSlim(1);
 			m_sessionSemaphore = new SemaphoreSlim(cs.MaximumPoolSize);
 			m_sessions = new LinkedList<ServerSession>();
-			m_leasedSessions = new Dictionary<int, ServerSession>();
+			m_leasedSessions = new Dictionary<string, ServerSession>();
 			if (cs.LoadBalance == MySqlLoadBalance.LeastConnections)
 			{
 				m_hostSessions = new Dictionary<string, int>();
@@ -355,6 +392,14 @@ private ConnectionPool(ConnectionSettings cs)
 				cs.LoadBalance == MySqlLoadBalance.Random ? RandomLoadBalancer.Instance :
 				cs.LoadBalance == MySqlLoadBalance.LeastConnections ? new LeastConnectionsLoadBalancer(this) :
 				(ILoadBalancer) new RoundRobinLoadBalancer();
+
+			Id = Interlocked.Increment(ref s_poolId);
+			m_logArguments = new object[] { "Pool{0}".FormatInvariant(Id) };
+			if (Log.IsInfoEnabled())
+			{
+				var csb = new MySqlConnectionStringBuilder(cs.ConnectionString);
+				Log.Info("{0} creating new connection pool for {1}", m_logArguments[0], csb.GetConnectionString(includePassword: false));
+			}
 		}
 
 		private void AdjustHostConnectionCount(ServerSession session, int delta)
@@ -379,6 +424,7 @@ public IEnumerable<string> LoadBalance(IReadOnlyList<string> hosts)
 			readonly ConnectionPool m_pool;
 		}
 
+		static readonly IMySqlConnectorLogger Log = MySqlConnectorLogManager.CreateLogger(nameof(ConnectionPool));
 		static readonly ReaderWriterLockSlim s_poolLock = new ReaderWriterLockSlim();
 		static readonly Dictionary<string, ConnectionPool> s_pools = new Dictionary<string, ConnectionPool>();
 #if DEBUG
@@ -402,15 +448,18 @@ public IEnumerable<string> LoadBalance(IReadOnlyList<string> hosts)
 			}
 		});
 
+		static int s_poolId;
+
 		int m_generation;
 		readonly SemaphoreSlim m_cleanSemaphore;
 		readonly SemaphoreSlim m_sessionSemaphore;
 		readonly LinkedList<ServerSession> m_sessions;
 		readonly ConnectionSettings m_connectionSettings;
-		readonly Dictionary<int, ServerSession> m_leasedSessions;
+		readonly Dictionary<string, ServerSession> m_leasedSessions;
 		readonly ILoadBalancer m_loadBalancer;
 		readonly Dictionary<string, int> m_hostSessions;
-		int m_lastId;
+		readonly object[] m_logArguments;
 		uint m_lastRecoveryTime;
+		int m_lastSessionId;
 	}
 }