Skip to content

Commit 819f769

Browse files
bgraingerbgrainger
committed
Reduce most Info logging to Debug or Trace.
Signed-off-by: Bradley Grainger <[email protected]>
1 parent f719e4e commit 819f769

File tree

6 files changed

+49
-49
lines changed

6 files changed

+49
-49
lines changed

‎src/MySqlConnector/Core/BackgroundConnectionResetHelper.cs

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ public static void AddSession(ServerSession session, MySqlConnection? owningConn
3535

3636
public static void Start()
3737
{
38-
Log.Info("Starting BackgroundConnectionResetHelper worker.");
38+
Log.Trace("Starting BackgroundConnectionResetHelper worker.");
3939
lock (s_lock)
4040
{
4141
if (s_workerTask is null)
@@ -45,7 +45,7 @@ public static void Start()
4545

4646
public static void Stop()
4747
{
48-
Log.Info("Stopping BackgroundConnectionResetHelper worker.");
48+
Log.Trace("Stopping BackgroundConnectionResetHelper worker.");
4949
s_cancellationTokenSource.Cancel();
5050
Task? workerTask;
5151
lock (s_lock)
@@ -61,12 +61,12 @@ public static void Stop()
6161
{
6262
}
6363
}
64-
Log.Info("Stopped BackgroundConnectionResetHelper worker.");
64+
Log.Trace("Stopped BackgroundConnectionResetHelper worker.");
6565
}
6666

6767
public static async Task ReturnSessionsAsync()
6868
{
69-
Log.Info("Started BackgroundConnectionResetHelper worker.");
69+
Log.Trace("Started BackgroundConnectionResetHelper worker.");
7070

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

‎src/MySqlConnector/Core/CachedProcedure.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -97,8 +97,8 @@ FROM information_schema.parameters
9797
}
9898
}
9999

100-
if (Log.IsInfoEnabled())
101-
Log.Info("Procedure for Schema={0} Component={1} has RoutineCount={2}, ParameterCount={3}", schema, component, routineCount, parameters.Count);
100+
if (Log.IsTraceEnabled())
101+
Log.Trace("Procedure for Schema={0} Component={1} has RoutineCount={2}, ParameterCount={3}", schema, component, routineCount, parameters.Count);
102102
return routineCount == 0 ? null : new CachedProcedure(schema, component, parameters);
103103
}
104104

‎src/MySqlConnector/Core/ConnectionPool.cs

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
2828
// on the lock in RecoverLeakedSessions in high-concurrency situations
2929
if (IsEmpty && unchecked(((uint) Environment.TickCount) - m_lastRecoveryTime) >= 1000u)
3030
{
31-
Log.Info("Pool{0} is empty; recovering leaked sessions", m_logArguments);
31+
Log.Debug("Pool{0} is empty; trying to recover any leaked sessions", m_logArguments);
3232
await RecoverLeakedSessionsAsync(ioBehavior).ConfigureAwait(false);
3333
}
3434

@@ -183,7 +183,7 @@ public async ValueTask ReturnAsync(IOBehavior ioBehavior, ServerSession session)
183183
if (sessionHealth == 1)
184184
Log.Warn("Pool{0} received invalid Session{1}; destroying it", m_logArguments[0], session.Id);
185185
else
186-
Log.Info("Pool{0} received expired Session{1}; destroying it", m_logArguments[0], session.Id);
186+
Log.Debug("Pool{0} received expired Session{1}; destroying it", m_logArguments[0], session.Id);
187187
AdjustHostConnectionCount(session, -1);
188188
await session.DisposeAsync(ioBehavior, CancellationToken.None).ConfigureAwait(false);
189189
}
@@ -306,7 +306,7 @@ private async Task CleanPoolAsync(IOBehavior ioBehavior, Func<ServerSession, boo
306306
if (shouldCleanFn(session))
307307
{
308308
// session should be cleaned; dispose it and keep iterating
309-
Log.Info("Pool{0} found Session{1} to clean up", m_logArguments[0], session.Id);
309+
Log.Debug("Pool{0} found Session{1} to clean up", m_logArguments[0], session.Id);
310310
await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
311311
}
312312
else
@@ -371,40 +371,40 @@ private async Task CreateMinimumPooledSessions(IOBehavior ioBehavior, Cancellati
371371
private async ValueTask<ServerSession> ConnectSessionAsync(string logMessage, int startTickCount, IOBehavior ioBehavior, CancellationToken cancellationToken)
372372
{
373373
var session = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastSessionId));
374-
if (Log.IsInfoEnabled())
375-
Log.Info(logMessage, m_logArguments[0], session.Id);
374+
if (Log.IsDebugEnabled())
375+
Log.Debug(logMessage, m_logArguments[0], session.Id);
376376
var statusInfo = await session.ConnectAsync(ConnectionSettings, startTickCount, m_loadBalancer, ioBehavior, cancellationToken).ConfigureAwait(false);
377377
Exception? redirectionException = null;
378378

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

384384
if (ConnectionSettings.ServerRedirectionMode == MySqlServerRedirectionMode.Disabled)
385385
{
386-
Log.Info("Pool{0} server redirection is disabled; ignoring redirection", m_logArguments);
386+
Log.Trace("Pool{0} server redirection is disabled; ignoring redirection", m_logArguments);
387387
}
388388
else if (Utility.TryParseRedirectionHeader(statusInfo, out var host, out var port, out var user))
389389
{
390390
if (host != ConnectionSettings.HostNames![0] || port != ConnectionSettings.Port || user != ConnectionSettings.UserID)
391391
{
392392
var redirectedSettings = ConnectionSettings.CloneWith(host, port, user);
393-
Log.Info("Pool{0} opening new connection to Host={1}; Port={2}; User={3}", m_logArguments[0], host, port, user);
393+
Log.Debug("Pool{0} opening new connection to Host={1}; Port={2}; User={3}", m_logArguments[0], host, port, user);
394394
var redirectedSession = new ServerSession(this, m_generation, Interlocked.Increment(ref m_lastSessionId));
395395
try
396396
{
397397
await redirectedSession.ConnectAsync(redirectedSettings, startTickCount, m_loadBalancer, ioBehavior, cancellationToken).ConfigureAwait(false);
398398
}
399399
catch (Exception ex)
400400
{
401-
Log.Warn(ex, "Pool{0} failed to connect redirected Session{1}", m_logArguments[0], redirectedSession.Id);
401+
Log.Info(ex, "Pool{0} failed to connect redirected Session{1}", m_logArguments[0], redirectedSession.Id);
402402
redirectionException = ex;
403403
}
404404

405405
if (redirectionException is null)
406406
{
407-
Log.Info("Pool{0} closing Session{1} to use redirected Session{2} instead", m_logArguments[0], session.Id, redirectedSession.Id);
407+
Log.Trace("Pool{0} closing Session{1} to use redirected Session{2} instead", m_logArguments[0], session.Id, redirectedSession.Id);
408408
await session.DisposeAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
409409
return redirectedSession;
410410
}
@@ -421,7 +421,7 @@ private async ValueTask<ServerSession> ConnectSessionAsync(string logMessage, in
421421
}
422422
else
423423
{
424-
Log.Info("Session{0} is already connected to this server; ignoring redirection", session.Id);
424+
Log.Trace("Session{0} is already connected to this server; ignoring redirection", session.Id);
425425
}
426426
}
427427
}
@@ -486,9 +486,9 @@ private async ValueTask<ServerSession> ConnectSessionAsync(string logMessage, in
486486
if (connectionSettings.ConnectionReset)
487487
BackgroundConnectionResetHelper.Start();
488488
}
489-
else if (pool != newPool && Log.IsInfoEnabled())
489+
else if (pool != newPool && Log.IsDebugEnabled())
490490
{
491-
Log.Info("Pool{0} was created but will not be used (due to race)", newPool.m_logArguments);
491+
Log.Debug("Pool{0} was created but will not be used (due to race)", newPool.m_logArguments);
492492
}
493493

494494
return pool;

‎src/MySqlConnector/Core/ServerSession.cs

Lines changed: 22 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -111,7 +111,7 @@ public bool TryStartCancel(ICancellableCommand command)
111111
m_state = State.CancelingQuery;
112112
}
113113

114-
Log.Info("Session{0} will cancel CommandId: {1} (CancelledAttempts={2}) CommandText: {3}", m_logArguments[0], command.CommandId, command.CancelAttemptCount, (command as MySqlCommand)?.CommandText);
114+
Log.Debug("Session{0} will cancel CommandId: {1} (CancelledAttempts={2}) CommandText: {3}", m_logArguments[0], command.CommandId, command.CancelAttemptCount, (command as MySqlCommand)?.CommandText);
115115
return true;
116116
}
117117

@@ -122,7 +122,7 @@ public void DoCancel(ICancellableCommand commandToCancel, MySqlCommand killComma
122122
{
123123
if (ActiveCommandId != commandToCancel.CommandId)
124124
{
125-
Log.Info("Session{0} ActiveCommandId {1} is not the CommandId {2} being canceled; ignoring cancellation.", m_logArguments[0], ActiveCommandId, commandToCancel.CommandId);
125+
Log.Debug("Session{0} ActiveCommandId {1} is not the CommandId {2} being canceled; ignoring cancellation.", m_logArguments[0], ActiveCommandId, commandToCancel.CommandId);
126126
return;
127127
}
128128

@@ -132,7 +132,7 @@ public void DoCancel(ICancellableCommand commandToCancel, MySqlCommand killComma
132132
// command would be killed (because "KILL QUERY" specifies the connection whose command should be killed, not
133133
// a unique identifier of the command itself). As a mitigation, we set the CommandTimeout to a low value to avoid
134134
// blocking the other thread for an extended duration.
135-
Log.Info("Session{0} canceling CommandId {1} with CommandText {2}", killCommand.Connection!.Session.Id, commandToCancel.CommandId, killCommand.CommandText);
135+
Log.Debug("Session{0} canceling CommandId {1} with CommandText {2}", killCommand.Connection!.Session.Id, commandToCancel.CommandId, killCommand.CommandText);
136136
killCommand.ExecuteNonQuery();
137137
}
138138
}
@@ -312,7 +312,7 @@ public void FinishQuerying()
312312
// KILL QUERY will kill a subsequent query if the command it was intended to cancel has already completed.
313313
// In order to handle this case, we issue a dummy query that will consume the pending cancellation.
314314
// See https://bugs.mysql.com/bug.php?id=45679
315-
Log.Info("Session{0} sending 'DO SLEEP(0)' command to clear pending cancellation", m_logArguments);
315+
Log.Debug("Session{0} sending 'DO SLEEP(0)' command to clear pending cancellation", m_logArguments);
316316
var payload = QueryPayload.Create("DO SLEEP(0);");
317317
#pragma warning disable CA2012 // Safe because method completes synchronously
318318
SendAsync(payload, IOBehavior.Synchronous, CancellationToken.None).GetAwaiter().GetResult();
@@ -350,7 +350,7 @@ public async Task DisposeAsync(IOBehavior ioBehavior, CancellationToken cancella
350350
{
351351
try
352352
{
353-
Log.Info("Session{0} sending QUIT command", m_logArguments);
353+
Log.Trace("Session{0} sending QUIT command", m_logArguments);
354354
m_payloadHandler.StartNewConversation();
355355
await m_payloadHandler.WritePayloadAsync(QuitPayload.Instance.Memory, ioBehavior).ConfigureAwait(false);
356356
}
@@ -453,7 +453,7 @@ public async Task DisposeAsync(IOBehavior ioBehavior, CancellationToken cancella
453453
m_characterSet = ServerVersion.Version >= ServerVersions.SupportsUtf8Mb4 ? CharacterSet.Utf8Mb4GeneralCaseInsensitive : CharacterSet.Utf8GeneralCaseInsensitive;
454454
m_setNamesPayload = ServerVersion.Version >= ServerVersions.SupportsUtf8Mb4 ? s_setNamesUtf8mb4Payload : s_setNamesUtf8Payload;
455455

456-
Log.Info("Session{0} made connection; ServerVersion={1}; ConnectionId={2}; Compression={3}; Attributes={4}; DeprecateEof={5}; Ssl={6}; SessionTrack={7}",
456+
Log.Debug("Session{0} made connection; ServerVersion={1}; ConnectionId={2}; Compression={3}; Attributes={4}; DeprecateEof={5}; Ssl={6}; SessionTrack={7}",
457457
m_logArguments[0], ServerVersion.OriginalString, ConnectionId,
458458
m_useCompression, m_supportsConnectionAttributes, m_supportsDeprecateEof, serverSupportsSsl, m_supportsSessionTrack);
459459

@@ -850,7 +850,7 @@ public ValueTask<PayloadData> ReceiveReplyAsync(IOBehavior ioBehavior, Cancellat
850850
}
851851
catch (Exception ex)
852852
{
853-
Log.Info(ex, "Session{0} failed in ReceiveReplyAsync", m_logArguments);
853+
Log.Debug(ex, "Session{0} failed in ReceiveReplyAsync", m_logArguments);
854854
if ((ex as MySqlException)?.ErrorCode == MySqlErrorCode.CommandTimeoutExpired)
855855
HandleTimeout();
856856
task = ValueTaskExtensions.FromException<ArraySegment<byte>>(ex);
@@ -900,7 +900,7 @@ public ValueTask<int> SendReplyAsync(PayloadData payload, IOBehavior ioBehavior,
900900
}
901901
catch (Exception ex)
902902
{
903-
Log.Info(ex, "Session{0} failed in SendReplyAsync", m_logArguments);
903+
Log.Debug(ex, "Session{0} failed in SendReplyAsync", m_logArguments);
904904
task = ValueTaskExtensions.FromException<int>(ex);
905905
}
906906

@@ -971,7 +971,7 @@ private async Task<bool> OpenTcpSocketAsync(ConnectionSettings cs, ILoadBalancer
971971
// need to try IP Addresses one at a time: https://github.com/dotnet/corefx/issues/5829
972972
foreach (var ipAddress in ipAddresses)
973973
{
974-
Log.Info("Session{0} connecting to IpAddress {1} for HostName '{2}'", m_logArguments[0], ipAddress, hostName);
974+
Log.Trace("Session{0} connecting to IpAddress {1} for HostName '{2}'", m_logArguments[0], ipAddress, hostName);
975975
TcpClient? tcpClient = null;
976976
try
977977
{
@@ -1047,7 +1047,7 @@ private async Task<bool> OpenTcpSocketAsync(ConnectionSettings cs, ILoadBalancer
10471047
private async Task<bool> OpenUnixSocketAsync(ConnectionSettings cs, IOBehavior ioBehavior, CancellationToken cancellationToken)
10481048
{
10491049
m_logArguments[1] = cs.UnixSocket;
1050-
Log.Info("Session{0} connecting to UNIX Socket '{1}'", m_logArguments);
1050+
Log.Trace("Session{0} connecting to UNIX Socket '{1}'", m_logArguments);
10511051
var socket = new Socket(AddressFamily.Unix, SocketType.Stream, ProtocolType.IP);
10521052
var unixEp = new UnixEndPoint(cs.UnixSocket!);
10531053
try
@@ -1105,8 +1105,8 @@ private async Task<bool> OpenNamedPipeAsync(ConnectionSettings cs, int startTick
11051105
#if NETSTANDARD1_3
11061106
throw new NotSupportedException("Named pipe connections are not supported in netstandard1.3");
11071107
#else
1108-
if (Log.IsInfoEnabled())
1109-
Log.Info("Session{0} connecting to NamedPipe '{1}' on Server '{2}'", m_logArguments[0], cs.PipeName, cs.HostNames![0]);
1108+
if (Log.IsTraceEnabled())
1109+
Log.Trace("Session{0} connecting to NamedPipe '{1}' on Server '{2}'", m_logArguments[0], cs.PipeName, cs.HostNames![0]);
11101110
var namedPipeStream = new NamedPipeClientStream(cs.HostNames![0], cs.PipeName, PipeDirection.InOut, PipeOptions.Asynchronous);
11111111
var timeout = Math.Max(1, cs.ConnectionTimeoutMilliseconds - unchecked(Environment.TickCount - startTickCount));
11121112
try
@@ -1150,7 +1150,7 @@ private async Task<bool> OpenNamedPipeAsync(ConnectionSettings cs, int startTick
11501150

11511151
private async Task InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken)
11521152
{
1153-
Log.Info("Session{0} initializing TLS connection", m_logArguments);
1153+
Log.Trace("Session{0} initializing TLS connection", m_logArguments);
11541154
X509CertificateCollection? clientCertificates = null;
11551155

11561156
if (cs.CertificateStoreLocation != MySqlCertificateStoreLocation.None)
@@ -1273,8 +1273,8 @@ private async Task InitSslAsync(ProtocolCapabilities serverCapabilities, Connect
12731273
}
12741274

12751275
// success
1276-
if (Log.IsInfoEnabled())
1277-
Log.Info("Session{0} loaded certificates from CertificateFile '{1}'; CertificateCount: {2}", m_logArguments[0], cs.CACertificateFile, certificateChain.ChainPolicy.ExtraStore.Count);
1276+
if (Log.IsTraceEnabled())
1277+
Log.Trace("Session{0} loaded certificates from CertificateFile '{1}'; CertificateCount: {2}", m_logArguments[0], cs.CACertificateFile, certificateChain.ChainPolicy.ExtraStore.Count);
12781278
caCertificateChain = certificateChain;
12791279
certificateChain = null;
12801280
}
@@ -1363,12 +1363,12 @@ await sslStream.AuthenticateAsClientAsync(clientAuthenticationOptions.TargetHost
13631363
m_payloadHandler!.ByteHandler = sslByteHandler;
13641364
m_isSecureConnection = true;
13651365
m_sslStream = sslStream;
1366-
if (Log.IsInfoEnabled())
1366+
if (Log.IsDebugEnabled())
13671367
{
13681368
#if NET45 || NET461 || NET471 || NETSTANDARD1_3 || NETSTANDARD2_0 || NETSTANDARD2_1 || NETCOREAPP2_1
1369-
Log.Info("Session{0} connected TLS with SslProtocol={1}, CipherAlgorithm={2}, HashAlgorithm={3}, KeyExchangeAlgorithm={4}, KeyExchangeStrength={5}", m_logArguments[0], sslStream.SslProtocol, sslStream.CipherAlgorithm, sslStream.HashAlgorithm, sslStream.KeyExchangeAlgorithm, sslStream.KeyExchangeStrength);
1369+
Log.Debug("Session{0} connected TLS with SslProtocol={1}, CipherAlgorithm={2}, HashAlgorithm={3}, KeyExchangeAlgorithm={4}, KeyExchangeStrength={5}", m_logArguments[0], sslStream.SslProtocol, sslStream.CipherAlgorithm, sslStream.HashAlgorithm, sslStream.KeyExchangeAlgorithm, sslStream.KeyExchangeStrength);
13701370
#else
1371-
Log.Info("Session{0} connected TLS with SslProtocol={1}, NegotiatedCipherSuite={2}", m_logArguments[0], sslStream.SslProtocol, sslStream.NegotiatedCipherSuite);
1371+
Log.Debug("Session{0} connected TLS with SslProtocol={1}, NegotiatedCipherSuite={2}", m_logArguments[0], sslStream.SslProtocol, sslStream.NegotiatedCipherSuite);
13721372
#endif
13731373
}
13741374
}
@@ -1511,7 +1511,7 @@ private bool ShouldGetRealServerDetails(ConnectionSettings cs)
15111511

15121512
private async Task GetRealServerDetailsAsync(IOBehavior ioBehavior, CancellationToken cancellationToken)
15131513
{
1514-
Log.Info("Session{0} detected proxy; getting CONNECTION_ID(), VERSION() from server", m_logArguments);
1514+
Log.Debug("Session{0} detected proxy; getting CONNECTION_ID(), VERSION() from server", m_logArguments);
15151515
try
15161516
{
15171517
await SendAsync(QueryPayload.Create("SELECT CONNECTION_ID(), VERSION();"), ioBehavior, cancellationToken).ConfigureAwait(false);
@@ -1552,7 +1552,7 @@ static void ReadRow(ReadOnlySpan<byte> span, out int? connectionId, out byte[]?
15521552
if (connectionId.HasValue && serverVersion is not null)
15531553
{
15541554
var newServerVersion = new ServerVersion(serverVersion);
1555-
Log.Info("Session{0} changing ConnectionIdOld {1} to ConnectionId {2} and ServerVersionOld {3} to ServerVersion {4}", m_logArguments[0], ConnectionId, connectionId.Value, ServerVersion.OriginalString, newServerVersion.OriginalString);
1555+
Log.Debug("Session{0} changing ConnectionIdOld {1} to ConnectionId {2} and ServerVersionOld {3} to ServerVersion {4}", m_logArguments[0], ConnectionId, connectionId.Value, ServerVersion.OriginalString, newServerVersion.OriginalString);
15561556
ConnectionId = connectionId.Value;
15571557
ServerVersion = newServerVersion;
15581558
}
@@ -1565,7 +1565,7 @@ static void ReadRow(ReadOnlySpan<byte> span, out int? connectionId, out byte[]?
15651565

15661566
private void ShutdownSocket()
15671567
{
1568-
Log.Info("Session{0} closing stream/socket", m_logArguments);
1568+
Log.Debug("Session{0} closing stream/socket", m_logArguments);
15691569
Utility.Dispose(ref m_payloadHandler);
15701570
Utility.Dispose(ref m_stream);
15711571
SafeDispose(ref m_tcpClient);
@@ -1605,7 +1605,7 @@ private static void SafeDispose<T>(ref T? disposable)
16051605

16061606
internal void SetFailed(Exception exception)
16071607
{
1608-
Log.Info(exception, "Session{0} setting state to Failed", m_logArguments);
1608+
Log.Debug(exception, "Session{0} setting state to Failed", m_logArguments);
16091609
lock (m_lock)
16101610
m_state = State.Failed;
16111611
if (OwningConnection is not null && OwningConnection.TryGetTarget(out var connection))

‎src/MySqlConnector/MySqlBulkCopy.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -227,7 +227,7 @@ private async ValueTask WriteToServerAsync(IOBehavior ioBehavior, CancellationTo
227227
var tableName = DestinationTableName ?? throw new InvalidOperationException("DestinationTableName must be set before calling WriteToServer");
228228
m_wasAborted = false;
229229

230-
Log.Info("Starting bulk copy to {0}", tableName);
230+
Log.Debug("Starting bulk copy to {0}", tableName);
231231
var bulkLoader = new MySqlBulkLoader(m_connection)
232232
{
233233
CharacterSet = "utf8mb4",
@@ -318,7 +318,7 @@ private async ValueTask WriteToServerAsync(IOBehavior ioBehavior, CancellationTo
318318
if (closeConnection)
319319
m_connection.Close();
320320

321-
Log.Info("Finished bulk copy to {0}", tableName);
321+
Log.Debug("Finished bulk copy to {0}", tableName);
322322

323323
if (!m_wasAborted && rowsInserted != RowsCopied)
324324
{

0 commit comments

Comments
 (0)