proget 500 Internal server error when pushing to a proget docker feed

felfert

@thomas_3037 said in proget 500 Internal server error when pushing to a proget docker feed:

Hey Fritz,

a colleague find out that the parameter "--compression-format zstd:chunked" in the podman push command helped.

You can also set this option globally.

Hi Marc,

Many thanks for that workaround. Works perfectly with podman.
Unfortunately, I did not find an equivalent option for the regular docker.

atripp

Thanks for the find @thomas_3037 !

What a strange scenario... I have no idea what that parameter does (aside from what's written in the docs). Do you know if that has to do with how the layers are compressed?

I think this definitely points to some kind of middleware bug. But still aren't sure how to better error report. We'll update a bit later!

Thanks,
Alana

felfert

@atripp said in proget 500 Internal server error when pushing to a proget docker feed:

I have no idea what that parameter does

Maybe this sheds some light on the problem (from the containers.conf(5) manpage):

"Specifies the compression format to use when pushing an image. Supported values are: gzip, zstd and zstd:chunked. This field is ignored when pushing images to the docker-daemon and docker-archive formats. It is also ignored when the manifest format is set to v2s2. zstd:chunked is incompatible with encrypting images, and will be treated as zstd with a warning in that case."

The regular docker has an option --output=type=image,compression=zstd for setting image compression to zstd when running docker build and I tried that here whithout success. This leaves the chunked part. My guess is: It enables chunked http transfer encoding during the actual upload of the image blobs. You can verify that by looking at the http headers sent by the client. If my guess is correct, there should be a Header Content-Transfer-Encoding: chunked in the PUT request of the client. Just a guess for now. Will do a wireshark session of some push with podman and report back.

Cheers
-Fritz

felfert

@atripp, @thomas_3037

Update:

It's getting more weird: Now the podman push fails too even with that compression-format option. So it seems unrelated.

Cheers
-Fritz

wechselberg.nisboerge_3629

Chiming in here:
I have the same issue and it is behaving very erratic.

I have some images that are pushed fine without any parameter.
I have some images that are pushed fine with zstd
I have some images that are pushed fine with zstd:chunked

This is getting very weird ...

atripp

I just changed some of the logging code via PG-3101, which will probably cause the exception to be logged.

It just finished building the image inedo/proget:25.0.9-ci.6 -- would someone mind giving that a try? Once we we get the stack trace it'll probably be one of those type of errors

@thomas_3037 @inedo_1308 @wechselberg-nisboerge_3629

Thanks!!!!

wechselberg.nisboerge_3629

Well ...

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:341aba9cd1b201183186977186c3e3c8e8a9f79967b31f6fc2bff2a8da510c5d - - -
A 500 error occurred in sst-devops-oci-prod: Nullable object must have a value.
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 PUT http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/uploads/88cd2aa3-f537-4816-bcd8-23b0ed5eefa4?digest=sha256%3A31e705e6bb0246691b44e7e35991da5066444c0e861d9ef40703695b037552b8 - 500 90 application/json 32.8098ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:fdab6c583bb88b36e350d7c2011d1a6490bc8a501cc503d9b4a0198ca1f1cfb0 - 404 158 application/json 13.9966ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:3626f18144516cf17d3c15f60a55c075d34130f1cc3a00d43fe68edf5568d994 - - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 PATCH http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/uploads/1cf960f6-1b21-4a89-9eb7-1064b2f9a9ad - 202 0 - 11.7030ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:123542a56fc98af9ea8a10cb74548ace0c5e05db21e2f82e4ef989870dc72adf - 200 246 application/octet-stream 17.2649ms
A 500 error occurred in sst-devops-oci-prod: Nullable object must have a value.
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 PUT http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/uploads/ba1a754f-3c96-4b3a-8d04-8dd9c90e3db3?digest=sha256%3Aa2c2378190e0b91ba3e274e1d2c236873b1960d15602027fb9110f787feee901 - 500 90 application/json 25.0325ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:3626f18144516cf17d3c15f60a55c075d34130f1cc3a00d43fe68edf5568d994 - 200 2338 application/octet-stream 6.4659ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:341aba9cd1b201183186977186c3e3c8e8a9f79967b31f6fc2bff2a8da510c5d - 404 158 application/json 16.9192ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 PUT http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/uploads/1cf960f6-1b21-4a89-9eb7-1064b2f9a9ad?digest=sha256%3A7af4036786251654395076ed8392df109d652ae2e1c6de74aac94db89a9f9235 - application/octet-stream 0
A 500 error occurred in sst-devops-oci-prod: Nullable object must have a value.
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 PUT http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/uploads/1cf960f6-1b21-4a89-9eb7-1064b2f9a9ad?digest=sha256%3A7af4036786251654395076ed8392df109d652ae2e1c6de74aac94db89a9f9235 - 500 90 application/json 16.1379ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:972115bef0bf0586114d827ecd50b5591446d6e260d2f734e2861280eb620422 - - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 HEAD http://vl-dev-repo.ki.lan/v2/sst-devops-oci-prod/confluence-cmdb/blobs/sha256:972115bef0bf0586114d827ecd50b5591446d6e260d2f734e2861280eb620422 - 200 14142880 application/octet-stream 3.5634ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://vl-dev-repo.ki.lan/0x44/proget/Inedo.ProGet.WebApplication.Controls.Layout.NotificationBar/GetNotifications - - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET http://vl-dev-repo.ki.lan/0x44/proget/Inedo.ProGet.WebApplication.Controls.Layout.NotificationBar/GetNotifications - 200 30 - 6.2359ms

doesn't look like the logging is extended ... @atripp

Something I found: I switched from podman to docker as a test and that is able to push images that podman can't

felfert

@atripp said in proget 500 Internal server error when pushing to a proget docker feed:

25.0.9-ci.6

Just tested this 25.0.9-ci.6. Unfortunately, there is neither a stacktrace shown in GUI nor in stdout/stderr on the docker container that runs proget itself :-(

felfert

Just trying to help. This is a wireshark analysis of the tcp stream where it happens:

POST /v2/testing/xts-addon-webui/blobs/uploads/ HTTP/1.1
Host: proget.graudatastorage.intern
User-Agent: containers/5.35.0 (github.com/containers/image)
Content-Length: 0
Authorization: ----REDACTED----
Docker-Distribution-Api-Version: registry/2.0
Accept-Encoding: gzip


HTTP/1.1 202 Accepted
Date: Thu, 28 Aug 2025 07:11:37 GMT
Server: Kestrel
Content-Length: 0
Cache-Control: private
Location: /v2/testing/xts-addon-webui/blobs/uploads/2006612a-8f6d-4d13-8781-6ceaa1f808fb
Vary: Accept-Encoding,Authorization
X-ProGet-Version: 25.0.8.17
X-ProGet-Edition: free
Docker-Distribution-API-Version: registry/2.0
Range: 0-0
Docker-Upload-UUID: 2006612a-8f6d-4d13-8781-6ceaa1f808fb


PATCH /v2/testing/xts-addon-webui/blobs/uploads/2006612a-8f6d-4d13-8781-6ceaa1f808fb HTTP/1.1
Host: proget.graudatastorage.intern
User-Agent: containers/5.35.0 (github.com/containers/image)
Transfer-Encoding: chunked
Authorization: ----REDACTED----
Content-Type: application/octet-stream
Docker-Distribution-Api-Version: registry/2.0
Accept-Encoding: gzip
---- Binary BLOB data in chunked encoding redacted ----


PUT /v2/testing/xts-addon-webui/blobs/uploads/2006612a-8f6d-4d13-8781-6ceaa1f808fb?digest=sha256%3Acf93e1bb05f4874a5923244a5600fbc0091ef87879b6c780e7baced4b409daa0 HTTP/1.1
Host: proget.graudatastorage.intern
User-Agent: containers/5.35.0 (github.com/containers/image)
Content-Length: 0
Authorization: ----REDACTED----
Content-Type: application/octet-stream
Docker-Distribution-Api-Version: registry/2.0
Accept-Encoding: gzip


HTTP/1.1 500 Internal Server Error
Date: Thu, 28 Aug 2025 07:11:50 GMT
Server: Kestrel
Content-Length: 90
Content-Type: application/json
Cache-Control: private
Content-Range: 0-32281444
Vary: Accept-Encoding,Authorization
X-ProGet-Version: 25.0.8.17
X-ProGet-Edition: free
Docker-Distribution-API-Version: registry/2.0
Connection: close

{"errors":[{"code":"UNKNOWN","message":"Nullable object must have a value.","detail":[]}]}

The 500 happens only after the very last PUT request. Depending on the image being uploaded,
there might be uploads of other image layers before that which always use a PATCH request first for the actual blob and after that a PUT request with Content-Length: 0
Since those previous PUT requests are the same (except the URI of course) and they do NOT get a 500 response, i suspect this must be some code which only runs at the very end of the image upload.
NOTE: This was done before I updated to 25.0.9-ci.6

felfert

@thomas_3037 @wechselberg-nisboerge_3629

Another idea (just to find common parts of our proget installations or rule-out differences):

In my proget, I use the embedded postgres as db
The proget container itself is running on Rocky 9 in a quadlet.

Cheers
-Fritz

wechselberg.nisboerge_3629

My setup:

Host is Ubuntu 24.04 LTS
Running proget in a quadlet
Using embedded Database
With a caddy as a reverse proxy in front of it
Caddy also running in a quadlet
proget and caddy in a common podman network
Caddyfile as simple as possible:

<hostname {
    tls <certpath> <keypath>
    reverse_proxy http://proget:80
}

atripp

Hi @inedo_1308

Just tested this 25.0.9-ci.6. Unfortunately, there is neither a stacktrace shown in GUI nor in stdout/stderr on the docker container that runs proget itself :-(

Sorry but just to confirm, you looked in the Admin > Diagnostic Center?

Basically, I just changed the code from this...

if (error.StatusCode >= 500 || context.Response.HeadersWritten)
   WUtil.LogFeedException(error.StatusCode, feed, context, error);

...to this...

if (error.StatusCode == 500)
   WUtil.LogFeedException(error.StatusCode, feed, context, error);

I really don't see how that wouldn't work to log it. I guess, next thing I could try is to write the stack trace in the detail.

Thanks,
Alana

felfert

@atripp said in proget 500 Internal server error when pushing to a proget docker feed:

Sorry but just to confirm, you looked in the Admin > Diagnostic Center?

Yes, exactly. Also: Before perfoming the test, i deleted all messages (there were some unrelated errors from another feed). After the 500 happened, I did a reload in the browser and it still said "There are no errors to display."

Cheers
-Fritz

felfert

@atripp BTW it's getting weirder by the minute,
I now have created a second instance as a sandbox for testing and there I tried a bisection of the proget versions (starting from 25.0.2 until I reached 25.0.9-ci.6) and was NOT able to reproduce the error with that sandbox instance. I did two test variants: The first sequence of tests was using the default DB (mssql). After that, I recreated the sandbox VM from scratch ant repeated the sequece of tests after migrating proget to postgres with 25.0.2 installed.
I did this, because the "production" instance was using postgres and was migrated very early after 25.0 was released.

After learning that I cannot reproduce the error that way, I then had another idea: Performing a DB export on the production proget and importing that on the sandbox. Unfortunately, the import does not work: In the form for importing, I chose upload, then selected the DB-export but after some short time it simply said "Not found" in the form. No errors were shown in the diag center either.

Next steps (tomorrow - its 3 in the morning here) will be:

Freshly recreate the sandbox with 25.0.9-ci.6 and migrated to postgres.
Stop the proget container
Copy the content of all mapped docker volumes (/var/proget/{backup,database,extensions,packages}) from "production" to sandbox
Start proget container
Retry to reproduce the error on the sandbox

Will report back when i have more results

Cheers
-Fritz

felfert

@atripp said in proget 500 Internal server error when pushing to a proget docker feed:

Basically, I just changed the code from this...

if (error.StatusCode >= 500 || context.Response.HeadersWritten)
    WUtil.LogFeedException(error.StatusCode, feed, context, error);

...to this...

if (error.StatusCode == 500)
    WUtil.LogFeedException(error.StatusCode, feed, context, error);

That change looks wrong to me, because (error.StatusCode == 500) is more specific/restrictive than (error.StatusCode >= 500 || context.Response.HeadersWritten)
In other words: It logs less than before.

atripp

@inedo_1308 thanks for continuing to help us figure this out

Do you mind trying inedo/proget:25.0.9-ci.7?

I'm thinking it's some kind of middleware bug (our code? .NET code? who knows), and I can't see why the logging code I added didn't log that in diagnostic center.

Whatever the case, we can see the error JSON is being written: {"errors":[{"code":"UNKNOWN","message":"Nullable object must have a value.","detail":[]}]} ... so I just added the stack trace to detail element.

FYI, the code:

catch (Exception ex)
{
    WriteError(context, DockerException.Unknown(ex.Message), feed, w => w.WriteValue(ex.StackTrace)); // I added the final argument
}

....

private static void WriteError(AhHttpContext context, DockerException error, DockerFeed? feed, Action<JsonTextWriter>? writeDetail = null)
{
    /// code from before that should have worked
    if (error.StatusCode == 500)
        WUtil.LogFeedException(error.StatusCode, feed, context, error);

    if (!context.Response.HeadersWritten)
    {
        context.Response.Clear();
        context.Response.StatusCode = error.StatusCode;
        context.Response.ContentType = "application/json";

        using var jsonWriter = new JsonTextWriter(context.Response.Output);
        jsonWriter.WriteStartObject();
        jsonWriter.WritePropertyName("errors");
        jsonWriter.WriteStartArray();

        jsonWriter.WriteStartObject();
        jsonWriter.WritePropertyName("code");
        jsonWriter.WriteValue(error.ErrorCode);
        jsonWriter.WritePropertyName("message");
        jsonWriter.WriteValue(error.Message);
        jsonWriter.WritePropertyName("detail");
        jsonWriter.WriteStartArray();
        writeDetail?.Invoke(jsonWriter);
        jsonWriter.WriteEndArray();
        jsonWriter.WriteEndObject();

        jsonWriter.WriteEndArray();
        jsonWriter.WriteEndObject();
    }
}

atripp

@inedo_1308 said in proget 500 Internal server error when pushing to a proget docker feed:

That change looks wrong to me, because (error.StatusCode == 500) is more specific/restrictive than (error.StatusCode >= 500 || context.Response.HeadersWritten)
In other words: It logs less than before.

Good spot / good find -- though we never actually raise anything except 500 anyway, so i thought it would be fine

public static DockerException Unknown(string message) => new DockerException(500, "UNKNOWN", message);

Anyway wriiting the detail to that array will hpefully be caught.

felfert

@atripp said in proget 500 Internal server error when pushing to a proget docker feed:

Do you mind trying inedo/proget:25.0.9-ci.7?

Coming up in a few minutes ...

felfert

@inedo_1308

Nope, like before: Nothing in the diag center and on the container's output, only this:

Aug 29 03:53:54 gsg1repo.graudatastorage.intern systemd-proget[538207]:       Request finished HTTP/1.1 GET http://proget.graudatastorage.intern/0x44/proget/Inedo.ProGet.WebApplication.Controls.Layout.NotificationBar/GetNotifications - 200 30 - 7.0388ms
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]:       Request finished HTTP/1.1 PATCH http://proget.graudatastorage.intern/v2/testing/xts-addon-webui/blobs/uploads/ca81bc12-62b5-47f9-9bb3-7ef9b8c1530a - 202 0 - 19396.8436ms
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]: info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]:       Request starting HTTP/1.1 PUT http://proget.graudatastorage.intern/v2/testing/xts-addon-webui/blobs/uploads/ca81bc12-62b5-47f9-9bb3-7ef9b8c1530a?digest=sha256%3Acf93e1bb05f4874a5923244a5600fbc0091ef87879b6c780e7baced4b409daa0 - application/octet-stream 0
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]: A 500 error occurred in testing: Nullable object must have a value.
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Aug 29 03:53:58 gsg1repo.graudatastorage.intern systemd-proget[538207]:       Request finished HTTP/1.1 PUT http://proget.graudatastorage.intern/v2/testing/xts-addon-webui/blobs/uploads/ca81bc12-62b5-47f9-9bb3-7ef9b8c1530a?digest=sha256%3Acf93e1bb05f4874a5923244a5600fbc0091ef87879b6c780e7baced4b409daa0 - 500 1091 application/json 162.3468ms

felfert

Hold on. The second number in the last line:

... - 500 1091 application/json 162.3468ms

The 500 obviously is the status code. Is the second number the body size of the error response. If yes, that is more than before (in the previous tests, the second number was 90) and I will reveal that, If I do a wireshark dump .... just a minute ...