Skip to content

Introduce ILogger and ActivitySource based logging #649

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
haga-rak merged 6 commits into from
May 3, 2026
Merged

Introduce ILogger and ActivitySource based logging #649

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
b1f589e
Remove H2 Logger
haga-rak Apr 24, 2026
4c4e52d
Remove H1 Logger
haga-rak Apr 24, 2026
4125cfb
Fix cancellation wrongly removed
haga-rak Apr 24, 2026
5656f21
Introduce ILogger and ActivitySource based logging
haga-rak Apr 29, 2026
05c2225
Tag activities with Proxy.InstanceId
Apr 29, 2026
bdca2f9
Add -t/--trace option to fluxzy start
Apr 29, 2026
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
296 changes: 296 additions & 0 deletions docs/logging.md
View file
Open in desktop

Large diffs are not rendered by default.

21 changes: 16 additions & 5 deletions src/Fluxzy.Core/Clients/DnsUtility.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,10 @@
using System.Threading.Tasks;
using Fluxzy.Clients.Mock;
using Fluxzy.Core;
using Fluxzy.Logging;
using Fluxzy.Rules;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;

namespace Fluxzy.Clients
{
Expand All @@ -28,24 +31,32 @@ public DnsResolutionResult(IPEndPoint endPoint, DateTime dnsSolveStart, DateTime
internal static class DnsUtility
{
public static async ValueTask<DnsResolutionResult>
ComputeDnsUpdateExchange(Exchange exchange,
ITimingProvider timingProvider, IDnsSolver dnsSolver,
ProxyRuntimeSetting? runtimeSetting)
ComputeDnsUpdateExchange(Exchange exchange,
ITimingProvider timingProvider, IDnsSolver dnsSolver,
ProxyRuntimeSetting? runtimeSetting,
ILogger? logger = null)
{
var dnsSolveStart = timingProvider.Instant();
var connectHostName = exchange.Context.ProxyConfiguration?.Host ?? exchange.Authority.HostName;


var wasForced = exchange.Context.RemoteHostIp != null;

var ipAddress = exchange.Context.RemoteHostIp ??
await dnsSolver.SolveDns(connectHostName).ConfigureAwait(false);

var dnsSolveEnd = timingProvider.Instant();

var remotePort = exchange.Context.ProxyConfiguration?.Port ?? exchange.Context.RemoteHostPort
var remotePort = exchange.Context.ProxyConfiguration?.Port ?? exchange.Context.RemoteHostPort
?? exchange.Authority.Port;

exchange.Context.RemoteHostIp = ipAddress;
exchange.Context.RemoteHostPort = remotePort;

FluxzyLogEvents.LogDnsResolved(
logger ?? NullLogger.Instance,
exchange, connectHostName, ipAddress, remotePort,
dnsSolveStart, dnsSolveEnd, dnsSolver, wasForced);

var remoteEndPoint = new IPEndPoint(ipAddress, remotePort);

return new(remoteEndPoint, dnsSolveStart, dnsSolveEnd);
Expand Down
30 changes: 5 additions & 25 deletions src/Fluxzy.Core/Clients/H11/Http11ConnectionPool.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,8 +22,6 @@ public class Http11ConnectionPool : IHttpConnectionPool
private readonly RealtimeArchiveWriter _archiveWriter;
private readonly DnsResolutionResult _resolutionResult;

private readonly H1Logger _logger;

private readonly Channel<Http11ProcessingState> _pendingConnections;

private readonly ProxyRuntimeSetting _proxyRuntimeSetting;
Expand Down Expand Up @@ -52,8 +50,6 @@ internal Http11ConnectionPool(
SingleWriter = false
});

_logger = new H1Logger(authority);

ITimingProvider.Default.Instant();
}

Expand All @@ -74,9 +70,6 @@ public async ValueTask Send(
exchange.HttpVersion = "HTTP/1.1";

try {
_logger.Trace(exchange, "Begin wait for authority slot");
_logger.Trace(exchange.Id, "Acquiring slot");

var requestDate = _timingProvider.Instant();

while (_pendingConnections.Reader.TryRead(out var state)) {
Expand All @@ -90,14 +83,10 @@ public async ValueTask Send(
}

exchange.Connection = state.Connection;
_logger.Trace(exchange.Id, () => $"Recycling connection : {exchange.Connection.Id}");

break;
}

if (exchange.Connection == null) {
_logger.Trace(exchange.Id, () => "New connection request");

var openingResult =
await _remoteConnectionBuilder.OpenConnectionToRemote(
exchange, _resolutionResult , Http11Protocols,
Expand All @@ -113,21 +102,19 @@ await _remoteConnectionBuilder.OpenConnectionToRemote(

if (_archiveWriter != null!)
_archiveWriter.Update(exchange.Connection, cancellationToken);

_logger.Trace(exchange.Id, () => $"New connection obtained: {exchange.Connection.Id}");
}

var poolProcessing = new Http11PoolProcessing(_logger, _proxyRuntimeSetting.ExpectContinueTimeout);
var poolProcessing = new Http11PoolProcessing(
_proxyRuntimeSetting.ExpectContinueTimeout,
_proxyRuntimeSetting.GetLogger<Http11PoolProcessing>());

try {
await poolProcessing.Process(exchange, buffer, exchangeScope, cancellationToken)
.ConfigureAwait(false);

if (exchange.Response.Header != null)
exchange.Connection.TimeoutIdleSeconds = exchange.Response.Header.TimeoutIdleSeconds;

_logger.Trace(exchange.Id, () => "[Process] return");


var lastUsed = _timingProvider.Instant();

void OnExchangeCompleteFunction(Task<bool> completeTask)
Expand All @@ -143,8 +130,6 @@ void OnExchangeCompleteFunction(Task<bool> completeTask)
exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant();

if (completeTask.Exception != null && completeTask.Exception.InnerExceptions.Any()) {
_logger.Trace(exchange.Id, () => $"Complete on error {completeTask.Exception.GetType()} : {completeTask.Exception.Message}");

foreach (var exception in completeTask.Exception.InnerExceptions) {
exchange.Errors.Add(new Error("Error while reading response", exception));
}
Expand All @@ -154,13 +139,10 @@ void OnExchangeCompleteFunction(Task<bool> completeTask)
if (_pendingConnections.Writer.TryWrite(
new Http11ProcessingState(exchange.Connection, lastUsed)))
{
_logger.Trace(exchange.Id, () => "Complete on success, recycling connection ...");
return;
}
}
else {
_logger.Trace(exchange.Id, () => "Complete on success, closing connection ...");

// should close connection
}

Expand All @@ -178,9 +160,7 @@ void OnExchangeCompleteFunction(Task<bool> completeTask)

exchange.Connection = null;
}

_logger.Trace(exchange.Id, () => $"Processing error {ex}");


throw;
}
}
Expand Down
36 changes: 16 additions & 20 deletions src/Fluxzy.Core/Clients/H11/Http11PoolProcessing.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,21 +8,24 @@
using Fluxzy.Clients.H2.Encoder.Utils;
using Fluxzy.Core;
using Fluxzy.Formatters.Producers.Requests;
using Fluxzy.Logging;
using Fluxzy.Misc.ResizableBuffers;
using Fluxzy.Misc.Streams;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Org.BouncyCastle.Tls;

namespace Fluxzy.Clients.H11
{
internal class Http11PoolProcessing
{
private readonly H1Logger _logger;
private readonly TimeSpan _expectContinueTimeout;
private readonly ILogger _logger;

public Http11PoolProcessing(H1Logger logger, TimeSpan expectContinueTimeout)
public Http11PoolProcessing(TimeSpan expectContinueTimeout, ILogger? logger = null)
{
_logger = logger;
_expectContinueTimeout = expectContinueTimeout;
_logger = logger ?? NullLogger.Instance;
}

/// <summary>
Expand All @@ -43,23 +46,22 @@ public async ValueTask<bool> Process(Exchange exchange, RsBuffer buffer, Exchang

exchange.Metrics.RequestHeaderSending = ITimingProvider.Default.Instant();

_logger.Trace(exchange.Id, () => "Begin writing header");

var headerLength = exchange.Request.Header.WriteHttp11(
!exchange.Authority.Secure,
buffer, skipNonForwardableHeader: true, writeExtraHeaderField: true, requestClose: false);

exchange.Metrics.RequestHeaderLength = headerLength;

FluxzyLogEvents.LogRequestSending(_logger, exchange);

// Sending request header

await exchange.Connection.WriteStream!
.WriteAsync(buffer.Memory.Slice(0, headerLength), cancellationToken)
.ConfigureAwait(false);

_logger.Trace(exchange.Id, () => "Header sent");

exchange.Metrics.TotalSent += headerLength;
exchange.Metrics.RequestHeaderSent = ITimingProvider.Default.Instant();
exchange.Metrics.RequestHeaderLength = headerLength;

// Expect: 100-continue path — read any interim/final response from
// upstream before streaming the body, otherwise the body-copy below
Expand Down Expand Up @@ -132,7 +134,7 @@ await ForwardInterimToClient(exchange, 100, cancellationToken)
exchange.Metrics.RequestBodySent = exchange.Metrics.RequestHeaderSent;
}

_logger.Trace(exchange.Id, () => "Body sent");
FluxzyLogEvents.LogRequestSent(_logger, exchange, hasEarlyResponseHeader);

// Waiting for header block — unless the Expect pre-read already
// produced the final response header.
Expand Down Expand Up @@ -187,7 +189,10 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken)
exchange.Response.Header = new ResponseHeader(
headerContent, exchange.Authority.Secure, true);

_logger.TraceResponse(exchange);
exchange.Metrics.TotalReceived += headerBlockDetectResult.HeaderLength;
exchange.Metrics.ResponseHeaderLength = headerBlockDetectResult.HeaderLength;

FluxzyLogEvents.LogResponseHeaderReceived(_logger, exchange);

var shouldCloseConnection = exchange.Response.Header.ConnectionCloseRequest;

Expand All @@ -202,9 +207,7 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken)
exchange.Response.Body = Stream.Null;

exchange.ExchangeCompletionSource.TrySetResult(shouldCloseConnection || shouldClose);

_logger.Trace(exchange.Id, () => "No response body");


return true;
}

Expand Down Expand Up @@ -232,9 +235,6 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken)
);
}

exchange.Metrics.TotalReceived += headerBlockDetectResult.HeaderLength;
exchange.Metrics.ResponseHeaderLength = headerBlockDetectResult.HeaderLength;

ChunkedTransferReadStream? chunkedReadStream = null;

if (exchange.Response.Header.ChunkedBody) {
Expand All @@ -249,7 +249,6 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken)
exchange.Response.Body = new MetricsStream(bodyStream,
() => {
exchange.Metrics.ResponseBodyStart = ITimingProvider.Default.Instant();
_logger.Trace(exchange.Id, () => "First body bytes read");
},
(endConnection, length) => {
exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant();
Expand All @@ -259,13 +258,10 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken)
exchange.Response.Trailers = chunkedReadStream.Trailers;

exchange.ExchangeCompletionSource.TrySetResult(endConnection);
_logger.Trace(exchange.Id, () => $"Last body bytes end : {length} total bytes");
},
exception => {
exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant();
exchange.ExchangeCompletionSource.SetException(exception);

_logger.Trace(exchange.Id, () => $"Read error : {exception}");
},
shouldCloseConnection,
exchange.Response.Header.ContentLength >= 0 ? exchange.Response.Header.ContentLength : null,
Expand Down
Loading
Loading