IBKR: Zeitkontext einer Verbindung nachvollziehbar machen
ResolveExecutionTime liefert neben dem UTC-Zeitpunkt jetzt die Herkunft der verwendeten Zeitzone (gemeldet / angenommen / unbekannt / unlesbar). Bisher war im Nachhinein nicht unterscheidbar, ob ein Buchungszeitpunkt von TWS stammte oder eine Annahme war - genau der Fehler, der beim Umzug zwischen EU- und US-Host lautlos entsteht. IbkrConnection schreibt beim Verbinden einmalig Betriebszeitzone, Systemzeitzone und den Versatz zur TWS-Serverzeit ins Log; ab 5 s Abweichung gilt die Uhr des Hosts als verstellt. TWS-Setup-Checkliste um den Linux-Abschnitt ergaenzt (Betrieb und Umgebung unterscheiden sich, das Protokoll nicht). Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
@@ -41,6 +41,13 @@ internal sealed class IbkrConnection : DefaultEWrapper, IDisposable
|
||||
private PortfolioSlot? _portfolio;
|
||||
|
||||
private TaskCompletionSource<bool> _handshake = NewTcs();
|
||||
private TaskCompletionSource<long>? _serverTime;
|
||||
|
||||
/// <summary>Ab diesem Versatz zur TWS-Serverzeit gilt die Uhr des Hosts als verstellt.</summary>
|
||||
private const double MaxClockSkewSeconds = 5;
|
||||
|
||||
// Der Hinweis auf angenommene Zeitzonen soll einmal je Verbindung kommen, nicht je Abruf.
|
||||
private bool _zoneWarningIssued;
|
||||
private volatile bool _ready;
|
||||
private volatile bool _disposed;
|
||||
private int _nextRequestId = 1000;
|
||||
@@ -125,12 +132,104 @@ internal sealed class IbkrConnection : DefaultEWrapper, IDisposable
|
||||
}
|
||||
|
||||
_ready = true;
|
||||
_zoneWarningIssued = false;
|
||||
_socket.reqMarketDataType(_marketDataType);
|
||||
_logger.Info(LogModule,
|
||||
$"Verbunden mit {_host}:{_port} (Client {_clientId}), Konto {_account ?? "unbekannt"}.");
|
||||
|
||||
await LogTimeContextAsync(ct).ConfigureAwait(false);
|
||||
return true;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Schreibt den vollständigen Zeitkontext einer Verbindung ins Log: Betriebszeitzone,
|
||||
/// Systemzeitzone und den Versatz zur Uhr des TWS-Servers.
|
||||
///
|
||||
/// <para><b>Wozu:</b> Wir betreiben Instanzen in EU und US, künftig auf Linux-VMs. Weicht die
|
||||
/// Betriebszeitzone von der des Hosts ab oder geht die VM-Uhr nach, verschieben sich
|
||||
/// Buchungszeiten – ohne dass irgendwo ein Fehler auftaucht. Steht der Kontext am Anfang jeder
|
||||
/// Verbindung im Log, lässt sich das im Nachhinein an einer Zeile ablesen statt zu raten.</para>
|
||||
/// </summary>
|
||||
private async Task LogTimeContextAsync(CancellationToken ct)
|
||||
{
|
||||
var context = $"Zeitkontext: Betriebszeitzone {AppTimeZone.CurrentId}, " +
|
||||
$"Systemzeitzone {TimeZoneInfo.Local.Id}";
|
||||
|
||||
var pending = NewTcs<long>();
|
||||
_serverTime = pending;
|
||||
try
|
||||
{
|
||||
_socket.reqCurrentTime();
|
||||
|
||||
if (!await WaitAsync(pending.Task, TimeSpan.FromSeconds(5), ct).ConfigureAwait(false))
|
||||
{
|
||||
_logger.Info(LogModule, context + ", TWS-Serverzeit nicht ermittelbar.");
|
||||
return;
|
||||
}
|
||||
|
||||
var serverUtc = DateTimeOffset.FromUnixTimeSeconds(pending.Task.Result).UtcDateTime;
|
||||
var skew = (serverUtc - DateTime.UtcNow).TotalSeconds;
|
||||
|
||||
context += $", TWS-Serverzeit {serverUtc:yyyy-MM-dd HH:mm:ss}Z, " +
|
||||
$"Uhrenversatz {skew.ToString("+0.0;-0.0;0", CultureInfo.InvariantCulture)} s";
|
||||
|
||||
if (Math.Abs(skew) > MaxClockSkewSeconds)
|
||||
_logger.Warn(LogModule, context +
|
||||
" – die Uhren laufen auseinander. In virtuellen Maschinen ist das ein häufiger " +
|
||||
"Fehler; die Zeitsynchronisation des Hosts prüfen, sonst wandern Buchungszeiten.");
|
||||
else
|
||||
_logger.Info(LogModule, context + ".");
|
||||
}
|
||||
finally
|
||||
{
|
||||
_serverTime = null;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Fasst nach jedem Abruf zusammen, wie viele Zeitstempel TWS mit Zonenangabe gemeldet hat und
|
||||
/// wie viele über die Betriebszeitzone <b>angenommen</b> wurden. Die angenommenen sind die
|
||||
/// Stelle, an der ein Wechsel zwischen EU- und US-Host lautlos danebenliegt.
|
||||
/// </summary>
|
||||
private void LogTimeProvenance(IReadOnlyList<IbkrMapping.ExecutionTimestamp> stamps)
|
||||
{
|
||||
if (stamps.Count == 0) return;
|
||||
|
||||
var reported = stamps.Count(t => t.Source == IbkrMapping.ExecutionTimeSource.ReportedZone);
|
||||
var assumed = stamps.Count(t => t.IsAssumed);
|
||||
var unreadable = stamps.Count(t => t.Source == IbkrMapping.ExecutionTimeSource.Unparsable);
|
||||
|
||||
var zones = string.Join(", ", stamps.Where(t => t.ReportedZone is not null)
|
||||
.Select(t => t.ReportedZone!)
|
||||
.Distinct());
|
||||
|
||||
var text = $"Zeitstempel von {stamps.Count} Ausführung(en): {reported} mit gemeldeter Zone" +
|
||||
(zones.Length > 0 ? $" ({zones})" : "") +
|
||||
$", {assumed} über die Betriebszeitzone {AppTimeZone.CurrentId}" +
|
||||
(unreadable > 0 ? $", {unreadable} unlesbar" : "") + ".";
|
||||
|
||||
_logger.Info(LogModule, text);
|
||||
|
||||
// Unlesbare Zeitstempel sind immer ein Defekt – die Ausführung landet sonst auf DateTime.MinValue.
|
||||
if (unreadable > 0)
|
||||
_logger.Warn(LogModule,
|
||||
$"{unreadable} Ausführung(en) mit unlesbarem Zeitstempel – das Format von TWS hat sich " +
|
||||
"vermutlich geändert. IbkrMapping.ResolveExecutionTime prüfen.");
|
||||
|
||||
// Angenommene Zonen sind nur dann heikel, wenn Betriebs- und Systemzeitzone auseinandergehen:
|
||||
// dann ist nicht mehr offensichtlich, gegen welche Uhr TWS die Zeit gemeldet hat.
|
||||
if (assumed > 0 && !_zoneWarningIssued &&
|
||||
!string.Equals(AppTimeZone.CurrentId, TimeZoneInfo.Local.Id, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
_zoneWarningIssued = true;
|
||||
_logger.Warn(LogModule,
|
||||
$"{assumed} Zeitstempel ohne Zonenangabe wurden gegen die Betriebszeitzone " +
|
||||
$"{AppTimeZone.CurrentId} gerechnet, das System läuft aber auf {TimeZoneInfo.Local.Id}. " +
|
||||
"Stimmt Trading.ApplicationTimeZoneId nicht mit der Zeitzone des TWS-Hosts überein, " +
|
||||
"liegen die Buchungszeiten daneben. Einmal gegen TWS gegenprüfen.");
|
||||
}
|
||||
}
|
||||
|
||||
private void StartReader()
|
||||
{
|
||||
var reader = new EReader(_socket, _signal);
|
||||
@@ -327,6 +426,8 @@ internal sealed class IbkrConnection : DefaultEWrapper, IDisposable
|
||||
|
||||
await Task.Delay(TimeSpan.FromSeconds(1), ct).ConfigureAwait(false);
|
||||
|
||||
LogTimeProvenance(slot.Timestamps);
|
||||
|
||||
return slot.Items
|
||||
.Select(e => slot.Commissions.TryGetValue(e.ExecId, out var c)
|
||||
? e with { Commission = c.Amount, CommissionCurrency = c.Currency }
|
||||
@@ -452,14 +553,20 @@ internal sealed class IbkrConnection : DefaultEWrapper, IDisposable
|
||||
|
||||
public override void accountDownloadEnd(string account) => _portfolio?.Complete();
|
||||
|
||||
/// <summary>Antwort auf <c>reqCurrentTime</c> – Sekunden seit Epoch, Basis des Uhrenvergleichs.</summary>
|
||||
public override void currentTime(long time) => _serverTime?.TrySetResult(time);
|
||||
|
||||
public override void execDetails(int reqId, Contract contract, Execution execution)
|
||||
{
|
||||
if (!_executions.TryGetValue(reqId, out var slot)) return;
|
||||
|
||||
var stamp = IbkrMapping.ResolveExecutionTime(execution.Time, AppTimeZone.Current);
|
||||
slot.Timestamps.Add(stamp);
|
||||
|
||||
slot.Items.Add(new BrokerExecution
|
||||
{
|
||||
ExecId = execution.ExecId,
|
||||
Time = IbkrMapping.ParseExecutionTime(execution.Time, AppTimeZone.Current) ?? DateTime.MinValue,
|
||||
Time = stamp.Utc ?? DateTime.MinValue,
|
||||
Symbol = contract.Symbol,
|
||||
SecType = contract.SecType,
|
||||
Side = IbkrMapping.ParseSide(execution.Side),
|
||||
@@ -569,7 +676,9 @@ internal sealed class IbkrConnection : DefaultEWrapper, IDisposable
|
||||
? parsed
|
||||
: 0m;
|
||||
|
||||
private static TaskCompletionSource<bool> NewTcs() =>
|
||||
private static TaskCompletionSource<bool> NewTcs() => NewTcs<bool>();
|
||||
|
||||
private static TaskCompletionSource<T> NewTcs<T>() =>
|
||||
new(TaskCreationOptions.RunContinuationsAsynchronously);
|
||||
|
||||
private static async Task<bool> WaitAsync(Task task, TimeSpan timeout, CancellationToken ct)
|
||||
@@ -637,5 +746,9 @@ internal sealed class IbkrConnection : DefaultEWrapper, IDisposable
|
||||
{
|
||||
public readonly List<BrokerExecution> Items = new();
|
||||
public readonly ConcurrentDictionary<string, (decimal Amount, string Currency)> Commissions = new();
|
||||
|
||||
// Herkunft der Zeitangaben, damit nach dem Abruf zusammengefasst werden kann, wie viele
|
||||
// Zeitpunkte TWS gemeldet und wie viele wir angenommen haben.
|
||||
public readonly List<IbkrMapping.ExecutionTimestamp> Timestamps = new();
|
||||
}
|
||||
}
|
||||
|
||||
@@ -89,6 +89,43 @@ internal static class IbkrMapping
|
||||
(decimal)(ask > 0 ? ask : price));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Woher die Zeitzone einer Ausführung stammt. Ohne diese Angabe lässt sich im Nachhinein
|
||||
/// nicht mehr feststellen, ob ein Buchungszeitpunkt belastbar ist oder auf einer Annahme beruht –
|
||||
/// und genau das ist der Fehler, der bei einem Umzug zwischen EU- und US-Host lautlos entsteht.
|
||||
/// </summary>
|
||||
public enum ExecutionTimeSource
|
||||
{
|
||||
/// <summary>TWS hat eine Zone gemeldet und sie war auflösbar – der verlässliche Fall.</summary>
|
||||
ReportedZone,
|
||||
|
||||
/// <summary>TWS meldete keine Zone; es galt die Betriebszeitzone der Instanz.</summary>
|
||||
FallbackZone,
|
||||
|
||||
/// <summary>TWS meldete eine Zone, die dieses System nicht kennt; es galt die Betriebszeitzone.</summary>
|
||||
UnknownZoneFallback,
|
||||
|
||||
/// <summary>Der Zeitstempel war nicht lesbar.</summary>
|
||||
Unparsable
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Ergebnis der Zeitauflösung samt Herkunft – die Grundlage für die Beobachtung im Log.
|
||||
/// </summary>
|
||||
/// <param name="Utc">Zeitpunkt in UTC, oder <c>null</c> wenn nicht lesbar.</param>
|
||||
/// <param name="Source">Woher die verwendete Zone stammt.</param>
|
||||
/// <param name="ZoneUsed">Die tatsächlich zur Umrechnung benutzte Zone.</param>
|
||||
/// <param name="ReportedZone">Was TWS gemeldet hat, oder <c>null</c> bei fehlender Angabe.</param>
|
||||
public readonly record struct ExecutionTimestamp(
|
||||
DateTime? Utc,
|
||||
ExecutionTimeSource Source,
|
||||
string ZoneUsed,
|
||||
string? ReportedZone)
|
||||
{
|
||||
/// <summary>true, wenn der Zeitpunkt auf einer Annahme statt auf einer Meldung von TWS beruht.</summary>
|
||||
public bool IsAssumed => Source is ExecutionTimeSource.FallbackZone or ExecutionTimeSource.UnknownZoneFallback;
|
||||
}
|
||||
|
||||
/// <summary>Ausführungsseite laut TWS: "BOT" = gekauft, "SLD" = verkauft.</summary>
|
||||
public static TradeSide ParseSide(string side) =>
|
||||
side.Trim().ToUpperInvariant() is "SLD" or "SELL" ? TradeSide.Sell : TradeSide.Buy;
|
||||
@@ -109,32 +146,48 @@ internal static class IbkrMapping
|
||||
/// <param name="fallbackZone">
|
||||
/// Zeitzone für Meldungen ohne Zonenangabe – die Betriebszeitzone (<c>AppTimeZone.Current</c>).
|
||||
/// </param>
|
||||
public static DateTime? ParseExecutionTime(string? raw, TimeZoneInfo fallbackZone)
|
||||
public static DateTime? ParseExecutionTime(string? raw, TimeZoneInfo fallbackZone) =>
|
||||
ResolveExecutionTime(raw, fallbackZone).Utc;
|
||||
|
||||
/// <summary>
|
||||
/// Wie <see cref="ParseExecutionTime"/>, liefert aber zusätzlich die <b>Herkunft</b> der
|
||||
/// verwendeten Zeitzone. Nur damit lässt sich im Nachhinein unterscheiden, ob ein
|
||||
/// Buchungszeitpunkt von TWS gemeldet oder von uns angenommen wurde.
|
||||
/// </summary>
|
||||
public static ExecutionTimestamp ResolveExecutionTime(string? raw, TimeZoneInfo fallbackZone)
|
||||
{
|
||||
if (string.IsNullOrWhiteSpace(raw)) return null;
|
||||
if (string.IsNullOrWhiteSpace(raw))
|
||||
return new ExecutionTimestamp(null, ExecutionTimeSource.Unparsable, fallbackZone.Id, null);
|
||||
|
||||
// Datum und Uhrzeit trennen TWS je nach Aufruf per Leerzeichen oder Bindestrich
|
||||
// ("20260804-17:52:56" ist das Format, das auch der Anfragefilter nutzt).
|
||||
var parts = raw.Replace('-', ' ')
|
||||
.Split(' ', StringSplitOptions.RemoveEmptyEntries | StringSplitOptions.TrimEntries);
|
||||
if (parts.Length < 2) return null;
|
||||
|
||||
if (!DateTime.TryParseExact($"{parts[0]} {parts[1]}", "yyyyMMdd HH:mm:ss",
|
||||
if (parts.Length < 2 ||
|
||||
!DateTime.TryParseExact($"{parts[0]} {parts[1]}", "yyyyMMdd HH:mm:ss",
|
||||
CultureInfo.InvariantCulture, DateTimeStyles.None, out var local))
|
||||
return null;
|
||||
return new ExecutionTimestamp(null, ExecutionTimeSource.Unparsable, fallbackZone.Id, null);
|
||||
|
||||
// Dritter Teil, falls vorhanden, ist die Zeitzone der Börse.
|
||||
var zone = parts.Length >= 3 ? ResolveZone(parts[2]) ?? fallbackZone : fallbackZone;
|
||||
var reported = parts.Length >= 3 ? parts[2] : null;
|
||||
var resolved = reported is null ? null : ResolveZone(reported);
|
||||
|
||||
var zone = resolved ?? fallbackZone;
|
||||
var source = reported is null ? ExecutionTimeSource.FallbackZone
|
||||
: resolved is null ? ExecutionTimeSource.UnknownZoneFallback
|
||||
: ExecutionTimeSource.ReportedZone;
|
||||
|
||||
local = DateTime.SpecifyKind(local, DateTimeKind.Unspecified);
|
||||
|
||||
// Bei der Zeitumstellung kann die Ortszeit ungültig (Vorstellen) oder doppelt (Zurückstellen)
|
||||
// sein. ConvertTimeToUtc würde bei ungültigen Werten werfen – eine Ausführung darf daran
|
||||
// nicht verlorengehen, deshalb der ausdrückliche Versatz.
|
||||
if (zone.IsInvalidTime(local))
|
||||
return DateTime.SpecifyKind(local - zone.BaseUtcOffset, DateTimeKind.Utc);
|
||||
var utc = zone.IsInvalidTime(local)
|
||||
? DateTime.SpecifyKind(local - zone.BaseUtcOffset, DateTimeKind.Utc)
|
||||
: TimeZoneInfo.ConvertTimeToUtc(local, zone);
|
||||
|
||||
return TimeZoneInfo.ConvertTimeToUtc(local, zone);
|
||||
return new ExecutionTimestamp(utc, source, zone.Id, reported);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
Reference in New Issue
Block a user