Horde server - issues with azure storage back end

Development Pipeline & Plugins
, ,
1

My horde server instance will not upload logs to a configured azure blob storage account upon the log leaving the server cache. I can force the server to upload a log blob by posting to the /api/v1/logs/{logId}/blobs endpoint, which does make it to azure.

When attempting to load a log that has left the cache this way I get an error saying that the server was unable to read the log from azure, and the page comes up empty:

EpicGames.Horde.Storage.StorageException: Unable to read 67ea59e0112c7c768b1dd791/d876e6e6bcf24c619e1a9b723f502f47_241#pkt=9964,176: Unable to read logs/67ea59e0112c7c768b1dd791/d876e6e6bcf24c619e1a9b723f502f47_241.blob from Azure

Status: 404 (The specified blob does not exist.)

Here is my storage plugin configuration from my globals.json:

"storage": { "backends": [ { "id": "azure-backend", "type": "Azure", "azureConnectionString": <Secure value removed>, "azureContainerName": "artifacts" } ], "namespaces": [ { "id": "default", "backend": "azure-backend" }, { "id": "horde-artifacts", "prefix": "Artifacts/", "backend": "azure-backend" }, { "id": "horde-perforce", "prefix": "Perforce/", "backend": "azure-backend" }, { "id": "horde-logs", "prefix": "Logs/", "backend": "azure-backend" }, { "id": "horde-tools", "prefix": "Tools/", "backend": "azure-backend" } ] },

2

Steps to Reproduce
Using Horde server 5.5.4 configure it to use azure blob storage as the backend for the horde-logs namespace.

Run a conform on a connected node to generate a log

Observe that once the job completes and leaves the cache the log is not uploaded to azure storage, and reloading the page will produce an empty log

3

Hey there Nicolas,

Do you have the horde server logs during the job completion, in order to see what’s occurring during that window when the logs should be pushed to your storage backend? I’m curious if there’s some kind of auth issue occurring, wherein your manual REST api invocation is working.

It’s also worth inquiring: local storage will work, it’s only when pushing to Azure.

Kind regards,

Julian

4

Hey Julian, thanks for the response!

I’m having some trouble parsing these logs as the server is pretty noisy, but I’m seeing this around the logs in several places:

[21:24:46 inf] Request starting HTTP/2 POST https://inx-horde-dev.inxile.net/Horde.HordeRpc/UploadTelemetry - application/grpc null

[21:24:46 inf] Failed to validate the token.

Microsoft.IdentityModel.Tokens.SecurityTokenSignatureKeyNotFoundException: IDX10503: Signature validation failed. Token does not have a kid. Keys tried: ‘[PII of type ‘System.Text.StringBuilder’ is hidden. For more details, see Search - Microsoft Bing]’. Number of keys in TokenValidationParameters: ‘0’.

Number of keys in Configuration: ‘10’.

Exceptions caught:

‘[PII of type ‘System.Text.StringBuilder’ is hidden. For more details, see Search - Microsoft Bing]’.

token: ‘[PII of type ‘System.IdentityModel.Tokens.Jwt.JwtSecurityToken’ is hidden. For more details, see Search - Microsoft Bing]’. See SecurityTokenInvalidSignatureException · AzureAD/azure-activedirectory-identitymodel-extensions-for-dotnet Wiki · GitHub for details.

at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateSignature(String token, JwtSecurityToken jwtToken, TokenValidationParameters validationParameters, BaseConfiguration configuration)

at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateJWS(String token, TokenValidationParameters validationParameters, BaseConfiguration currentConfiguration, SecurityToken& signatureValidatedToken, ExceptionDispatchInfo& exceptionThrown)

--- End of stack trace from previous location ---

at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateToken(String token, JwtSecurityToken outerToken, TokenValidationParameters validationParameters, SecurityToken& signatureValidatedToken)

at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateToken(String token, TokenValidationParameters validationParameters, SecurityToken& validatedToken)

at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateTokenAsync(String token, TokenValidationParameters validationParameters)

[21:24:46 inf] ExternalJwt was not authenticated. Failure message: IDX10503: Signature validation failed. Token does not have a kid. Keys tried: ‘[PII of type ‘System.Text.StringBuilder’ is hidden. For more details, see Search - Microsoft Bing]’. Number of keys in TokenValidationParameters: ‘0’.

Number of keys in Configuration: ‘10’.

Exceptions caught:

‘[PII of type ‘System.Text.StringBuilder’ is hidden. For more details, see Search - Microsoft Bing]’.

token: ‘[PII of type ‘System.IdentityModel.Tokens.Jwt.JwtSecurityToken’ is hidden. For more details, see Search - Microsoft Bing]’. See SecurityTokenInvalidSignatureException · AzureAD/azure-activedirectory-identitymodel-extensions-for-dotnet Wiki · GitHub for details.

[21:24:46 inf] Executing endpoint ‘gRPC - /Horde.HordeRpc/UploadTelemetry’

If that’s not related are there any log lines in particular I should be looking for?

5

Hey there Nicolas,

Thanks for this. Yeah I do fundamentally suspect that there’s an auth issue going on here (that tends to be the case when a manual rest API invocation “works” whilst system level API invocations don’t). Now this specific endpoint doesn’t look explicitly related to this, but it does appear to occur at the end of the job which could be causing some issues here.

Just reviewing the source I’ve tracked down a couple of useful entry points that you could try debugging:

  • UpdateLogAsync/UpdateLogTailAsync (ServerLogger.cs)
    • We will see (from the agent logs) "Writing log data: "
      • This is done through the GRPC; so could be similar scenario to the above; but it’s from agent back to the horde server
  • AddRefAsync (StorageService.cs)
    • “Created blob {} at LOCATOR/{}”
      • LOCATOR is the blob ID we would see surface in our HordeServer/log/LOCATOR
      • This initiates the GetLeaseLogAsync controller endpoint
        • This performs a redirection as needed
    • “Added ref horde-logs:” is of particular interest. If we can check out in and around there within the server log to see if the GRPC message was received properly from the agent

So if we can see what’s going on around the “Created blob” lines on server log, or around the “writing log data:” lines on agent log, we may see whether there is some auth issue occurring from the server->storage backend.

If you use local storage instead of azure (as your backend), do you still see this, and do blobs properly get pushed up? Just trying to establish some ground truth.

Appreciate the collaboration on this ahead of time. Sometimes these issues can require a bit of back and forth to track down!

Kind regards,

Julian

6

Looking at the agent logs was the ticket, I’m seeing this when trying to upload a log blob to storage:

2025-05-06 11:46:39.194 -07:00 [WRN] Unable to flush data to server (log 681a55c08456fa71c979fc9c, offset 40431) EpicGames.Horde.Storage.StorageException: Unable to upload data to redirected URL <Secure URL removed>. Status:BadRequest Reason:An HTTP header that's mandatory for this request is not specified. Response:<?xml version="1.0" encoding="utf-8"?> <Error><Code>MissingRequiredHeader</Code><Message>An HTTP header that&apos;s mandatory for this request is not specified. RequestId:0eb27bb7-a01e-0001-5bb7-bef661000000 Time:2025-05-06T18:46:39.1753500Z</Message><HeaderName>x-ms-blob-type</HeaderName></Error> at EpicGames.Horde.Storage.Backends.HttpStorageBackend.WriteBlobAsync(Nullable1 locator, Stream stream, IReadOnlyCollection1 imports, String prefix, CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Backends\HttpStorageBackend.cs:line 162 at EpicGames.Horde.Storage.Bundles.V2.BundleWriter.PendingBundleHandle.FlushAsync(CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Bundles\V2\BundleWriter.cs:line 214 at EpicGames.Horde.Storage.Bundles.V2.BundleWriter.FlushAsync(CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Bundles\V2\BundleWriter.cs:line 314 at EpicGames.Horde.Logs.LogBuilder.FlushAsync(IBlobWriter writer, Boolean complete, CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Logs\LogNode.cs:line 300 at EpicGames.Horde.Logs.ServerLogger.WriteOutputAsync(ReadOnlyMemory1 data, Boolean flush, CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Logs\ServerLogger.cs:line 351
at EpicGames.Horde.Logs.ServerLogger.RunDataWriterAsync() in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Logs\ServerLogger.cs:line 223
2025-05-06 11:46:39.196 -07:00 [INF] Disposing json log task
2025-05-06 11:46:39.196 -07:00 [INF] Cancelling long poll from client side (complete)
2025-05-06 11:46:39.237 -07:00 [INF] Log 681a55c08456fa71c979fc9c tail next = -1
2025-05-06 11:46:39.237 -07:00 [INF] Finishing log tail task
2025-05-06 11:46:39.349 -07:00 [ERR] Unhandled exception while executing lease 681a55c08456fa71c979fc9b: Unable to upload data to redirected URL . Status:BadRequest Reason:An HTTP header that’s mandatory for this request is not specified. Response:<?xml version="1.0" encoding="utf-8"?>
MissingRequiredHeaderAn HTTP header that's mandatory for this request is not specified.
RequestId:0eb27c49-a01e-0001-63b7-bef661000000
Time:2025-05-06T18:46:39.3296731Zx-ms-blob-type
EpicGames.Horde.Storage.StorageException: Unable to upload data to redirected URL . Status:BadRequest Reason:An HTTP header that’s mandatory for this request is not specified. Response:<?xml version="1.0" encoding="utf-8"?>
MissingRequiredHeaderAn HTTP header that's mandatory for this request is not specified.
RequestId:0eb27c49-a01e-0001-63b7-bef661000000
Time:2025-05-06T18:46:39.3296731Zx-ms-blob-type
at EpicGames.Horde.Storage.Backends.HttpStorageBackend.WriteBlobAsync(Nullable1 locator, Stream stream, IReadOnlyCollection1 imports, String prefix, CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Backends\HttpStorageBackend.cs:line 162
at EpicGames.Horde.Storage.Bundles.V2.BundleWriter.PendingBundleHandle.FlushAsync(CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Bundles\V2\BundleWriter.cs:line 214
at EpicGames.Horde.Storage.Bundles.V2.BundleWriter.FlushAsync(CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Bundles\V2\BundleWriter.cs:line 314
at EpicGames.Horde.Storage.Bundles.V2.BundleWriter.DisposeAsync() in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Storage\Bundles\V2\BundleWriter.cs:line 307
at EpicGames.Horde.Logs.ServerLogger.DisposeAsync() in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Shared\EpicGames.Horde\Logs\ServerLogger.cs:line 123
at HordeAgent.Leases.Handlers.ConformHandler.ExecuteAsync(ISession session, LeaseId leaseId, ConformTask conformTask, Tracer tracer, ILogger localLogger, CancellationToken cancellationToken) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Horde\HordeAgent\Leases\Handlers\ConformHandler.cs:line 46
at HordeAgent.Leases.LeaseHandler.HandleLeasePayloadAsync(ISession session, Tracer tracer, LeaseLoggerFactory leaseLoggerFactory) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Horde\HordeAgent\Leases\LeaseHandler.cs:line 167
at HordeAgent.Leases.LeaseHandler.HandleLeaseAsync(ISession session, Tracer tracer, ILogger logger, LeaseLoggerFactory leaseLoggerFactory) in D:\P4\Epic\Release-5.5\Engine\Source\Programs\Horde\HordeAgent\Leases\LeaseHandler.cs:line 118
2025-05-06 11:46:39.351 -07:00 [INF] Transitioning lease 681a55c08456fa71c979fc9b to “Completed”, outcome=“Failed”` Also to answer your question about local storage, that backend seems to work completely fine so it’s likely this missing http header error

7

OK we are making some progress here :slight_smile: Just to confirm, guessing the redirected URL is going to be the Azure endpoint. I don’t see anywhere that we would explicitly add the header here. We don’t use Azure internally (AWS), but if there were systemic issues here I’d expect some other notes in EPS (which I haven’t found). What’s further interesting here is if you manually invoke the rest API, it seemingly works…

One thing I have seen while looking at the issue on forums, is sometimes changing the url suffix works?

I’ll keep looking on my send to see if I can make further sense of this.

Julian

8

Hey Julian,

Yeah that URL is the azure blob storage URL, it uses the blob.core.windows.net.

Looks like I was able to fix the issue by changing the code after line 157 in HttpStorageBackend.cs:

Vanilla:

using HttpClient uploadRedirectClient = _createUploadRedirectClient(); using HttpResponseMessage uploadResponse = await uploadRedirectClient.PutAsync(redirectResponse.UploadUrl, streamContent, cancellationToken); if (!uploadResponse.IsSuccessStatusCode) { string body = await uploadResponse.Content.ReadAsStringAsync(cancellationToken); throw new StorageException($"Unable to upload data to redirected URL {redirectResponse.UploadUrl}. Status:{uploadResponse.StatusCode} Reason:{uploadResponse.ReasonPhrase} Response:{body}"); }My edits:

using HttpClient uploadRedirectClient = _createUploadRedirectClient(); using (HttpRequestMessage uploadRequest = new HttpRequestMessage(HttpMethod.Put, redirectResponse.UploadUrl)) { uploadRequest.Content = streamContent; uploadRequest.Content.Headers.Add("x-ms-blob-type", "BlockBlob"); using HttpResponseMessage uploadResponse = await uploadRedirectClient.SendAsync(uploadRequest, cancellationToken); if (!uploadResponse.IsSuccessStatusCode) { string body = await uploadResponse.Content.ReadAsStringAsync(cancellationToken); throw new StorageException($"Unable to upload data to redirected URL {redirectResponse.UploadUrl}. Status:{uploadResponse.StatusCode} Reason:{uploadResponse.ReasonPhrase} Response:{body}"); } }After this change the node will succeed in auto-uploading log blobs to azure. Haven’t tested with AWS, but all storage tests are passing

9

Hey Nicolas,

Yeah I was hoping we could have avoided this, alas, it looks like such is the way. I’ll reach out to some of our other partners who use Azure (some at Microsoft :slight_smile: ) to see if they hit this as well. It’s tough for us to verify this on our end for aforementioned reasons.

Kind regards,

Julian