Skip to content

Reduce log levels #984

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Jul 5, 2021
Merged

Reduce log levels #984

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
f719e4e
Reduce most Debug logging to Trace level.
bgrainger May 1, 2021
819f769
Reduce most Info logging to Debug or Trace.
bgrainger May 1, 2021
56774e9
Reduce most Warn logging to Info.
bgrainger May 1, 2021
30aed32
Fix some error logging.
bgrainger May 1, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
20 changes: 10 additions & 10 deletions src/MySqlConnector/Core/BackgroundConnectionResetHelper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,13 +15,13 @@ public static void AddSession(ServerSession session, MySqlConnection? owningConn
lock (s_lock)
s_resetTasks.Add(resetTask);

if (Log.IsDebugEnabled())
Log.Debug("Started Session{0} reset in background; waiting TaskCount: {1}.", session.Id, s_resetTasks.Count);
if (Log.IsTraceEnabled())
Log.Trace("Started Session{0} reset in background; waiting TaskCount: {1}.", session.Id, s_resetTasks.Count);

// release only if it is likely to succeed
if (s_semaphore.CurrentCount == 0)
{
Log.Debug("Releasing semaphore.");
Log.Trace("Releasing semaphore.");
try
{
s_semaphore.Release();
Expand All @@ -35,7 +35,7 @@ public static void AddSession(ServerSession session, MySqlConnection? owningConn

public static void Start()
{
Log.Info("Starting BackgroundConnectionResetHelper worker.");
Log.Trace("Starting BackgroundConnectionResetHelper worker.");
lock (s_lock)
{
if (s_workerTask is null)
Expand All @@ -45,7 +45,7 @@ public static void Start()

public static void Stop()
{
Log.Info("Stopping BackgroundConnectionResetHelper worker.");
Log.Trace("Stopping BackgroundConnectionResetHelper worker.");
s_cancellationTokenSource.Cancel();
Task? workerTask;
lock (s_lock)
Expand All @@ -61,12 +61,12 @@ public static void Stop()
{
}
}
Log.Info("Stopped BackgroundConnectionResetHelper worker.");
Log.Trace("Stopped BackgroundConnectionResetHelper worker.");
}

public static async Task ReturnSessionsAsync()
{
Log.Info("Started BackgroundConnectionResetHelper worker.");
Log.Trace("Started BackgroundConnectionResetHelper worker.");

List<Task<bool>> localTasks = new();

Expand All @@ -76,7 +76,7 @@ public static async Task ReturnSessionsAsync()
try
{
// block until AddSession releases the semaphore
Log.Debug("Waiting for semaphore.");
Log.Trace("Waiting for semaphore.");
await s_semaphore.WaitAsync(s_cancellationTokenSource.Token).ConfigureAwait(false);

// process all sessions that have started being returned
Expand All @@ -91,8 +91,8 @@ public static async Task ReturnSessionsAsync()
if (localTasks.Count == 0)
break;

if (Log.IsDebugEnabled())
Log.Debug("Found TaskCount {0} task(s) to process.", localTasks.Count);
if (Log.IsTraceEnabled())
Log.Trace("Found TaskCount {0} task(s) to process.", localTasks.Count);

await Task.WhenAll(localTasks);
localTasks.Clear();
Expand Down
8 changes: 4 additions & 4 deletions src/MySqlConnector/Core/CachedProcedure.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,15 +51,15 @@ internal sealed class CachedProcedure
}
catch (MySqlException ex)
{
Log.Warn("Session{0} failed to retrieve metadata for Schema={1} Component={2}; falling back to INFORMATION_SCHEMA. Error: {3}", connection.Session.Id, schema, component, ex.Message);
Log.Info("Session{0} failed to retrieve metadata for Schema={1} Component={2}; falling back to INFORMATION_SCHEMA. Error: {3}", connection.Session.Id, schema, component, ex.Message);
if (ex.ErrorCode == MySqlErrorCode.TableAccessDenied)
connection.Session.ProcAccessDenied = true;
}
}

if (connection.Session.ServerVersion.Version < ServerVersions.SupportsProcedureCache)
{
Log.Warn("Session{0} ServerVersion={1} does not support cached procedures", connection.Session.Id, connection.Session.ServerVersion.OriginalString);
Log.Info("Session{0} ServerVersion={1} does not support cached procedures", connection.Session.Id, connection.Session.ServerVersion.OriginalString);
return null;
}

Expand Down Expand Up @@ -97,8 +97,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);
if (Log.IsTraceEnabled())
Log.Trace("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);
}

Expand Down
6 changes: 3 additions & 3 deletions src/MySqlConnector/Core/CommandExecutor.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,8 +23,8 @@ public static async Task<MySqlDataReader> ExecuteReaderAsync(IReadOnlyList<IMySq
// pre-requisite: Connection is non-null must be checked before calling this method
var connection = command.Connection!;

if (Log.IsDebugEnabled())
Log.Debug("Session{0} ExecuteReader {1} CommandCount: {2}", connection.Session.Id, ioBehavior, commands.Count);
if (Log.IsTraceEnabled())
Log.Trace("Session{0} ExecuteReader {1} CommandCount: {2}", connection.Session.Id, ioBehavior, commands.Count);

Dictionary<string, CachedProcedure?>? cachedProcedures = null;
foreach (var command2 in commands)
Expand Down Expand Up @@ -61,7 +61,7 @@ public static async Task<MySqlDataReader> ExecuteReaderAsync(IReadOnlyList<IMySq
}
catch (MySqlException ex) when (ex.ErrorCode == MySqlErrorCode.QueryInterrupted && cancellationToken.IsCancellationRequested)
{
Log.Warn("Session{0} query was interrupted", connection.Session.Id);
Log.Info("Session{0} query was interrupted", connection.Session.Id);
throw new OperationCanceledException(ex. Message, ex, cancellationToken);
}
catch (Exception ex) when (payload.Span.Length > 4_194_304 && (ex is SocketException or IOException or MySqlProtocolException))
Expand Down
4 changes: 2 additions & 2 deletions src/MySqlConnector/Core/ConcatenatedCommandPayloadCreator.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,8 +19,8 @@ public bool WriteQueryCommand(ref CommandListPosition commandListPosition, IDict
do
{
var command = commandListPosition.Commands[commandListPosition.CommandIndex];
if (Log.IsDebugEnabled())
Log.Debug("Session{0} Preparing command payload; CommandText: {1}", command.Connection!.Session.Id, command.CommandText);
if (Log.IsTraceEnabled())
Log.Trace("Session{0} Preparing command payload; CommandText: {1}", command.Connection!.Session.Id, command.CommandText);

isComplete = SingleCommandPayloadCreator.WriteQueryPayload(command, cachedProcedures, writer);
commandListPosition.CommandIndex++;
Expand Down
54 changes: 27 additions & 27 deletions src/MySqlConnector/Core/ConnectionPool.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,15 +28,15 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
// on the lock in RecoverLeakedSessions in high-concurrency situations
if (IsEmpty && unchecked(((uint) Environment.TickCount) - m_lastRecoveryTime) >= 1000u)
{
Log.Info("Pool{0} is empty; recovering leaked sessions", m_logArguments);
Log.Debug("Pool{0} is empty; trying to recover any leaked sessions", m_logArguments);
await RecoverLeakedSessionsAsync(ioBehavior).ConfigureAwait(false);
}

if (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("Pool{0} waiting for an available session", m_logArguments);
Log.Trace("Pool{0} waiting for an available session", m_logArguments);
if (ioBehavior == IOBehavior.Asynchronous)
await m_sessionSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false);
else
Expand All @@ -56,12 +56,12 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
}
if (session is not null)
{
Log.Debug("Pool{0} found an existing session; checking it for validity", m_logArguments);
Log.Trace("Pool{0} found an existing session; checking it for validity", m_logArguments);
bool reuseSession;

if (session.PoolGeneration != m_generation)
{
Log.Debug("Pool{0} discarding session due to wrong generation", m_logArguments);
Log.Trace("Pool{0} discarding session due to wrong generation", m_logArguments);
reuseSession = false;
}
else
Expand All @@ -83,7 +83,7 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
if (!reuseSession)
{
// session is either old or cannot communicate with the server
Log.Warn("Pool{0} Session{1} is unusable; destroying it", m_logArguments[0], session.Id);
Log.Info("Pool{0} Session{1} is unusable; destroying it", m_logArguments[0], session.Id);
AdjustHostConnectionCount(session, -1);
await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
}
Expand All @@ -97,8 +97,8 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
m_leasedSessions.Add(session.Id, session);
leasedSessionsCountPooled = m_leasedSessions.Count;
}
if (Log.IsDebugEnabled())
Log.Debug("Pool{0} returning pooled Session{1} to caller; LeasedSessionsCount={2}", m_logArguments[0], session.Id, leasedSessionsCountPooled);
if (Log.IsTraceEnabled())
Log.Trace("Pool{0} returning pooled Session{1} to caller; LeasedSessionsCount={2}", m_logArguments[0], session.Id, leasedSessionsCountPooled);
return session;
}
}
Expand All @@ -113,8 +113,8 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
m_leasedSessions.Add(session.Id, session);
leasedSessionsCountNew = m_leasedSessions.Count;
}
if (Log.IsDebugEnabled())
Log.Debug("Pool{0} returning new Session{1} to caller; LeasedSessionsCount={2}", m_logArguments[0], session.Id, leasedSessionsCountNew);
if (Log.IsTraceEnabled())
Log.Trace("Pool{0} returning new Session{1} to caller; LeasedSessionsCount={2}", m_logArguments[0], session.Id, leasedSessionsCountNew);
return session;
}
catch (Exception ex)
Expand All @@ -129,7 +129,7 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
}
catch (Exception unexpectedException)
{
Log.Error(unexpectedException, "Pool{0} unexpected error in GetSessionAsync: {1}", m_logArguments[0], unexpectedException.Message);
Log.Warn(unexpectedException, "Pool{0} unexpected error in GetSessionAsync: {1}", m_logArguments[0], unexpectedException.Message);
}
}

Expand Down Expand Up @@ -164,8 +164,8 @@ public async ValueTask<int> ReturnAsync(IOBehavior ioBehavior, ServerSession ses
public async ValueTask ReturnAsync(IOBehavior ioBehavior, ServerSession session)
#endif
{
if (Log.IsDebugEnabled())
Log.Debug("Pool{0} receiving Session{1} back", m_logArguments[0], session.Id);
if (Log.IsTraceEnabled())
Log.Trace("Pool{0} receiving Session{1} back", m_logArguments[0], session.Id);

try
{
Expand All @@ -181,9 +181,9 @@ public async ValueTask ReturnAsync(IOBehavior ioBehavior, ServerSession session)
else
{
if (sessionHealth == 1)
Log.Warn("Pool{0} received invalid Session{1}; destroying it", m_logArguments[0], session.Id);
Log.Info("Pool{0} received invalid Session{1}; destroying it", m_logArguments[0], session.Id);
else
Log.Info("Pool{0} received expired Session{1}; destroying it", m_logArguments[0], session.Id);
Log.Debug("Pool{0} received expired Session{1}; destroying it", m_logArguments[0], session.Id);
AdjustHostConnectionCount(session, -1);
await session.DisposeAsync(ioBehavior, CancellationToken.None).ConfigureAwait(false);
}
Expand All @@ -210,7 +210,7 @@ public async Task ClearAsync(IOBehavior ioBehavior, CancellationToken cancellati

public async Task ReapAsync(IOBehavior ioBehavior, CancellationToken cancellationToken)
{
Log.Debug("Pool{0} reaping connection pool", m_logArguments);
Log.Trace("Pool{0} reaping connection pool", m_logArguments);
await RecoverLeakedSessionsAsync(ioBehavior).ConfigureAwait(false);
await CleanPoolAsync(ioBehavior, session => (unchecked((uint) Environment.TickCount) - session.LastReturnedTicks) / 1000 >= ConnectionSettings.ConnectionIdleTimeout, true, cancellationToken).ConfigureAwait(false);
}
Expand Down Expand Up @@ -250,7 +250,7 @@ private async Task RecoverLeakedSessionsAsync(IOBehavior ioBehavior)
}
}
if (recoveredSessions.Count == 0)
Log.Debug("Pool{0} recovered no sessions", m_logArguments);
Log.Trace("Pool{0} recovered no sessions", m_logArguments);
else
Log.Warn("Pool{0}: RecoveredSessionCount={1}", m_logArguments[0], recoveredSessions.Count);
foreach (var session in recoveredSessions)
Expand Down Expand Up @@ -306,7 +306,7 @@ private async Task CleanPoolAsync(IOBehavior ioBehavior, Func<ServerSession, boo
if (shouldCleanFn(session))
{
// session should be cleaned; dispose it and keep iterating
Log.Info("Pool{0} found Session{1} to clean up", m_logArguments[0], session.Id);
Log.Debug("Pool{0} found Session{1} to clean up", m_logArguments[0], session.Id);
await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
}
else
Expand Down Expand Up @@ -371,40 +371,40 @@ private async Task CreateMinimumPooledSessions(IOBehavior ioBehavior, Cancellati
private async ValueTask<ServerSession> ConnectSessionAsync(string logMessage, int startTickCount, IOBehavior ioBehavior, CancellationToken cancellationToken)
{
var session = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastSessionId));
if (Log.IsInfoEnabled())
Log.Info(logMessage, m_logArguments[0], session.Id);
if (Log.IsDebugEnabled())
Log.Debug(logMessage, m_logArguments[0], session.Id);
var statusInfo = await session.ConnectAsync(ConnectionSettings, startTickCount, m_loadBalancer, ioBehavior, cancellationToken).ConfigureAwait(false);
Exception? redirectionException = null;

if (statusInfo is not null && statusInfo.StartsWith("Location: mysql://", StringComparison.Ordinal))
{
// server redirection string has the format "Location: mysql://{host}:{port}/user={userId}[&ttl={ttl}]"
Log.Info("Session{0} has server redirection header {1}", session.Id, statusInfo);
Log.Trace("Session{0} has server redirection header {1}", session.Id, statusInfo);

if (ConnectionSettings.ServerRedirectionMode == MySqlServerRedirectionMode.Disabled)
{
Log.Info("Pool{0} server redirection is disabled; ignoring redirection", m_logArguments);
Log.Trace("Pool{0} server redirection is disabled; ignoring redirection", m_logArguments);
}
else if (Utility.TryParseRedirectionHeader(statusInfo, out var host, out var port, out var user))
{
if (host != ConnectionSettings.HostNames![0] || port != ConnectionSettings.Port || user != ConnectionSettings.UserID)
{
var redirectedSettings = ConnectionSettings.CloneWith(host, port, user);
Log.Info("Pool{0} opening new connection to Host={1}; Port={2}; User={3}", m_logArguments[0], host, port, user);
Log.Debug("Pool{0} opening new connection to Host={1}; Port={2}; User={3}", m_logArguments[0], host, port, user);
var redirectedSession = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastSessionId));
try
{
await redirectedSession.ConnectAsync(redirectedSettings, startTickCount, m_loadBalancer, ioBehavior, cancellationToken).ConfigureAwait(false);
}
catch (Exception ex)
{
Log.Warn(ex, "Pool{0} failed to connect redirected Session{1}", m_logArguments[0], redirectedSession.Id);
Log.Info(ex, "Pool{0} failed to connect redirected Session{1}", m_logArguments[0], redirectedSession.Id);
redirectionException = ex;
}

if (redirectionException is null)
{
Log.Info("Pool{0} closing Session{1} to use redirected Session{2} instead", m_logArguments[0], session.Id, redirectedSession.Id);
Log.Trace("Pool{0} closing Session{1} to use redirected Session{2} instead", m_logArguments[0], session.Id, redirectedSession.Id);
await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
return redirectedSession;
}
Expand All @@ -421,7 +421,7 @@ private async ValueTask<ServerSession> ConnectSessionAsync(string logMessage, in
}
else
{
Log.Info("Session{0} is already connected to this server; ignoring redirection", session.Id);
Log.Trace("Session{0} is already connected to this server; ignoring redirection", session.Id);
}
}
}
Expand Down Expand Up @@ -486,9 +486,9 @@ private async ValueTask<ServerSession> ConnectSessionAsync(string logMessage, in
if (connectionSettings.ConnectionReset)
BackgroundConnectionResetHelper.Start();
}
else if (pool != newPool && Log.IsInfoEnabled())
else if (pool != newPool && Log.IsDebugEnabled())
{
Log.Info("Pool{0} was created but will not be used (due to race)", newPool.m_logArguments);
Log.Debug("Pool{0} was created but will not be used (due to race)", newPool.m_logArguments);
}

return pool;
Expand Down
Loading