Auth logging updates

SVSim.EmulatedEntrypoint/Middlewares/SessionidMappingMiddleware.cs

@@ -10,21 +10,55 @@ namespace SVSim.EmulatedEntrypoint.Middlewares;
 public class SessionidMappingMiddleware : IMiddleware
 {
     private readonly ShadowverseSessionService _shadowverseSessionService;
+    private readonly ILogger<SessionidMappingMiddleware> _logger;
 
-    public SessionidMappingMiddleware(ShadowverseSessionService shadowverseSessionService)
+    public SessionidMappingMiddleware(
+        ShadowverseSessionService shadowverseSessionService,
+        ILogger<SessionidMappingMiddleware> logger)
     {
         _shadowverseSessionService = shadowverseSessionService;
+        _logger = logger;
     }
 
     public async Task InvokeAsync(HttpContext context, RequestDelegate next)
     {
-        bool hasSessionId = context.Request.Headers.TryGetValue(NetworkConstants.UdidHeaderName, out var udid);
+        // NOTE: the bool names below were historically inverted (hasSessionId held UDID and
-        bool hasUdid = context.Request.Headers.TryGetValue(NetworkConstants.SessionIdHeaderName, out var sid);
+        // vice versa). Variable names corrected in-place; behavior unchanged.
-        if (hasSessionId && hasUdid)
+        bool hasUdid = context.Request.Headers.TryGetValue(NetworkConstants.UdidHeaderName, out var udid);
+        bool hasSid = context.Request.Headers.TryGetValue(NetworkConstants.SessionIdHeaderName, out var sid);
+
+        if (hasUdid && hasSid)
         {
-            _shadowverseSessionService.StoreUdidForSessionId(sid.FirstOrDefault(), Guid.Parse(Encryption.Decode(udid.FirstOrDefault())));
+            string? sidValue = sid.FirstOrDefault();
+            string? encodedUdid = udid.FirstOrDefault();
+            try
+            {
+                string? decoded = Encryption.Decode(encodedUdid);
+                Guid parsedUdid = Guid.Parse(decoded);
+                _shadowverseSessionService.StoreUdidForSessionId(sidValue, parsedUdid);
+                _logger.LogDebug(
+                    "Stored SID→UDID mapping for {Path} (sid={Sid}, udid={Udid}).",
+                    context.Request.Path, sidValue, parsedUdid);
+            }
+            catch (Exception ex)
+            {
+                _logger.LogError(ex,
+                    "Failed to decode/parse UDID header for {Path} (sid={Sid}, encodedUdidLen={EncodedUdidLen}). " +
+                    "Downstream translation will fall back to Guid.Empty and almost certainly fail msgpack decrypt.",
+                    context.Request.Path, sidValue, encodedUdid?.Length ?? 0);
+            }
+        }
+        else if (hasUdid ^ hasSid)
+        {
+            // Only one of the two headers present — usually a client bug or a test that forgot
+            // to set both. The translation middleware will then fall back to Guid.Empty and
+            // surface as a generic msgpack/decrypt error, so warn here where the cause is clear.
+            _logger.LogWarning(
+                "Only one of UDID/SID headers present for {Path} (hasUdid={HasUdid}, hasSid={HasSid}). " +
+                "Translation will use Guid.Empty as the encryption key.",
+                context.Request.Path, hasUdid, hasSid);
         }
 
         await next.Invoke(context);
     }
-}
+}

SVSim.EmulatedEntrypoint/Middlewares/ShadowverseTranslationMiddleware.cs

@@ -25,6 +25,7 @@ public class ShadowverseTranslationMiddleware : IMiddleware
 {
     private readonly IActionDescriptorCollectionProvider _actionDescriptorCollectionProvider;
     private readonly ShadowverseSessionService _sessionService;
+    private readonly ILogger<ShadowverseTranslationMiddleware> _logger;
 
     // Serialization policy MUST match what AddJsonOptions configured on the controllers, or the
     // model binder won't find the snake_case keys we write into the synthetic request body and
@@ -36,10 +37,14 @@ public class ShadowverseTranslationMiddleware : IMiddleware
         DefaultIgnoreCondition = JsonIgnoreCondition.WhenWritingNull
     };
 
-    public ShadowverseTranslationMiddleware(IActionDescriptorCollectionProvider actionDescriptorCollectionProvider, ShadowverseSessionService sessionService)
+    public ShadowverseTranslationMiddleware(
+        IActionDescriptorCollectionProvider actionDescriptorCollectionProvider,
+        ShadowverseSessionService sessionService,
+        ILogger<ShadowverseTranslationMiddleware> logger)
     {
         _actionDescriptorCollectionProvider = actionDescriptorCollectionProvider;
         _sessionService = sessionService;
+        _logger = logger;
     }
 
     public async Task InvokeAsync(HttpContext context, RequestDelegate next)
@@ -54,25 +59,65 @@ public class ShadowverseTranslationMiddleware : IMiddleware
             await next.Invoke(context);
             return;
         }
-        
+
         // Replace response body stream to re-access it.
         using MemoryStream tempResponseBody = new MemoryStream();
         Stream originalResponsebody = context.Response.Body;
         context.Response.Body = tempResponseBody;
-        
+
         // Pull out the request bytes into a stream
         using MemoryStream requestBytesStream = new MemoryStream();
         await context.Request.Body.CopyToAsync(requestBytesStream);
         byte[] requestBytes = requestBytesStream.ToArray();
-        
+
         // Get encryption values for this request
         string sid = context.Request.Headers[NetworkConstants.SessionIdHeaderName];
-        string udid = _sessionService.GetUdidFromSessionId(sid).GetValueOrDefault().ToString();
+        Guid? mappedUdid = _sessionService.GetUdidFromSessionId(sid);
-        
+        if (mappedUdid is null)
+        {
+            // Per design (2026-05-25): warn and continue. Decrypt will fail with Guid.Empty as
+            // the AES key, surfacing as a msgpack/decrypt error below — but now the *root cause*
+            // (the SID wasn't in our dict, likely because the prior request didn't include a UDID
+            // header or the server was restarted between handshake and this call) is in the log.
+            _logger.LogWarning(
+                "No UDID mapping for SID on {Path} (sid={Sid}). Falling back to Guid.Empty — the following decrypt/msgpack error is almost certainly caused by this.",
+                path, sid);
+        }
+        string udid = mappedUdid.GetValueOrDefault().ToString();
+
         // Decrypt incoming data.
-        requestBytes = Encryption.Decrypt(requestBytes, udid);
+        byte[] decryptedBytes;
+        try
+        {
+            decryptedBytes = Encryption.Decrypt(requestBytes, udid);
+        }
+        catch (Exception ex)
+        {
+            _logger.LogError(ex,
+                "Decrypt failed for {Path} (udid={Udid}, encryptedLen={EncryptedLen}). " +
+                "If udid is all-zero, see the preceding 'No UDID mapping' warning.",
+                path, udid, requestBytes.Length);
+            throw;
+        }
+
         Type requestType = endpointDescriptor.Parameters.FirstOrDefault().ParameterType;
-        object? data = MessagePackSerializer.Deserialize(requestType, requestBytes);
+        object? data;
+        try
+        {
+            data = MessagePackSerializer.Deserialize(requestType, decryptedBytes);
+        }
+        catch (Exception ex)
+        {
+            // The most common cause is a Guid.Empty decrypt above producing garbage bytes — but
+            // it can also be a genuine schema mismatch (DTO missing [Key], wrong types, etc.),
+            // so include the first few bytes for triage.
+            string bytePrefix = Convert.ToHexString(decryptedBytes.AsSpan(0, Math.Min(16, decryptedBytes.Length)));
+            _logger.LogError(ex,
+                "Msgpack deserialize failed for {Path} into {RequestType} (udid={Udid}, decryptedLen={DecryptedLen}, firstBytes={BytePrefix}). " +
+                "If decrypted bytes look like noise, the SID→UDID mapping was missing (see warnings above).",
+                path, requestType.Name, udid, decryptedBytes.Length, bytePrefix);
+            throw;
+        }
         // Re-serialize via System.Text.Json with the SAME options the controllers use, so the
         // model binder sees snake_case keys it can match. Using JsonConvert here writes the
         // CLR property names (PascalCase) and every property silently binds to default → 400.
@@ -80,7 +125,7 @@ public class ShadowverseTranslationMiddleware : IMiddleware
         StringContent newStream = new StringContent(json, Encoding.UTF8, "application/json");
         context.Request.Body = newStream.ReadAsStream();
         context.Request.Headers.ContentType = new StringValues("application/json");
-        
+
         await next.Invoke(context);
 
         Viewer? viewer = context.GetViewer();
@@ -130,8 +175,19 @@ public class ShadowverseTranslationMiddleware : IMiddleware
         // primitive tree under Data — emitting only the keys present in the dictionary.
         var msgPackOptions = MessagePackSerializerOptions.Standard
             .WithResolver(ContractlessStandardResolver.Instance);
-        byte[] packedData = MessagePackSerializer.Serialize(wrappedResponseData, msgPackOptions);
+        byte[] packedData;
-        packedData = Encryption.Encrypt(packedData, udid);
+        try
+        {
+            packedData = MessagePackSerializer.Serialize(wrappedResponseData, msgPackOptions);
+            packedData = Encryption.Encrypt(packedData, udid);
+        }
+        catch (Exception ex)
+        {
+            _logger.LogError(ex,
+                "Response msgpack/encrypt failed for {Path} (viewerId={ViewerId}, udid={Udid}).",
+                path, viewer?.Id, udid);
+            throw;
+        }
         await originalResponsebody.WriteAsync(Encoding.UTF8.GetBytes(Convert.ToBase64String(packedData)));
         context.Response.Body = originalResponsebody;
     }
@@ -160,4 +216,4 @@ public class ShadowverseTranslationMiddleware : IMiddleware
             _ => token.ToString()
         };
     }
-}
+}

SVSim.EmulatedEntrypoint/Security/SteamSessionAuthentication/SteamSessionAuthenticationHandler.cs

@@ -34,6 +34,7 @@ public class SteamSessionAuthenticationHandler : AuthenticationHandler<SteamAuth
 
     protected async override Task<AuthenticateResult> HandleAuthenticateAsync()
     {
+        string path = Request.Path;
         byte[] requestBytes;
         try
         {
@@ -51,6 +52,7 @@ public class SteamSessionAuthenticationHandler : AuthenticationHandler<SteamAuth
         }
         catch (Exception e)
         {
+            Logger.LogWarning(e, "Auth: failed to read request body on {Path}.", path);
             return AuthenticateResult.Fail("Failed to read request body.");
         }
 
@@ -61,13 +63,21 @@ public class SteamSessionAuthenticationHandler : AuthenticationHandler<SteamAuth
         {
             requestJson = JsonSerializer.Deserialize<BaseRequest>(requestString, RequestJsonOptions);
         }
-        catch (JsonException)
+        catch (JsonException ex)
         {
+            Logger.LogWarning(ex,
+                "Auth: failed to JSON-parse request body on {Path} (bodyLen={BodyLen}). " +
+                "Translation middleware should have rewritten this to JSON — if it didn't, the request bypassed translation (non-Unity UA?).",
+                path, requestBytes.Length);
             return AuthenticateResult.Fail("Invalid request body.");
         }
 
         if (requestJson is null || string.IsNullOrEmpty(requestJson.SteamSessionTicket))
         {
+            Logger.LogWarning(
+                "Auth: request body missing steam_session_ticket on {Path} (bodyLen={BodyLen}, hasViewerId={HasViewerId}, steamId={SteamId}).",
+                path, requestBytes.Length,
+                !string.IsNullOrEmpty(requestJson?.ViewerId), requestJson?.SteamId ?? 0);
             return AuthenticateResult.Fail("Invalid request body.");
         }
 
@@ -75,6 +85,10 @@ public class SteamSessionAuthenticationHandler : AuthenticationHandler<SteamAuth
         bool sessionIsValid = _sessionService.IsTicketValidForUser(requestJson.SteamSessionTicket, requestJson.SteamId);
         if (!sessionIsValid)
         {
+            Logger.LogWarning(
+                "Auth: Steam ticket rejected on {Path} for steamId={SteamId} (ticketLen={TicketLen}). " +
+                "See SteamSessionService logs above for the underlying Steam reason (BeginAuthSession failure, duplicate, etc.).",
+                path, requestJson.SteamId, requestJson.SteamSessionTicket.Length);
             return AuthenticateResult.Fail("Invalid ticket.");
         }
 
@@ -83,6 +97,12 @@ public class SteamSessionAuthenticationHandler : AuthenticationHandler<SteamAuth
 
         if (viewer is null)
         {
+            // Most common dev-loop cause: DB was re-bootstrapped and this Steam account hasn't
+            // been re-linked yet. Log loudly with the steam_id so it's obvious what to add back.
+            Logger.LogWarning(
+                "Auth: no viewer linked to steamId={SteamId} on {Path}. " +
+                "Likely you re-bootstrapped the DB without re-linking this Steam account.",
+                requestJson.SteamId, path);
             return AuthenticateResult.Fail("User not found.");
         }