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

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 ...

atripp

This post is deleted!

felfert

Got it from the wireshark dump:

HTTP/1.1 500 Internal Server Error
Date: Fri, 29 Aug 2025 02:08:39 GMT
Server: Kestrel
Content-Length: 1091
Content-Type: application/json
Cache-Control: private
Content-Range: 0-32281444
Vary: Accept-Encoding,Authorization
X-ProGet-Version: 25.0.9.7
X-ProGet-Edition: free
Docker-Distribution-API-Version: registry/2.0
Connection: close

{"errors":[{"code":"UNKNOWN","message":"Nullable object must have a value.","detail":["   at System.Nullable`1.get_Value()\n   at Inedo.ProGet.Feeds.Docker.DockerFeed.VerifyAndInstallBlobUpload(String uploadId, DockerDigest digest, String mediaType) in C:\\Users\\builds\\AppData\\Local\\Temp\\InedoAgent\\BuildMaster\\192.168.44.60\\Temp\\_E588882\\Src\\src\\ProGet\\Feeds\\Docker\\DockerFeed.cs:line 381\n   at Inedo.ProGet.WebApplication.SimpleHandlers.Docker.DockerHandler.ProcessBlobUploadAsync(AhHttpContext context, WebApiContext apiContext, DockerFeed feed, String repositoryName, String uploadId) in C:\\Users\\builds\\AppData\\Local\\Temp\\InedoAgent\\BuildMaster\\192.168.44.60\\Temp\\_E588882\\Src\\src\\ProGet\\WebApplication\\SimpleHandlers\\Docker\\DockerHandler.cs:line 200\n   at Inedo.ProGet.WebApplication.SimpleHandlers.Docker.DockerHandler.ProcessRequestAsync(AhHttpContext context) in C:\\Users\\builds\\AppData\\Local\\Temp\\InedoAgent\\BuildMaster\\192.168.44.60\\Temp\\_E588882\\Src\\src\\ProGet\\WebApplication\\SimpleHandlers\\Docker\\DockerHandler.cs:line 92"]}]}

atripp

@inedo_1308 finally!!! nice find :)

atripp

In case you're curious, here is #381

49baf0bd-fa8f-4b1d-bf03-bcc7775cedd8-{23102B2B-0A1F-4CD1-B54C-71137AB85636}.png

.... and now to figure out what could possibly be null in that specific area

atripp

Hmmm the only possibility I can see is that DockerBlobs_CreateOrUpdateBlob is returning NULL , which is failing conversion to int dockerBlobId. That's the only nullable converstion on that line.

There's gotta be some kind of bug with this postresql procedure. Maybe a race condition??

CREATE OR REPLACE FUNCTION "DockerBlobs_CreateOrUpdateBlob"
(
    "@Feed_Id" INT,
    "@Blob_Digest" VARCHAR(128),
    "@Blob_Size" BIGINT,
    "@MediaType_Name" VARCHAR(255) = NULL,
    "@Cached_Indicator" BOOLEAN = NULL,
    "@Download_Count" INT = NULL,
    "@DockerBlob_Id" INT = NULL
)
RETURNS INT
LANGUAGE plpgsql
AS $$
BEGIN

    SELECT "DockerBlob_Id"
      INTO "@DockerBlob_Id"
      FROM "DockerBlobs"
     WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL))
       AND "Blob_Digest" = "@Blob_Digest";

    WITH updated AS
    (
        UPDATE "DockerBlobs"
           SET "Blob_Size" = "@Blob_Size",
               "MediaType_Name" = COALESCE("@MediaType_Name", "MediaType_Name"),
               "Cached_Indicator" = COALESCE("@Cached_Indicator", "Cached_Indicator")
         WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL)) 
           AND "Blob_Digest" = "@Blob_Digest"
        RETURNING *
    )        
    INSERT INTO "DockerBlobs"
    (
        "Feed_Id",
        "Blob_Digest",
        "Download_Count",
        "Blob_Size",
        "MediaType_Name",
        "Cached_Indicator"
    )
    SELECT
        "@Feed_Id",
        "@Blob_Digest",
        COALESCE("@Download_Count", 0),
        "@Blob_Size",
        "@MediaType_Name",
        COALESCE("@Cached_Indicator", 'N')
    WHERE NOT EXISTS (SELECT * FROM updated)
    RETURNING "DockerBlob_Id" INTO "@DockerBlob_Id";

    RETURN "@DockerBlob_Id";

END $$;

Anyway we'll study that another day.. at least we think we know specifically where the issue is.

felfert

@atripp Tomorrow I will compare this function's code on my "production" proget with that on the sandbox. Just to be shure.

atripp

@inedo_1308 sounds good!

The code would almost certainly be the same, since it hasn't been updated since we did the PostgreSQL version of the script.

So, I think it's a race condition, though I don't know how it would happen. However, if it's a race condition, then it should be solved with an UPDLOCK (or whatever) in PostgreSQL.

SELECT finds no matching blob in the database (thus DockerBlob_Id is null)
... small delay ...
UPDATE finds the matching blob because it was added (thus a row gets added to insert)
INSERT does run because there is a row in inserted
A NULL DockerBlob_Id is returned

If you're able to patch the procedure, could you add FOR UPDATE as follows? We are still relatively to PostgreSQL so I don't know if this the right way to do it in this case.

I think a second SELECT could also work, but I dunno.

CREATE OR REPLACE FUNCTION "DockerBlobs_CreateOrUpdateBlob"
(
    "@Feed_Id" INT,
    "@Blob_Digest" VARCHAR(128),
    "@Blob_Size" BIGINT,
    "@MediaType_Name" VARCHAR(255) = NULL,
    "@Cached_Indicator" BOOLEAN = NULL,
    "@Download_Count" INT = NULL,
    "@DockerBlob_Id" INT = NULL
)
RETURNS INT
LANGUAGE plpgsql
AS $$
BEGIN

    SELECT "DockerBlob_Id"
      INTO "@DockerBlob_Id"
      FROM "DockerBlobs"
     WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL))
       AND "Blob_Digest" = "@Blob_Digest"
   FOR UPDATE;

    WITH updated AS
    (
        UPDATE "DockerBlobs"
           SET "Blob_Size" = "@Blob_Size",
               "MediaType_Name" = COALESCE("@MediaType_Name", "MediaType_Name"),
               "Cached_Indicator" = COALESCE("@Cached_Indicator", "Cached_Indicator")
         WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL)) 
           AND "Blob_Digest" = "@Blob_Digest"
        RETURNING *
    )        
    INSERT INTO "DockerBlobs"
    (
        "Feed_Id",
        "Blob_Digest",
        "Download_Count",
        "Blob_Size",
        "MediaType_Name",
        "Cached_Indicator"
    )
    SELECT
        "@Feed_Id",
        "@Blob_Digest",
        COALESCE("@Download_Count", 0),
        "@Blob_Size",
        "@MediaType_Name",
        COALESCE("@Cached_Indicator", 'N')
    WHERE NOT EXISTS (SELECT * FROM updated)
    RETURNING "DockerBlob_Id" INTO "@DockerBlob_Id";

    RETURN "@DockerBlob_Id";

END $$;

felfert

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

The code would almost certainly be the same, since it hasn't been updated since we did the PostgreSQL version of the script.

You are right "production" and sandbox showed the same function

If you're able to patch the procedure, could you add FOR UPDATE as follows? We are still relatively to PostgreSQL so I don't know if this the right way to do it in this case.

Did that, verified that the function actually has changed and did another test. Unfortunately this did not help, error was exactly the same like in my above wireshark dump.
Or does one have to "compile" the function somehow after replacing? (I never dealt with SQL functions before and in general have very limited SQL knowledge.)

Cheers,
-Fritz

felfert

BTW:
Did you guys generate a different password for the postgres DB than for MSQL
during migration?

I'm asking, because i vaguely remember that i could access the postgres DB using the same password (taken from the mssql connection-string environment var).

Now, this didn't work anymore and I had to disable password-auth in pg_hba.conf in order to use pg_dump and psql inside the proget container.

Thanks
-Fritz

atripp

Hi @inedo_1308 ,

I forgot how it worked in the preview migration, but the connection string is stored in the database directory (/var/proget/database/.pgsqlconn).

Thanks,
Alana

atripp

Did that, verified that the function actually has changed and did another test. Unfortunately this did not help, error was exactly the same like in my above wireshark dump.
Or does one have to "compile" the function somehow after replacing? (I never dealt with SQL functions before and in general have very limited SQL knowledge.)

Ah that's a shame! We're kind of new to "patching" functions like this in postgresql, but I think that should have worked to change the code. And also the code change should have worked.

If you don't mind trying one other patch, where we select out the Blob_Id again in the end.

CREATE OR REPLACE FUNCTION "DockerBlobs_CreateOrUpdateBlob"
(
    "@Feed_Id" INT,
    "@Blob_Digest" VARCHAR(128),
    "@Blob_Size" BIGINT,
    "@MediaType_Name" VARCHAR(255) = NULL,
    "@Cached_Indicator" BOOLEAN = NULL,
    "@Download_Count" INT = NULL,
    "@DockerBlob_Id" INT = NULL
)
RETURNS INT
LANGUAGE plpgsql
AS $$
BEGIN

    SELECT "DockerBlob_Id"
      INTO "@DockerBlob_Id"
      FROM "DockerBlobs"
     WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL))
       AND "Blob_Digest" = "@Blob_Digest"
   FOR UPDATE;

    WITH updated AS
    (
        UPDATE "DockerBlobs"
           SET "Blob_Size" = "@Blob_Size",
               "MediaType_Name" = COALESCE("@MediaType_Name", "MediaType_Name"),
               "Cached_Indicator" = COALESCE("@Cached_Indicator", "Cached_Indicator")
         WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL)) 
           AND "Blob_Digest" = "@Blob_Digest"
        RETURNING *
    )        
    INSERT INTO "DockerBlobs"
    (
        "Feed_Id",
        "Blob_Digest",
        "Download_Count",
        "Blob_Size",
        "MediaType_Name",
        "Cached_Indicator"
    )
    SELECT
        "@Feed_Id",
        "@Blob_Digest",
        COALESCE("@Download_Count", 0),
        "@Blob_Size",
        "@MediaType_Name",
        COALESCE("@Cached_Indicator", 'N')
    WHERE NOT EXISTS (SELECT * FROM updated)
    RETURNING "DockerBlob_Id" INTO "@DockerBlob_Id";

    SELECT "DockerBlob_Id"
      INTO "@DockerBlob_Id"
      FROM "DockerBlobs"
     WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL))
       AND "Blob_Digest" = "@Blob_Digest"

    RETURN "@DockerBlob_Id";

END $$;

If this doesn't do the trick, I think we need to look a lot closer.

thomas_3037

I dump the schema from the Database. The Function looks nearly identical. Only the varchar sizes are different.

CREATE FUNCTION public."DockerBlobs_CreateOrUpdateBlob"("@Feed_Id" integer, "@Blob_Digest" character varying, "@Blob_Size" bigint, "@MediaType_Name" character varying DEFAULT NULL::character varying, "@Cached_Indicator" boolean DEFAULT 
NULL::boolean, "@Download_Count" integer DEFAULT NULL::integer, "@DockerBlob_Id" integer DEFAULT NULL::integer) RETURNS integer
    LANGUAGE plpgsql
    AS $$
BEGIN

    SELECT "DockerBlob_Id"
      INTO "@DockerBlob_Id"
      FROM "DockerBlobs"
     WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL))
       AND "Blob_Digest" = "@Blob_Digest";

    WITH updated AS
    (
        UPDATE "DockerBlobs"
           SET "Blob_Size" = "@Blob_Size",
               "MediaType_Name" = COALESCE("@MediaType_Name", "MediaType_Name"),
               "Cached_Indicator" = COALESCE("@Cached_Indicator", "Cached_Indicator")
         WHERE ("Feed_Id" = "@Feed_Id" OR ("Feed_Id" IS NULL AND "@Feed_Id" IS NULL)) 
           AND "Blob_Digest" = "@Blob_Digest"
        RETURNING *
    )        
    INSERT INTO "DockerBlobs"
    (
        "Feed_Id",
        "Blob_Digest",
        "Download_Count",
        "Blob_Size",
        "MediaType_Name",
        "Cached_Indicator"
    )
    SELECT
        "@Feed_Id",
        "@Blob_Digest",
        COALESCE("@Download_Count", 0),
        "@Blob_Size",
        "@MediaType_Name",
        COALESCE("@Cached_Indicator", 'N')
    WHERE NOT EXISTS (SELECT * FROM updated)
    RETURNING "DockerBlob_Id" INTO "@DockerBlob_Id";

    RETURN "@DockerBlob_Id";

END $$;

and the table schema

proget=# \d "DockerBlobs"
                                     Table "public.DockerBlobs"
       Column       |           Type           | Collation | Nullable |           Default            
--------------------+--------------------------+-----------+----------+------------------------------
 Feed_Id            | integer                  |           |          | 
 Blob_Digest        | character varying(128)   |           | not null | 
 Download_Count     | integer                  |           | not null | 
 LastRequested_Date | timestamp with time zone |           |          | 
 Blob_Size          | bigint                   |           | not null | 
 Cached_Indicator   | boolean                  |           | not null | 
 MediaType_Name     | character varying(255)   |           |          | 
 DockerBlob_Id      | integer                  |           | not null | generated always as identity
 LastScan_Date      | timestamp with time zone |           |          | 
Indexes:
    "PK__DockerBlobs" PRIMARY KEY, btree ("DockerBlob_Id")
    "IX__DockerBlobs__Blob_Digest" btree ("Blob_Digest")
    "UQ__DockerBlobs" UNIQUE CONSTRAINT, btree ("Feed_Id", "Blob_Digest")
Foreign-key constraints:
    "FK__DockerBlobs__Feeds" FOREIGN KEY ("Feed_Id") REFERENCES "Feeds"("Feed_Id") ON DELETE CASCADE
Referenced by:
    TABLE ""DockerImageLayers"" CONSTRAINT "FK__DockerBlobIndex__DockerBlobs" FOREIGN KEY ("DockerBlob_Id") REFERENCES "DockerBlobs"("DockerBlob_Id") ON DELETE CASCADE
    TABLE ""DockerBlobInfos"" CONSTRAINT "FK__DockerBlobInfos__DockerBlobs" FOREIGN KEY ("DockerBlob_Id") REFERENCES "DockerBlobs"("DockerBlob_Id") ON DELETE CASCADE
    TABLE ""DockerBlobPackages"" CONSTRAINT "FK__DockerBlobPackages__DockerBlobs" FOREIGN KEY ("DockerBlob_Id") REFERENCES "DockerBlobs"("DockerBlob_Id") ON DELETE CASCADE
    TABLE ""DockerImages"" CONSTRAINT "FK__DockerImages__DockerBlobs" FOREIGN KEY ("ContainerConfigBlob_Id") REFERENCES "DockerBlobs"("DockerBlob_Id") ON DELETE CASCADE

felfert

@atripp
If you don't mind trying one other patch, where we select out the Blob_Id again in the end.

Yippieh - That one did the Trick. Error is gone

There is a semicolon missing after the additional selct before the return

felfert

Going to push some more images to be on the safe side ...

felfert

@atripp Ok this is definitively working now. Pushed approx. 20 different images from 80MiB up to 2GiB. None of them produced an error anymore.

Excellent Support!!!

Thanks alot
-Fritz