Skip to content

Commit

Permalink
remove Debug log (an alt handling is yet to come)
Browse files Browse the repository at this point in the history
This is phase 1: make it stop creating the Debug
log, and just generally getting my head around
the flow of the deep transport logic that writes
to this log.

(Current debug-log calls are either eliminated
or temporarily routed to console-writes)

The reason these log lines are weird is because
they happen in code that isn't specific to a
session, so it can't follow the existing paradigm
(where each session has its own logger).

But some of those logs are still valuable,
so phase 2 will be logging them in an alternate
way, likely in a way that will only create
the logs when absolutely necessary (as opposed
to the current impl which can create a ton
of empty logs).
  • Loading branch information
gbirchmeier committed Feb 8, 2024
1 parent dbf04b3 commit 871b26d
Show file tree
Hide file tree
Showing 7 changed files with 44 additions and 71 deletions.
6 changes: 3 additions & 3 deletions QuickFIXn/AcceptorSocketDescriptor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,7 @@ public AcceptorSocketDescriptor(IPEndPoint socketEndPoint, SocketSettings socket
SocketReactor = new ThreadedSocketReactor(Address, socketSettings, sessionDict, this);
}

public void AcceptSession(Session session)
internal void AcceptSession(Session session)
{
lock (_acceptedSessions)
{
Expand All @@ -39,15 +39,15 @@ public void AcceptSession(Session session)
/// </summary>
/// <param name="sessionId">ID of session to be removed</param>
/// <returns>true if session removed, false if not found</returns>
public bool RemoveSession(SessionID sessionId)
internal bool RemoveSession(SessionID sessionId)
{
lock (_acceptedSessions)
{
return _acceptedSessions.Remove(sessionId);
}
}

public Dictionary<SessionID, Session> GetAcceptedSessions()
internal Dictionary<SessionID, Session> GetAcceptedSessions()
{
lock (_acceptedSessions)
{
Expand Down
30 changes: 1 addition & 29 deletions QuickFIXn/ClientHandlerThread.cs
Original file line number Diff line number Diff line change
Expand Up @@ -30,21 +30,10 @@ public ExitedEventArgs(ClientHandlerThread clientHandlerThread)
private Thread? _thread = null;
private volatile bool _isShutdownRequested = false;
private readonly SocketReader _socketReader;
private readonly FileLog _log;

internal ClientHandlerThread(TcpClient tcpClient, long clientId, QuickFix.Dictionary settingsDict,
SocketSettings socketSettings, AcceptorSocketDescriptor? acceptorDescriptor)
{
string debugLogFilePath = "log";
if (settingsDict.Has(SessionSettings.DEBUG_FILE_LOG_PATH))
debugLogFilePath = settingsDict.GetString(SessionSettings.DEBUG_FILE_LOG_PATH);
else if (settingsDict.Has(SessionSettings.FILE_LOG_PATH))
debugLogFilePath = settingsDict.GetString(SessionSettings.FILE_LOG_PATH);

// FIXME - do something more flexible than hardcoding a filelog
_log = new FileLog(debugLogFilePath, new SessionID(
"ClientHandlerThread", clientId.ToString(), "Debug-" + Guid.NewGuid()));

Id = clientId;
_socketReader = new SocketReader(tcpClient, socketSettings, this, acceptorDescriptor);
}
Expand All @@ -57,7 +46,7 @@ public void Start()

public void Shutdown(string reason)
{
Log("shutdown requested: " + reason);
// TODO - need the reason param?
_isShutdownRequested = true;
}

Expand All @@ -84,29 +73,13 @@ private void Run()
}
}

Log("shutdown");
OnExited();
}

private void OnExited() {
Exited?.Invoke(this, new ExitedEventArgs(this));
}

/// FIXME do real logging
public void Log(string s)
{
_log.OnEvent(s);
}

/// <summary>
/// Provide StreamReader with access to the log
/// </summary>
/// <returns></returns>
internal ILog GetLog()
{
return _log;
}

#region Responder Members

public bool Send(string data)
Expand Down Expand Up @@ -135,7 +108,6 @@ protected virtual void Dispose(bool disposing)
if (disposing)
{
_socketReader.Dispose();
_log.Dispose();
}
_disposed = true;
}
Expand Down
1 change: 0 additions & 1 deletion QuickFIXn/SessionSettings.cs
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,6 @@ public class SessionSettings
public const string SOCKET_CONNECT_PORT = "SocketConnectPort";
public const string RECONNECT_INTERVAL = "ReconnectInterval";
public const string FILE_LOG_PATH = "FileLogPath";
public const string DEBUG_FILE_LOG_PATH = "DebugFileLogPath";
public const string FILE_STORE_PATH = "FileStorePath";
public const string REFRESH_ON_LOGON = "RefreshOnLogon";
public const string RESET_ON_LOGON = "ResetOnLogon";
Expand Down
36 changes: 22 additions & 14 deletions QuickFIXn/SocketReader.cs
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,7 @@ internal SocketReader(
_tcpClient = tcpClient;
_responder = responder;
_acceptorDescriptor = acceptorDescriptor;
_stream = Transport.StreamFactory.CreateServerStream(tcpClient, settings, responder.GetLog());
_stream = Transport.StreamFactory.CreateServerStream(tcpClient, settings);
}

public void Read()
Expand Down Expand Up @@ -105,12 +105,13 @@ protected virtual int ReadSome(byte[] buffer, int timeoutMilliseconds)
// Nothing read
return 0;
}
else if (inner is not null)

if (inner is not null)
{
throw inner; //rethrow SocketException part (which we have exception logic for)
}
else
throw; //rethrow original exception

throw; //rethrow original exception
}
}

Expand All @@ -121,9 +122,9 @@ private void OnMessageFound(string msg)
if (_qfSession is null)
{
_qfSession = Session.LookupSession(Message.GetReverseSessionId(msg));
if (_qfSession is null || IsAssumedSession(_qfSession.SessionID))
if (_qfSession is null || IsUnknownSession(_qfSession.SessionID))
{
Log("ERROR: Disconnecting; received message for unknown session: " + msg);
LogSessionEvent("ERROR: Disconnecting; received message for unknown session: " + msg);
_qfSession = null;
DisconnectClient();
return;
Expand All @@ -148,7 +149,7 @@ private void OnMessageFound(string msg)
}
catch (Exception e)
{
Log($"Error on Session '{_qfSession.SessionID}': {e}");
_qfSession.Log.OnEvent($"Error on Session '{_qfSession.SessionID}': {e}");
}
}
catch (InvalidMessage e)
Expand All @@ -167,12 +168,13 @@ protected void HandleBadMessage(string msg, Exception e)
{
if (Fields.MsgType.LOGON.Equals(Message.GetMsgType(msg)))
{
Log("ERROR: Invalid LOGON message, disconnecting: " + e.Message);
LogSessionEvent($"ERROR: Invalid LOGON message, disconnecting: {e.Message}");
// TODO: else session-agnostic log
DisconnectClient();
}
else
{
Log("ERROR: Invalid message: " + e.Message);
LogSessionEvent($"ERROR: Invalid message: {e.Message}");
}
}
catch (InvalidMessage)
Expand Down Expand Up @@ -204,7 +206,7 @@ protected void DisconnectClient()
_tcpClient.Close();
}

private bool IsAssumedSession(SessionID sessionId)
private bool IsUnknownSession(SessionID sessionId)
{
return _acceptorDescriptor is not null
&& !_acceptorDescriptor.GetAcceptedSessions().Any(kv => kv.Key.Equals(sessionId));
Expand Down Expand Up @@ -242,7 +244,7 @@ private void HandleExceptionInternal(Session? quickFixSession, Exception cause)
break;
}

Log($"SocketReader Error: {reason}");
LogSessionEvent($"SocketReader Error: {reason}");

if (disconnectNeeded)
{
Expand All @@ -254,12 +256,18 @@ private void HandleExceptionInternal(Session? quickFixSession, Exception cause)
}

/// <summary>
/// FIXME do proper logging
/// Log event if session can be identified (TODO: logging if not specific to a session)
/// </summary>
/// <param name="s"></param>
private void Log(string s)
private void LogSessionEvent(string s)
{
_responder.Log(s);
if(_qfSession is not null)
_qfSession.Log.OnEvent(s);
else {
// Can't tie this to a session, need a generic log.
// TODO this is a temp console log until I do something better
Console.WriteLine(s);
}
}

public int Send(string data)
Expand Down
3 changes: 0 additions & 3 deletions QuickFIXn/ThreadedSocketAcceptor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -145,11 +145,9 @@ private void StartAcceptingConnections()
{
lock (_sync)
{
// FIXME StartSessionTimer();
foreach (AcceptorSocketDescriptor socketDescriptor in _socketDescriptorForAddress.Values)
{
socketDescriptor.SocketReactor.Start();
// FIXME log_.Info("Listening for connections on " + socketDescriptor.getAddress());
}
}
}
Expand All @@ -161,7 +159,6 @@ private void StopAcceptingConnections()
foreach (AcceptorSocketDescriptor socketDescriptor in _socketDescriptorForAddress.Values)
{
socketDescriptor.SocketReactor.Shutdown();
// FIXME log_.Info("No longer accepting connections on " + socketDescriptor.getAddress());
}
}
}
Expand Down
5 changes: 2 additions & 3 deletions QuickFIXn/ThreadedSocketReactor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@ public State ReactorState

#endregion

// TODO: internalize. Only used by test.
public ThreadedSocketReactor(
IPEndPoint serverSocketEndPoint,
SocketSettings socketSettings,
Expand Down Expand Up @@ -137,8 +138,6 @@ public void Run()
_clientThreads.Add(t.Id, t);
}

// FIXME set the client thread's exception handler here
t.Log("connected");
t.Start();
}
else
Expand Down Expand Up @@ -214,7 +213,7 @@ private void ShutdownClientHandlerThreads()
}
catch (Exception e)
{
t.Log("Error shutting down: " + e.Message);
Log($"Error shutting down: {e.Message}");
}
t.Dispose();
}
Expand Down
34 changes: 16 additions & 18 deletions QuickFIXn/Transport/StreamFactory.cs
Original file line number Diff line number Diff line change
Expand Up @@ -102,7 +102,7 @@ public static Stream CreateClientStream(IPEndPoint endpoint, SocketSettings sett
Stream stream = new NetworkStream(socket, true);

if (settings.UseSSL)
stream = new SslStreamFactory(logger, settings).CreateClientStreamAndAuthenticate(stream);
stream = new SslStreamFactory(settings).CreateClientStreamAndAuthenticate(stream);

return stream;
}
Expand All @@ -112,18 +112,17 @@ public static Stream CreateClientStream(IPEndPoint endpoint, SocketSettings sett
/// </summary>
/// <param name="tcpClient">The TCP client.</param>
/// <param name="settings">The socket settings.</param>
/// <param name="logger">Logger to use.</param>
/// <returns>an opened and initiated stream which can be read and written to</returns>
/// <exception cref="System.ArgumentException">tcp client must be connected in order to get stream;tcpClient</exception>
public static Stream CreateServerStream(TcpClient tcpClient, SocketSettings settings, ILog logger)
public static Stream CreateServerStream(TcpClient tcpClient, SocketSettings settings)
{
if (tcpClient.Connected == false)
throw new ArgumentException("tcp client must be connected in order to get stream", nameof(tcpClient));

Stream stream = tcpClient.GetStream();
if (settings.UseSSL)
{
stream = new SslStreamFactory(logger, settings).CreateServerStreamAndAuthenticate(stream);
stream = new SslStreamFactory(settings).CreateServerStreamAndAuthenticate(stream);
}

return stream;
Expand Down Expand Up @@ -227,14 +226,12 @@ public static Stream CreateServerStream(TcpClient tcpClient, SocketSettings sett
/// </summary>
private sealed class SslStreamFactory
{
private readonly ILog _log;
private readonly SocketSettings _socketSettings;
private const string CLIENT_AUTHENTICATION_OID = "1.3.6.1.5.5.7.3.2";
private const string SERVER_AUTHENTICATION_OID = "1.3.6.1.5.5.7.3.1";

public SslStreamFactory(ILog log, SocketSettings settings)
public SslStreamFactory(SocketSettings settings)
{
_log = log;
_socketSettings = settings;
}

Expand Down Expand Up @@ -265,7 +262,7 @@ public Stream CreateClientStreamAndAuthenticate(Stream innerStream)
}
catch (System.Security.Authentication.AuthenticationException ex)
{
_log.OnEvent("Unable to perform authentication against server: " + ex.Message);
Log($"Unable to perform authentication against server: {ex.Message}");
throw;
}

Expand Down Expand Up @@ -306,7 +303,7 @@ public Stream CreateServerStreamAndAuthenticate(Stream innerStream)
}
catch (System.Security.Authentication.AuthenticationException ex)
{
_log.OnEvent("Unable to perform authentication against server: " + ex.Message);
Log($"Unable to perform authentication against server: {ex.Message}");
throw;
}

Expand Down Expand Up @@ -376,26 +373,22 @@ private bool VerifyRemoteCertificate(
// Validate enhanced key usage
if (!ContainsEnhancedKeyUsage(certificate, enhancedKeyUsage)) {
if (enhancedKeyUsage == CLIENT_AUTHENTICATION_OID)
_log.OnEvent(
"Remote certificate is not intended for client authentication: It is missing enhanced key usage " +
enhancedKeyUsage);
Log($"Remote certificate is not intended for client authentication: It is missing enhanced key usage {enhancedKeyUsage}");
else
_log.OnEvent(
"Remote certificate is not intended for server authentication: It is missing enhanced key usage " +
enhancedKeyUsage);
Log($"Remote certificate is not intended for server authentication: It is missing enhanced key usage {enhancedKeyUsage}");

return false;
}

if (string.IsNullOrEmpty(_socketSettings.CACertificatePath)) {
_log.OnEvent("CACertificatePath is not specified");
Log("CACertificatePath is not specified");
return false;
}

// If CA Certficiate is specified then validate agains the CA certificate, otherwise it is validated against the installed certificates
X509Certificate2? cert = LoadCertificate(_socketSettings.CACertificatePath, null);
if (cert is null) {
_log.OnEvent("Remote certificate was not recognized as a valid certificate: " + sslPolicyErrors);
Log($"Remote certificate was not recognized as a valid certificate: {sslPolicyErrors}");
return false;
}

Expand All @@ -420,7 +413,7 @@ private bool VerifyRemoteCertificate(
// Any basic authentication check failed, do after checking CA
if (sslPolicyErrors != SslPolicyErrors.None)
{
_log.OnEvent("Remote certificate was not recognized as a valid certificate: " + sslPolicyErrors);
Log($"Remote certificate was not recognized as a valid certificate: {sslPolicyErrors}");
return false;
}

Expand Down Expand Up @@ -494,6 +487,11 @@ private static bool ContainsEnhancedKeyUsage(X509Certificate certificate, string

return null;
}

private void Log(string s) {
// TODO this is just a temp console log until I do something better
Console.WriteLine(s);
}
}
}
}

0 comments on commit 871b26d

Please sign in to comment.