niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #249
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.72s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestParsePathInfoJSON96=== RUN TestParsePathInfoJSON/Nix_format97=== PAUSE TestParsePathInfoJSON/Nix_format98=== RUN TestParsePathInfoJSON/Lix_format99=== CONT TestClientSignaturesByStorePath100--- PASS: TestClientSignaturesByStorePath (0.00s)101=== CONT TestFileTokenMissing102=== CONT TestScriptTokenEmptyCommand103--- PASS: TestScriptTokenEmptyCommand (0.00s)104=== CONT TestFileTokenReadsAndCaches105=== CONT TestScriptTokenScriptFails106=== CONT TestScriptTokenBadJSON107=== CONT TestScriptTokenEmptyToken108--- PASS: TestFileTokenMissing (0.00s)109=== CONT TestStaticToken110=== CONT TestScriptTokenCachesUntilRefresh111--- PASS: TestStaticToken (0.00s)112=== CONT TestSetClientTLSErrors113=== CONT TestScriptTokenNoExpiryRerunsEveryCall114=== CONT TestFileTokenEmpty115=== PAUSE TestParsePathInfoJSON/Lix_format116=== RUN TestParsePathInfoJSON/empty_input117=== PAUSE TestParsePathInfoJSON/empty_input118=== RUN TestParsePathInfoJSON/whitespace_only119=== PAUSE TestParsePathInfoJSON/whitespace_only120=== RUN TestParsePathInfoJSON/invalid_JSON121=== PAUSE TestParsePathInfoJSON/invalid_JSON122=== CONT TestSetClientTLSDoesNotMutateDefaultTransport123--- PASS: TestFileTokenReadsAndCaches (0.00s)124=== CONT TestSetClientTLS125--- PASS: TestFileTokenEmpty (0.00s)126=== CONT TestShellSplitErrors127--- PASS: TestShellSplitErrors (0.00s)128=== CONT TestStreamPushReportsSignatures129--- PASS: TestScriptTokenScriptFails (0.01s)130=== CONT TestStreamPushRequestLine131=== RUN TestSetClientTLSErrors/missing_cert_file132=== PAUSE TestSetClientTLSErrors/missing_cert_file133=== RUN TestSetClientTLSErrors/missing_key_file134=== PAUSE TestSetClientTLSErrors/missing_key_file135=== RUN TestSetClientTLSErrors/missing_ca_file136=== PAUSE TestSetClientTLSErrors/missing_ca_file137=== RUN TestSetClientTLSErrors/invalid_ca_file138=== PAUSE TestSetClientTLSErrors/invalid_ca_file139=== CONT TestStreamPushGivesUpOnDeadServer1402026/09/22 10:44:35 ERROR Upload failed error=boom count=1141--- PASS: TestStreamPushReportsSignatures (0.00s)142=== CONT TestStreamPushIsolatesFailures1432026/09/22 10:44:35 ERROR Upload failed error=boom count=11442026/09/22 10:44:35 ERROR Upload failed error="connection refused" count=201452026/09/22 10:44:35 ERROR Server seems unavailable, giving up on batch untried=17146--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)147=== CONT TestStreamPushBatchesUnderLoad1482026/09/22 10:44:35 ERROR Upload failed error="bad path" count=3149--- PASS: TestStreamPushIsolatesFailures (0.00s)150=== CONT TestStreamPushReportsEveryPath151--- PASS: TestStreamPushReportsEveryPath (0.00s)152=== CONT TestDumpPathSingleFile153--- PASS: TestDoServerRequestAttachesToken (0.01s)154=== CONT TestPathInfoHashCompatibility155=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)157=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon159=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI160=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI161=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512162=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512163=== CONT TestGetStorePathHash164=== RUN TestGetStorePathHash/valid_store_path165--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)166=== CONT TestConvertHashToNix32167=== RUN TestConvertHashToNix32/SRI_format_to_Nix32168=== PAUSE TestGetStorePathHash/valid_store_path169=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32170=== RUN TestConvertHashToNix32/already_Nix32_format171=== PAUSE TestConvertHashToNix32/already_Nix32_format172=== RUN TestConvertHashToNix32/invalid_format173=== PAUSE TestConvertHashToNix32/invalid_format174=== CONT TestEncodeNixBase32WithRealHash175=== RUN TestGetStorePathHash/basename_without_hyphen_should_error176--- PASS: TestEncodeNixBase32WithRealHash (0.00s)177=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error178=== CONT TestEncodeNixBase32179=== RUN TestEncodeNixBase32/test_string_hash180=== PAUSE TestEncodeNixBase32/test_string_hash181=== RUN TestEncodeNixBase32/empty_input182=== PAUSE TestEncodeNixBase32/empty_input183=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error184=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error185=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error186=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error187=== CONT TestDumpPathWriterError188=== RUN TestSetClientTLS/rejects_connection_without_client_cert189=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert190=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA191=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA192=== RUN TestSetClientTLS/preserves_debug_logging_transport193=== PAUSE TestSetClientTLS/preserves_debug_logging_transport194=== CONT TestShellSplit195--- PASS: TestShellSplit (0.00s)196=== CONT TestResolveStorePath197=== CONT TestDoWithRetry_BodyReplayedViaGetBody198--- PASS: TestResolveStorePath (0.00s)199=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess2002026/09/22 10:44:35 WARN Rate limiter enabled after throttle name=server-test rate=52012026/09/22 10:44:35 WARN Rate limiter enabled after throttle name=server-test rate=52022026/09/22 10:44:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:563882032026/09/22 10:44:35 WARN Rate limiter backed off name=server-test rate=52042026/09/22 10:44:35 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56388205--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)206=== CONT TestPathInfoCACompatibility207=== RUN TestPathInfoCACompatibility/null_ca_field208=== PAUSE TestPathInfoCACompatibility/null_ca_field209=== RUN TestPathInfoCACompatibility/old_string_format_-_text210=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text211=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive212=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive213=== RUN TestPathInfoCACompatibility/new_structured_format_-_text214=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text215=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method216=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method217=== CONT TestRateLimiterFeedback218=== RUN TestRateLimiterFeedback/429_enables_limiter219=== PAUSE TestRateLimiterFeedback/429_enables_limiter220=== RUN TestRateLimiterFeedback/503_enables_limiter221=== PAUSE TestRateLimiterFeedback/503_enables_limiter222=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter223=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter224=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter225=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter226=== CONT TestCaseHackSuffix227--- PASS: TestScriptTokenBadJSON (0.02s)228--- PASS: TestScriptTokenEmptyToken (0.01s)229=== CONT TestFilterOversizedClosures230=== CONT TestDumpPathMatchesNix231=== RUN TestFilterOversizedClosures/no_limit_keeps_everything232=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything233=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped234=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped235=== RUN TestFilterOversizedClosures/all_closures_skipped236=== PAUSE TestFilterOversizedClosures/all_closures_skipped237=== CONT TestRegisterUploadedObjectReusesConnections238--- PASS: TestStreamPushRequestLine (0.03s)239=== CONT TestParsePathInfoJSONMultiplePaths240=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths241=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths242=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths243=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths244=== CONT TestUploadMultipart_PartsInParallel245--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)246=== CONT TestPartSizeForNAR247=== RUN TestPartSizeForNAR/zero_stays_at_minimum248=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum249=== RUN TestPartSizeForNAR/small_stays_at_minimum250=== PAUSE TestPartSizeForNAR/small_stays_at_minimum251=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum252=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum253=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts254=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts255=== RUN TestPartSizeForNAR/1_TiB256=== PAUSE TestPartSizeForNAR/1_TiB257=== RUN TestPartSizeForNAR/5_TiB_S3_max_object258=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object259=== RUN TestPartSizeForNAR/capped_at_5_GiB260=== PAUSE TestPartSizeForNAR/capped_at_5_GiB261=== CONT TestUploadMultipart_SupersededByPeer262=== RUN TestUploadMultipart_SupersededByPeer/exists263=== PAUSE TestUploadMultipart_SupersededByPeer/exists264=== RUN TestUploadMultipart_SupersededByPeer/missing265=== PAUSE TestUploadMultipart_SupersededByPeer/missing266=== CONT TestParsePathInfoJSON/Nix_format267=== CONT TestParsePathInfoJSON/whitespace_only268=== CONT TestParsePathInfoJSON/invalid_JSON269=== CONT TestParsePathInfoJSON/empty_input270=== CONT TestParsePathInfoJSON/Lix_format271--- PASS: TestParsePathInfoJSON (0.00s)272 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)273 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)274 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)275 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)276 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)277=== CONT TestSetClientTLSErrors/missing_cert_file278=== CONT TestSetClientTLSErrors/invalid_ca_file279=== CONT TestSetClientTLSErrors/missing_ca_file280=== CONT TestSetClientTLSErrors/missing_key_file281--- PASS: TestSetClientTLSErrors (0.01s)282 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)283 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)284 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)285 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)286=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)287=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512288=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI289=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon290--- PASS: TestPathInfoHashCompatibility (0.00s)291 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)292 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)293 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)294 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)295=== CONT TestConvertHashToNix32/SRI_format_to_Nix32296=== CONT TestConvertHashToNix32/already_Nix32_format297=== CONT TestEncodeNixBase32/test_string_hash298=== CONT TestEncodeNixBase32/empty_input299=== CONT TestGetStorePathHash/valid_store_path300=== CONT TestSetClientTLS/rejects_connection_without_client_cert301--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)302=== CONT TestConvertHashToNix32/invalid_format303=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error304=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error305=== CONT TestGetStorePathHash/basename_without_hyphen_should_error306=== CONT TestSetClientTLS/preserves_debug_logging_transport307--- PASS: TestConvertHashToNix32 (0.00s)308 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)309 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)310 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)311--- PASS: TestEncodeNixBase32 (0.00s)312 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)313 --- PASS: TestEncodeNixBase32/empty_input (0.00s)314--- PASS: TestGetStorePathHash (0.00s)315 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)316 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)317 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)318 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)319=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA320=== CONT TestPathInfoCACompatibility/null_ca_field321=== CONT TestPathInfoCACompatibility/new_structured_format_-_text322=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method323=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive324=== CONT TestPathInfoCACompatibility/old_string_format_-_text325--- PASS: TestPathInfoCACompatibility (0.00s)326 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)327 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)329 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)331=== CONT TestRateLimiterFeedback/429_enables_limiter3322026/09/22 10:44:35 WARN Rate limiter enabled after throttle name=server-test rate=53332026/09/22 10:44:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:564653342026/09/22 10:44:35 WARN Rate limiter backed off name=server-test rate=5335=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter336=== CONT TestRateLimiterFeedback/503_enables_limiter3372026/09/22 10:44:35 WARN Rate limiter enabled after throttle name=server-test rate=53382026/09/22 10:44:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:564693392026/09/22 10:44:35 WARN Rate limiter backed off name=server-test rate=5340=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter341--- PASS: TestDumpPathWriterError (0.06s)342=== CONT TestFilterOversizedClosures/no_limit_keeps_everything343=== CONT TestFilterOversizedClosures/all_closures_skipped3442026/09/22 10:44:35 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50345=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3462026/09/22 10:44:35 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000347--- PASS: TestFilterOversizedClosures (0.00s)348 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)349 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)350 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)351--- PASS: TestRateLimiterFeedback (0.00s)352 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)353 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)354 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)355 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)356=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths357=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths358--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)359 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)360 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)361=== CONT TestPartSizeForNAR/zero_stays_at_minimum362=== CONT TestPartSizeForNAR/capped_at_5_GiB363=== CONT TestPartSizeForNAR/1_TiB364=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts365=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum366=== CONT TestPartSizeForNAR/small_stays_at_minimum367=== CONT TestPartSizeForNAR/5_TiB_S3_max_object368--- PASS: TestPartSizeForNAR (0.00s)369 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)371 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)372 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)373 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)376=== CONT TestUploadMultipart_SupersededByPeer/exists377=== CONT TestUploadMultipart_SupersededByPeer/missing378--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)379--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)380 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)381 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)3822026/09/22 10:44:35 http: TLS handshake error from 127.0.0.1:56462: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.01s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)387--- PASS: TestDumpPathSingleFile (0.07s)388--- PASS: TestCaseHackSuffix (0.07s)389--- PASS: TestStreamPushBatchesUnderLoad (0.10s)390--- PASS: TestDumpPathMatchesNix (0.10s)391--- PASS: TestUploadMultipart_PartsInParallel (0.62s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld10".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-28854-4210868838/postgres2106888893/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-28854-4210868838/postgres2106888893/data -l logfile start421422/nix/var/nix/builds/nix-28854-4210868838/postgres2106888893:5432 - no response4232026-09-22 10:44:37.233 UTC [28963] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-09-22 10:44:37.233 UTC [28963] LOG: listening on Unix socket "/nix/var/nix/builds/nix-28854-4210868838/postgres2106888893/.s.PGSQL.5432"4252026-09-22 10:44:37.236 UTC [28970] LOG: database system was shut down at 2026-09-22 10:44:37 UTC4262026-09-22 10:44:37.237 UTC [28963] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-28854-4210868838/postgres2106888893:5432 - accepting connections428{"timestamp":"2026-09-22T10:44:37.451124Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"baf5e89f-4e06-4134-9c16-cf767f4cf990","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestResolveDBConnectionString462=== PAUSE TestResolveDBConnectionString463=== RUN TestLeadElectsOneAndHandsOver464=== PAUSE TestLeadElectsOneAndHandsOver465=== RUN TestLeadIncumbentWinsAfterRestart4662026-09-22 10:44:37.617 UTC [29009] ERROR: relation "goose_db_version" does not exist at character 364672026-09-22 10:44:37.617 UTC [29009] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4682026/09/22 10:44:37 OK 20241026095416_initial_model.sql (3.78ms)4692026/09/22 10:44:37 OK 20251210153512_drop_unused_gin_index.sql (756.21µs)4702026/09/22 10:44:37 OK 20251218171726_add_pins.sql (830.33µs)4712026/09/22 10:44:37 OK 20260628120000_add_object_size_and_stats.sql (883.58µs)4722026/09/22 10:44:37 OK 20260905000000_add_claims.sql (946.25µs)4732026/09/22 10:44:37 OK 20260920000000_drop_claims.sql (628.21µs)4742026/09/22 10:44:37 goose: successfully migrated database to version: 202609200000004752026/09/22 10:44:37 OK 1_commit_pending_closure.sql (1.45ms)4762026/09/22 10:44:37 OK 2_object_stats_trigger.sql (251.21µs)4772026/09/22 10:44:37 goose: up to current file version: 24782026/09/22 10:44:37 INFO lead: acquired remote=192.0.2.1:12344792026/09/22 10:44:38 INFO lead: released remote=192.0.2.1:12344802026/09/22 10:44:38 INFO lead: acquired remote=192.0.2.1:12344812026/09/22 10:44:38 INFO lead: released remote=192.0.2.1:1234482--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)483=== RUN TestLeadEndsOnShutdown484=== PAUSE TestLeadEndsOnShutdown485=== RUN TestGCAdvisoryLockBlocksConcurrentRun4862026-09-22 10:44:38.381 UTC [29031] ERROR: relation "goose_db_version" does not exist at character 364872026-09-22 10:44:38.381 UTC [29031] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4882026/09/22 10:44:38 OK 20241026095416_initial_model.sql (3.2ms)4892026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (766.54µs)4902026/09/22 10:44:38 OK 20251218171726_add_pins.sql (797.83µs)4912026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (832.67µs)4922026/09/22 10:44:38 OK 20260905000000_add_claims.sql (894.67µs)4932026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (625.29µs)4942026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000004952026/09/22 10:44:38 OK 1_commit_pending_closure.sql (857.96µs)4962026/09/22 10:44:38 OK 2_object_stats_trigger.sql (234.5µs)4972026/09/22 10:44:38 goose: up to current file version: 2498--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.11s)499=== RUN TestGCBugBareHashReferences500=== PAUSE TestGCBugBareHashReferences501=== RUN TestGCMetrics502=== PAUSE TestGCMetrics503=== RUN TestGCTaskStore_StartNew504=== PAUSE TestGCTaskStore_StartNew505=== RUN TestGCTaskStore_DeduplicateSameParams506=== PAUSE TestGCTaskStore_DeduplicateSameParams507=== RUN TestGCTaskStore_ConflictDifferentParams508=== PAUSE TestGCTaskStore_ConflictDifferentParams509=== RUN TestGCTaskStore_GetEmpty510=== PAUSE TestGCTaskStore_GetEmpty511=== RUN TestGCTaskStore_GetReturnsLatest512=== PAUSE TestGCTaskStore_GetReturnsLatest513=== RUN TestGCTaskStore_CompletedAllowsNewTask514=== PAUSE TestGCTaskStore_CompletedAllowsNewTask515=== RUN TestGCTaskStore_PhaseUpdates516=== PAUSE TestGCTaskStore_PhaseUpdates517=== RUN TestGCTaskStore_Fail518=== PAUSE TestGCTaskStore_Fail519=== RUN TestGracefulShutdownDrainsInflight520=== PAUSE TestGracefulShutdownDrainsInflight521=== RUN TestService_healthCheckHandler522=== PAUSE TestService_healthCheckHandler523=== RUN TestService_readinessHandler524=== PAUSE TestService_readinessHandler525=== RUN TestGenerateLandingPage526=== PAUSE TestGenerateLandingPage527=== RUN TestCacheConfigHandlerMaxNarSize528=== PAUSE TestCacheConfigHandlerMaxNarSize529=== RUN TestCreatePendingClosureRejectsOversizedNAR530=== PAUSE TestCreatePendingClosureRejectsOversizedNAR531=== RUN TestNARDeduplicationMetadataUploadBug532=== PAUSE TestNARDeduplicationMetadataUploadBug533=== RUN TestMetricsInventory534=== PAUSE TestMetricsInventory535=== RUN TestService_NativeMTLS536=== PAUSE TestService_NativeMTLS537=== RUN TestServerTLSConfig538=== PAUSE TestServerTLSConfig539=== RUN TestMultipartCleanup540=== PAUSE TestMultipartCleanup541=== RUN TestObjectStatsTrigger542=== PAUSE TestObjectStatsTrigger543=== RUN TestOrphanedObjectsGC544=== PAUSE TestOrphanedObjectsGC545=== RUN TestOrphanedObjectsGCStressTest546=== PAUSE TestOrphanedObjectsGCStressTest547=== RUN TestResurrectedObjectNotDeleted548=== PAUSE TestResurrectedObjectNotDeleted549=== RUN TestCreatePin_ReservedPins550=== PAUSE TestCreatePin_ReservedPins551=== RUN TestParseSingleRange552=== PAUSE TestParseSingleRange553=== RUN TestIsValidCachePath554=== PAUSE TestIsValidCachePath555=== RUN TestReadProxyNarinfo556=== PAUSE TestReadProxyNarinfo557=== RUN TestReadProxyNarinfoAlreadyDecompressed558=== PAUSE TestReadProxyNarinfoAlreadyDecompressed559=== RUN TestReadProxyNarStreaming560=== PAUSE TestReadProxyNarStreaming561=== RUN TestReadProxy404562=== PAUSE TestReadProxy404563=== RUN TestReadProxyInvalidPath564=== PAUSE TestReadProxyInvalidPath565=== RUN TestReadProxyHead566=== PAUSE TestReadProxyHead567=== RUN TestReadProxyConditionalGet568=== PAUSE TestReadProxyConditionalGet569=== RUN TestReadProxyRootRedirectsToIndexHTML570=== PAUSE TestReadProxyRootRedirectsToIndexHTML571=== RUN TestReadProxyDisabled572=== PAUSE TestReadProxyDisabled573=== RUN TestReadRedirectNar574=== PAUSE TestReadRedirectNar575=== RUN TestReadRedirectKeepsNarinfoProxied576=== PAUSE TestReadRedirectKeepsNarinfoProxied577=== RUN TestReadProxyRangeRequest578=== PAUSE TestReadProxyRangeRequest579=== RUN TestReadRedirectUsesPublicS3URL580=== PAUSE TestReadRedirectUsesPublicS3URL581=== RUN TestRedundantMultipartUpload582=== PAUSE TestRedundantMultipartUpload583=== RUN TestCompleteMultipartUpload_ErrorButObjectExists584=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists585=== RUN TestCompletedNarNotReofferedAcrossClosures586=== PAUSE TestCompletedNarNotReofferedAcrossClosures587=== RUN TestPresignedUploadRegisteredBeforeCommit588=== PAUSE TestPresignedUploadRegisteredBeforeCommit589=== RUN TestService_Rustfstest590=== PAUSE TestService_Rustfstest591=== RUN TestParseSize592=== PAUSE TestParseSize593=== RUN TestSkippedUploadsHandler594=== PAUSE TestSkippedUploadsHandler595=== RUN TestSystemdListenerNotActivated596--- PASS: TestSystemdListenerNotActivated (0.00s)597=== RUN TestWatchdogBeatsWhenHealthy598--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)599=== RUN TestWatchdogSkipsWhenUnhealthy6002026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6012026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6022026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6032026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6042026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6052026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6062026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6072026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6082026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6092026/09/22 10:44:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"610--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)611=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle612=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle613=== RUN TestProxyWriteTimeout614=== PAUSE TestProxyWriteTimeout615=== RUN TestIsValidUploadKey616=== PAUSE TestIsValidUploadKey617=== RUN TestUploadHandlersRejectInvalidKeys618=== PAUSE TestUploadHandlersRejectInvalidKeys619=== RUN TestUploadHandlersRejectOversizedBody620=== PAUSE TestUploadHandlersRejectOversizedBody621=== RUN TestService_cleanupPendingClosuresHandler622=== PAUSE TestService_cleanupPendingClosuresHandler623=== RUN TestService_createPendingClosureHandler624=== PAUSE TestService_createPendingClosureHandler625=== RUN TestService_verifyS3Integrity626=== PAUSE TestService_verifyS3Integrity627=== RUN TestCompleteMultipartUnregistered628=== PAUSE TestCompleteMultipartUnregistered629=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT630=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT631=== CONT TestService_AuthMiddleware632=== CONT TestMultipartCleanup633=== CONT TestReadProxyRangeRequest634=== CONT TestProxyWriteTimeout635=== CONT TestPresignedUploadRegisteredBeforeCommit636=== CONT TestCompleteMultipartUpload_ErrorButObjectExists637=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT638=== CONT TestSkippedUploadsHandler639=== RUN TestProxyWriteTimeout/narinfo640=== CONT TestRedundantMultipartUpload641=== CONT TestReadRedirectUsesPublicS3URL642=== PAUSE TestProxyWriteTimeout/narinfo643=== RUN TestProxyWriteTimeout/1_GiB_nar644=== PAUSE TestProxyWriteTimeout/1_GiB_nar645=== RUN TestProxyWriteTimeout/10_GiB_nar646=== PAUSE TestProxyWriteTimeout/10_GiB_nar647=== RUN TestProxyWriteTimeout/unknown_size648=== PAUSE TestProxyWriteTimeout/unknown_size649=== CONT TestService_cleanupPendingClosuresHandler6502026/09/22 10:44:38 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000651--- PASS: TestSkippedUploadsHandler (0.00s)652=== CONT TestCompleteMultipartUnregistered6532026-09-22 10:44:38.953 UTC [29067] ERROR: relation "goose_db_version" does not exist at character 366542026-09-22 10:44:38.953 UTC [29067] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6552026-09-22 10:44:38.962 UTC [29073] ERROR: relation "goose_db_version" does not exist at character 366562026-09-22 10:44:38.962 UTC [29073] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6572026-09-22 10:44:38.962 UTC [29070] ERROR: relation "goose_db_version" does not exist at character 366582026-09-22 10:44:38.962 UTC [29070] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6592026-09-22 10:44:38.962 UTC [29068] ERROR: relation "goose_db_version" does not exist at character 366602026-09-22 10:44:38.962 UTC [29068] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6612026-09-22 10:44:38.962 UTC [29071] ERROR: relation "goose_db_version" does not exist at character 366622026-09-22 10:44:38.962 UTC [29071] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6632026-09-22 10:44:38.962 UTC [29069] ERROR: relation "goose_db_version" does not exist at character 366642026-09-22 10:44:38.962 UTC [29069] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6652026-09-22 10:44:38.963 UTC [29072] ERROR: relation "goose_db_version" does not exist at character 366662026-09-22 10:44:38.963 UTC [29072] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6672026-09-22 10:44:38.963 UTC [29074] ERROR: relation "goose_db_version" does not exist at character 366682026-09-22 10:44:38.963 UTC [29074] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6692026-09-22 10:44:38.964 UTC [29075] ERROR: relation "goose_db_version" does not exist at character 366702026-09-22 10:44:38.964 UTC [29075] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6712026-09-22 10:44:38.966 UTC [29076] ERROR: relation "goose_db_version" does not exist at character 366722026-09-22 10:44:38.966 UTC [29076] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6732026/09/22 10:44:38 OK 20241026095416_initial_model.sql (9.69ms)6742026/09/22 10:44:38 OK 20241026095416_initial_model.sql (6.68ms)6752026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)6762026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)6772026/09/22 10:44:38 OK 20241026095416_initial_model.sql (7.69ms)6782026/09/22 10:44:38 OK 20241026095416_initial_model.sql (9.22ms)6792026/09/22 10:44:38 OK 20241026095416_initial_model.sql (8.88ms)6802026/09/22 10:44:38 OK 20241026095416_initial_model.sql (8.83ms)6812026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (857.75µs)6822026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (838.79µs)6832026/09/22 10:44:38 OK 20241026095416_initial_model.sql (9.05ms)6842026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (717.63µs)6852026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (872.29µs)6862026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (740.17µs)6872026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.9ms)6882026/09/22 10:44:38 OK 20241026095416_initial_model.sql (8.33ms)6892026/09/22 10:44:38 OK 20241026095416_initial_model.sql (8.76ms)6902026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.87ms)6912026/09/22 10:44:38 OK 20251218171726_add_pins.sql (1.61ms)6922026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)6932026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.41ms)6942026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.08ms)6952026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (1.44ms)6962026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.48ms)6972026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (737.13µs)6982026/09/22 10:44:38 OK 20241026095416_initial_model.sql (7.58ms)6992026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.15ms)7002026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (1.82ms)7012026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (1.28ms)7022026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (1.37ms)7032026/09/22 10:44:38 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)7042026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (2.53ms)7052026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.28ms)7062026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (2.09ms)7072026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (2.58ms)7082026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.82ms)7092026/09/22 10:44:38 OK 20251218171726_add_pins.sql (2.75ms)7102026/09/22 10:44:38 OK 20260905000000_add_claims.sql (1.99ms)7112026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.9ms)7122026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.57ms)7132026/09/22 10:44:38 OK 20251218171726_add_pins.sql (3ms)7142026/09/22 10:44:38 OK 20260905000000_add_claims.sql (1.95ms)7152026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)7162026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (2.09ms)7172026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007182026/09/22 10:44:38 OK 20260905000000_add_claims.sql (3.71ms)7192026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.67ms)7202026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007212026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (2.99ms)7222026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.05ms)7232026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007242026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.64ms)7252026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.48ms)7262026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007272026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.38ms)7282026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007292026/09/22 10:44:38 OK 20260628120000_add_object_size_and_stats.sql (1.86ms)7302026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.54ms)7312026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.93ms)7322026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007332026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.73ms)7342026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.74ms)7352026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007362026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.81ms)7372026/09/22 10:44:38 OK 2_object_stats_trigger.sql (877.46µs)7382026/09/22 10:44:38 goose: up to current file version: 27392026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.64ms)7402026/09/22 10:44:38 OK 2_object_stats_trigger.sql (711.88µs)7412026/09/22 10:44:38 goose: up to current file version: 27422026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.66ms)7432026/09/22 10:44:38 OK 2_object_stats_trigger.sql (542.88µs)7442026/09/22 10:44:38 goose: up to current file version: 27452026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.44ms)7462026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.99ms)7472026/09/22 10:44:38 OK 2_object_stats_trigger.sql (463.17µs)7482026/09/22 10:44:38 goose: up to current file version: 27492026/09/22 10:44:38 OK 2_object_stats_trigger.sql (362.5µs)7502026/09/22 10:44:38 goose: up to current file version: 27512026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.61ms)7522026/09/22 10:44:38 OK 1_commit_pending_closure.sql (1.17ms)7532026/09/22 10:44:38 OK 2_object_stats_trigger.sql (314.25µs)7542026/09/22 10:44:38 goose: up to current file version: 27552026/09/22 10:44:38 OK 2_object_stats_trigger.sql (372.58µs)7562026/09/22 10:44:38 goose: up to current file version: 27572026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.09ms)7582026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007592026/09/22 10:44:38 OK 20260905000000_add_claims.sql (2.46ms)7602026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (1.17ms)7612026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007622026/09/22 10:44:38 OK 1_commit_pending_closure.sql (894.75µs)7632026/09/22 10:44:38 OK 20260920000000_drop_claims.sql (993µs)7642026/09/22 10:44:38 goose: successfully migrated database to version: 202609200000007652026/09/22 10:44:38 OK 1_commit_pending_closure.sql (944.13µs)7662026/09/22 10:44:38 OK 2_object_stats_trigger.sql (457.46µs)7672026/09/22 10:44:38 goose: up to current file version: 27682026/09/22 10:44:38 OK 2_object_stats_trigger.sql (279.33µs)7692026/09/22 10:44:38 goose: up to current file version: 27702026/09/22 10:44:38 OK 1_commit_pending_closure.sql (722.54µs)7712026/09/22 10:44:38 OK 2_object_stats_trigger.sql (186.67µs)7722026/09/22 10:44:38 goose: up to current file version: 27732026/09/22 10:44:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7742026/09/22 10:44:39 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst775--- PASS: TestCompleteMultipartUnregistered (0.38s)776=== CONT TestService_verifyS3Integrity7772026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures7782026/09/22 10:44:39 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst7792026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures780--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.56s)781=== CONT TestService_createPendingClosureHandler782--- PASS: TestReadProxyRangeRequest (0.70s)783=== CONT TestGCMetrics7842026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures785--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.86s)786=== CONT TestServerTLSConfig787=== RUN TestServerTLSConfig/no_client_CA788=== PAUSE TestServerTLSConfig/no_client_CA789=== RUN TestServerTLSConfig/missing_CA_file790=== PAUSE TestServerTLSConfig/missing_CA_file791=== RUN TestServerTLSConfig/not_a_PEM_file792=== PAUSE TestServerTLSConfig/not_a_PEM_file793=== CONT TestService_NativeMTLS7942026-09-22 10:44:39.610 UTC [29097] ERROR: relation "goose_db_version" does not exist at character 367952026-09-22 10:44:39.610 UTC [29097] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures7972026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures7982026/09/22 10:44:39 OK 20241026095416_initial_model.sql (63.78ms)7992026/09/22 10:44:39 OK 20251210153512_drop_unused_gin_index.sql (6.09ms)8002026/09/22 10:44:39 OK 20251218171726_add_pins.sql (18.97ms)8012026/09/22 10:44:39 OK 20260628120000_add_object_size_and_stats.sql (18.79ms)8022026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures8032026-09-22 10:44:39.765 UTC [29101] ERROR: relation "goose_db_version" does not exist at character 368042026-09-22 10:44:39.765 UTC [29101] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8052026/09/22 10:44:39 OK 20260905000000_add_claims.sql (7.03ms)8062026/09/22 10:44:39 OK 20260920000000_drop_claims.sql (43.94ms)8072026/09/22 10:44:39 goose: successfully migrated database to version: 202609200000008082026/09/22 10:44:39 OK 1_commit_pending_closure.sql (921.08µs)8092026/09/22 10:44:39 OK 2_object_stats_trigger.sql (233.17µs)8102026/09/22 10:44:39 goose: up to current file version: 28112026/09/22 10:44:39 OK 20241026095416_initial_model.sql (55.06ms)8122026/09/22 10:44:39 OK 20251210153512_drop_unused_gin_index.sql (12.3ms)8132026/09/22 10:44:39 OK 20251218171726_add_pins.sql (12.38ms)8142026/09/22 10:44:39 OK 20260628120000_add_object_size_and_stats.sql (13.9ms)8152026-09-22 10:44:39.919 UTC [29105] ERROR: relation "goose_db_version" does not exist at character 368162026-09-22 10:44:39.919 UTC [29105] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8172026/09/22 10:44:39 INFO Received cleanup request method=DELETE path=/api/pending_closures8182026/09/22 10:44:39 INFO Aborted multipart uploads count=18192026/09/22 10:44:39 INFO Received cleanup request method=DELETE path=/api/pending_closures8202026/09/22 10:44:39 INFO Aborted multipart uploads count=08212026/09/22 10:44:39 INFO Received uploads request method=POST path=/api/pending_closures822--- PASS: TestMultipartCleanup (1.27s)823=== CONT TestMetricsInventory8242026/09/22 10:44:39 OK 20260905000000_add_claims.sql (56.82ms)8252026/09/22 10:44:39 INFO Received cleanup request method=DELETE path=/api/pending_closures8262026/09/22 10:44:39 INFO Aborted multipart uploads count=18272026/09/22 10:44:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8282026-09-22 10:44:40.000 UTC [29071] ERROR: Closure does not exist: id=18292026-09-22 10:44:40.000 UTC [29071] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE8302026-09-22 10:44:40.000 UTC [29071] STATEMENT: -- name: CommitPendingClosure :exec831 SELECT commit_pending_closure($1::bigint)832 833--- PASS: TestService_cleanupPendingClosuresHandler (1.32s)834=== CONT TestNARDeduplicationMetadataUploadBug8352026/09/22 10:44:40 OK 20260920000000_drop_claims.sql (35.15ms)8362026/09/22 10:44:40 goose: successfully migrated database to version: 202609200000008372026/09/22 10:44:40 OK 1_commit_pending_closure.sql (927.58µs)8382026/09/22 10:44:40 OK 2_object_stats_trigger.sql (250.67µs)8392026/09/22 10:44:40 goose: up to current file version: 28402026/09/22 10:44:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"841--- PASS: TestService_AuthMiddleware (1.46s)842=== CONT TestCreatePendingClosureRejectsOversizedNAR8432026/09/22 10:44:40 INFO Received uploads request method=POST path=/api/pending_closures844--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)845=== CONT TestCacheConfigHandlerMaxNarSize846--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)847=== CONT TestGenerateLandingPage848--- PASS: TestGenerateLandingPage (0.00s)849=== CONT TestService_readinessHandler8502026/09/22 10:44:40 OK 20241026095416_initial_model.sql (192.06ms)8512026/09/22 10:44:40 OK 20251210153512_drop_unused_gin_index.sql (6.52ms)8522026/09/22 10:44:40 OK 20251218171726_add_pins.sql (18.74ms)8532026/09/22 10:44:40 OK 20260628120000_add_object_size_and_stats.sql (24.01ms)8542026/09/22 10:44:40 OK 20260905000000_add_claims.sql (45.46ms)8552026/09/22 10:44:40 OK 20260920000000_drop_claims.sql (15.51ms)8562026/09/22 10:44:40 goose: successfully migrated database to version: 202609200000008572026/09/22 10:44:40 OK 1_commit_pending_closure.sql (1.4ms)8582026/09/22 10:44:40 OK 2_object_stats_trigger.sql (540.25µs)8592026/09/22 10:44:40 goose: up to current file version: 28602026-09-22 10:44:40.271 UTC [29120] ERROR: relation "goose_db_version" does not exist at character 368612026-09-22 10:44:40.271 UTC [29120] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC862--- PASS: TestReadRedirectUsesPublicS3URL (1.64s)863=== CONT TestService_healthCheckHandler8642026/09/22 10:44:40 OK 20241026095416_initial_model.sql (114.51ms)8652026/09/22 10:44:40 OK 20251210153512_drop_unused_gin_index.sql (8.71ms)8662026/09/22 10:44:40 INFO Received uploads request method=POST path=/api/pending_closures8672026/09/22 10:44:40 OK 20251218171726_add_pins.sql (8.2ms)8682026/09/22 10:44:40 OK 20260628120000_add_object_size_and_stats.sql (33.89ms)8692026/09/22 10:44:40 OK 20260905000000_add_claims.sql (37.45ms)8702026/09/22 10:44:40 OK 20260920000000_drop_claims.sql (24.46ms)8712026/09/22 10:44:40 goose: successfully migrated database to version: 202609200000008722026/09/22 10:44:40 OK 1_commit_pending_closure.sql (1.49ms)8732026/09/22 10:44:40 OK 2_object_stats_trigger.sql (288.08µs)8742026/09/22 10:44:40 goose: up to current file version: 28752026/09/22 10:44:40 INFO Received uploads request method=POST path=/api/pending_closures8762026/09/22 10:44:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8772026/09/22 10:44:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjJlNzkzYWYtZjI4NC00MTdlLTg2YjktMWVkOWJiNDdmZDgyLjIwNDg4ZTQzLWVkNjEtNDM4ZC04ZWVmLWJiZDk5MmNjN2JjNHgxNzkwMDczODgwNDcwNDE0MDAw8782026/09/22 10:44:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjJlNzkzYWYtZjI4NC00MTdlLTg2YjktMWVkOWJiNDdmZDgyLjIwNDg4ZTQzLWVkNjEtNDM4ZC04ZWVmLWJiZDk5MmNjN2JjNHgxNzkwMDczODgwNDcwNDE0MDAw parts=1879--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.96s)880=== CONT TestGracefulShutdownDrainsInflight8812026/09/22 10:44:40 INFO Starting HTTP server address=127.0.0.1:566228822026/09/22 10:44:40 INFO Shutdown signal received, draining in-flight requests timeout=10s883--- PASS: TestGracefulShutdownDrainsInflight (0.07s)884=== CONT TestGCTaskStore_Fail885--- PASS: TestGCTaskStore_Fail (0.00s)886=== CONT TestGCTaskStore_PhaseUpdates887--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)888=== CONT TestGCTaskStore_CompletedAllowsNewTask889--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)890=== CONT TestGCTaskStore_GetReturnsLatest891--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)892=== CONT TestGCTaskStore_GetEmpty893--- PASS: TestGCTaskStore_GetEmpty (0.00s)894=== CONT TestGCTaskStore_ConflictDifferentParams895--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)896=== CONT TestGCTaskStore_DeduplicateSameParams897--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)898=== CONT TestGCTaskStore_StartNew899--- PASS: TestGCTaskStore_StartNew (0.00s)900=== CONT TestUploadHandlersRejectInvalidKeys901=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info902=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info903=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal904=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal905=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key906=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key907=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key908=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key909=== CONT TestUploadHandlersRejectOversizedBody910=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure911=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure912=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart913=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart914=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts915=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts916=== CONT TestReadProxyNarStreaming9172026/09/22 10:44:40 INFO Received uploads request method=POST path=/api/pending_closures9182026/09/22 10:44:40 INFO Received uploads request method=POST path=/api/pending_closures9192026/09/22 10:44:40 INFO Received uploads request method=POST path=/api/pending_closures9202026/09/22 10:44:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9212026/09/22 10:44:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MjJlNzkzYWYtZjI4NC00MTdlLTg2YjktMWVkOWJiNDdmZDgyLjIwMjJiZjQ4LWM2MDQtNDU1My05YzcwLWYxYjI1MGRjNTFjMngxNzkwMDczODc5NjIxNzAxMDAw parts=12922--- PASS: TestRedundantMultipartUpload (2.27s)923=== CONT TestReadRedirectKeepsNarinfoProxied9242026/09/22 10:44:41 INFO Aborted multipart uploads count=09252026/09/22 10:44:41 WARN Force mode enabled - objects will be deleted immediately without grace period9262026/09/22 10:44:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09272026/09/22 10:44:41 INFO Vacuumed table table=pending_closures9282026/09/22 10:44:41 INFO Vacuumed table table=pending_objects9292026/09/22 10:44:41 INFO Vacuumed table table=multipart_uploads9302026/09/22 10:44:41 INFO Vacuumed table table=closures9312026/09/22 10:44:41 INFO Vacuumed table table=objects932--- PASS: TestGCMetrics (1.73s)933=== CONT TestReadRedirectNar9342026/09/22 10:44:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9352026/09/22 10:44:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"936--- PASS: TestService_NativeMTLS (1.75s)937=== CONT TestReadProxyDisabled9382026-09-22 10:44:41.490 UTC [29167] ERROR: relation "goose_db_version" does not exist at character 369392026-09-22 10:44:41.490 UTC [29167] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9402026-09-22 10:44:41.490 UTC [29166] ERROR: relation "goose_db_version" does not exist at character 369412026-09-22 10:44:41.490 UTC [29166] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9422026-09-22 10:44:41.557 UTC [29168] ERROR: relation "goose_db_version" does not exist at character 369432026-09-22 10:44:41.557 UTC [29168] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9442026/09/22 10:44:41 OK 20241026095416_initial_model.sql (96.12ms)9452026/09/22 10:44:41 OK 20241026095416_initial_model.sql (103.54ms)9462026/09/22 10:44:41 OK 20251210153512_drop_unused_gin_index.sql (7.45ms)9472026/09/22 10:44:41 OK 20251210153512_drop_unused_gin_index.sql (8.04ms)9482026/09/22 10:44:41 OK 20251218171726_add_pins.sql (22.16ms)9492026/09/22 10:44:41 OK 20251218171726_add_pins.sql (14.53ms)9502026/09/22 10:44:41 OK 20260628120000_add_object_size_and_stats.sql (7.88ms)9512026/09/22 10:44:41 OK 20241026095416_initial_model.sql (78.44ms)9522026/09/22 10:44:41 OK 20260628120000_add_object_size_and_stats.sql (8.07ms)9532026/09/22 10:44:41 OK 20251210153512_drop_unused_gin_index.sql (10.99ms)9542026/09/22 10:44:41 OK 20260905000000_add_claims.sql (21.69ms)9552026/09/22 10:44:41 OK 20260905000000_add_claims.sql (28.38ms)9562026/09/22 10:44:41 OK 20251218171726_add_pins.sql (24.42ms)9572026/09/22 10:44:41 OK 20260920000000_drop_claims.sql (16.43ms)9582026/09/22 10:44:41 goose: successfully migrated database to version: 202609200000009592026/09/22 10:44:41 OK 20260920000000_drop_claims.sql (23.29ms)9602026/09/22 10:44:41 goose: successfully migrated database to version: 202609200000009612026-09-22 10:44:41.720 UTC [29185] ERROR: relation "goose_db_version" does not exist at character 369622026-09-22 10:44:41.720 UTC [29185] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9632026/09/22 10:44:41 OK 1_commit_pending_closure.sql (1.09ms)9642026/09/22 10:44:41 OK 1_commit_pending_closure.sql (1.27ms)9652026/09/22 10:44:41 OK 2_object_stats_trigger.sql (230.25µs)9662026/09/22 10:44:41 goose: up to current file version: 29672026/09/22 10:44:41 OK 2_object_stats_trigger.sql (344.04µs)9682026/09/22 10:44:41 goose: up to current file version: 29692026/09/22 10:44:41 OK 20260628120000_add_object_size_and_stats.sql (23.26ms)9702026/09/22 10:44:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9712026/09/22 10:44:41 OK 20260905000000_add_claims.sql (56.2ms)9722026/09/22 10:44:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MjJlNzkzYWYtZjI4NC00MTdlLTg2YjktMWVkOWJiNDdmZDgyLjRiOTU0MjRkLTgwYTMtNGQwMi05MGE1LTQ5OGVhZDZlNmU3ZHgxNzkwMDczODgwNjUxMzIzMDAw parts=109732026/09/22 10:44:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9742026/09/22 10:44:41 INFO Completed upload id=19752026/09/22 10:44:41 INFO Received uploads request method=POST path=/api/pending_closures9762026/09/22 10:44:41 INFO Received uploads request method=POST path=/api/pending_closures9772026/09/22 10:44:41 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9782026/09/22 10:44:41 WARN Found objects in DB but missing from S3, will re-upload count=1979--- PASS: TestService_verifyS3Integrity (2.75s)980=== CONT TestReadProxyRootRedirectsToIndexHTML9812026/09/22 10:44:41 OK 20260920000000_drop_claims.sql (43.38ms)9822026/09/22 10:44:41 goose: successfully migrated database to version: 202609200000009832026/09/22 10:44:41 OK 1_commit_pending_closure.sql (959.21µs)9842026/09/22 10:44:41 OK 2_object_stats_trigger.sql (263.08µs)9852026/09/22 10:44:41 goose: up to current file version: 29862026/09/22 10:44:41 OK 20241026095416_initial_model.sql (113.68ms)9872026/09/22 10:44:41 OK 20251210153512_drop_unused_gin_index.sql (9.54ms)9882026/09/22 10:44:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9892026/09/22 10:44:41 OK 20251218171726_add_pins.sql (63.17ms)9902026/09/22 10:44:41 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MjJlNzkzYWYtZjI4NC00MTdlLTg2YjktMWVkOWJiNDdmZDgyLjVhOGJjMDhjLWJhYTQtNGQ5ZS1hODdiLWQ1MjkxZmE5OGU4NHgxNzkwMDczODgwODY2Njk0MDAw parts=109912026/09/22 10:44:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9922026/09/22 10:44:41 INFO Completed upload id=19932026/09/22 10:44:41 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009942026/09/22 10:44:41 INFO Received uploads request method=POST path=/api/pending_closures9952026/09/22 10:44:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures9962026/09/22 10:44:41 INFO Aborted multipart uploads count=09972026/09/22 10:44:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=09982026/09/22 10:44:42 OK 20260628120000_add_object_size_and_stats.sql (32.71ms)999--- PASS: TestMetricsInventory (2.06s)1000=== CONT TestReadProxyConditionalGet10012026/09/22 10:44:42 INFO Vacuumed table table=pending_closures10022026/09/22 10:44:42 INFO Vacuumed table table=pending_objects10032026/09/22 10:44:42 OK 20260905000000_add_claims.sql (17.4ms)10042026/09/22 10:44:42 OK 20260920000000_drop_claims.sql (8.41ms)10052026/09/22 10:44:42 goose: successfully migrated database to version: 2026092000000010062026/09/22 10:44:42 OK 1_commit_pending_closure.sql (1.31ms)10072026/09/22 10:44:42 OK 2_object_stats_trigger.sql (228.38µs)10082026/09/22 10:44:42 goose: up to current file version: 210092026/09/22 10:44:42 INFO Vacuumed table table=multipart_uploads10102026/09/22 10:44:42 INFO Vacuumed table table=closures10112026/09/22 10:44:42 INFO Vacuumed table table=objects10122026/09/22 10:44:42 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001013--- PASS: TestService_createPendingClosureHandler (2.86s)1014=== CONT TestReadProxyHead10152026-09-22 10:44:42.201 UTC [29234] ERROR: relation "goose_db_version" does not exist at character 3610162026-09-22 10:44:42.201 UTC [29234] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1017=== NAME TestNARDeduplicationMetadataUploadBug1018 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-28854-4210868838/TestNARDeduplicationMetadataUploadBug1255628358/001/store/sqdx3f7snq90mr70d286bdnk8rx3202p-file1.txt10192026/09/22 10:44:42 WARN readiness check failed error="closed pool"1020--- PASS: TestService_readinessHandler (2.14s)1021=== CONT TestReadProxyInvalidPath10222026/09/22 10:44:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10232026/09/22 10:44:42 INFO Received uploads request method=POST path=/api/pending_closures10242026/09/22 10:44:42 OK 20241026095416_initial_model.sql (103.66ms)10252026/09/22 10:44:42 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)10262026-09-22 10:44:42.342 UTC [29247] ERROR: relation "goose_db_version" does not exist at character 3610272026-09-22 10:44:42.342 UTC [29247] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10282026-09-22 10:44:42.343 UTC [29249] ERROR: relation "goose_db_version" does not exist at character 3610292026-09-22 10:44:42.343 UTC [29249] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10302026/09/22 10:44:42 OK 20251218171726_add_pins.sql (10.69ms)10312026/09/22 10:44:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10322026/09/22 10:44:42 INFO Uploading sqdx3f7snq90mr70d286bdnk8rx3202p-file1.txt (160B)10332026/09/22 10:44:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10342026/09/22 10:44:42 OK 20260628120000_add_object_size_and_stats.sql (16.92ms)10352026/09/22 10:44:42 WARN Failed to register uploaded object key=sqdx3f7snq90mr70d286bdnk8rx3202p.ls error="server returned 404: 404 page not found\n"10362026/09/22 10:44:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10372026/09/22 10:44:42 INFO Signed narinfos id=1 count=110382026/09/22 10:44:42 INFO Uploading 1 narinfos10392026/09/22 10:44:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10402026/09/22 10:44:42 WARN Failed to register uploaded object key=sqdx3f7snq90mr70d286bdnk8rx3202p.narinfo error="server returned 404: 404 page not found\n"10412026/09/22 10:44:42 OK 20260905000000_add_claims.sql (44.71ms)10422026/09/22 10:44:42 INFO Completed upload id=110432026/09/22 10:44:42 INFO Upload complete. (140ms)1044=== NAME TestNARDeduplicationMetadataUploadBug1045 metadata_upload_test.go:54: Retrieved narinfo from S3:1046 StorePath: /nix/var/nix/builds/nix-28854-4210868838/TestNARDeduplicationMetadataUploadBug1255628358/001/store/sqdx3f7snq90mr70d286bdnk8rx3202p-file1.txt1047 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1048 Compression: zstd1049 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1050 NarSize: 1601051 References: 1052 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1053 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1054 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1055 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}10562026/09/22 10:44:42 OK 20260920000000_drop_claims.sql (14.48ms)10572026/09/22 10:44:42 goose: successfully migrated database to version: 2026092000000010582026/09/22 10:44:42 OK 1_commit_pending_closure.sql (1.18ms)10592026/09/22 10:44:42 OK 2_object_stats_trigger.sql (249.38µs)10602026/09/22 10:44:42 goose: up to current file version: 210612026-09-22 10:44:42.458 UTC [29251] ERROR: relation "goose_db_version" does not exist at character 3610622026-09-22 10:44:42.458 UTC [29251] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1063--- PASS: TestService_healthCheckHandler (2.15s)1064=== CONT TestReadProxy4041065=== NAME TestNARDeduplicationMetadataUploadBug1066 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-28854-4210868838/TestNARDeduplicationMetadataUploadBug1255628358/001/store/m0vbyyxgmhbk6p95v1g77gmg2kmi7drn-file2.txt10672026/09/22 10:44:42 OK 20241026095416_initial_model.sql (77.72ms)10682026/09/22 10:44:42 OK 20251210153512_drop_unused_gin_index.sql (8.42ms)10692026/09/22 10:44:42 OK 20241026095416_initial_model.sql (103.92ms)10702026/09/22 10:44:42 OK 20251210153512_drop_unused_gin_index.sql (8.79ms)10712026/09/22 10:44:42 OK 20251218171726_add_pins.sql (28.05ms)10722026/09/22 10:44:42 OK 20251218171726_add_pins.sql (19.14ms)10732026/09/22 10:44:42 OK 20260628120000_add_object_size_and_stats.sql (9.08ms)10742026/09/22 10:44:42 OK 20260628120000_add_object_size_and_stats.sql (8.49ms)10752026/09/22 10:44:42 OK 20260905000000_add_claims.sql (20.09ms)10762026/09/22 10:44:42 OK 20260905000000_add_claims.sql (14.76ms)10772026/09/22 10:44:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10782026/09/22 10:44:42 INFO Received uploads request method=POST path=/api/pending_closures10792026/09/22 10:44:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10802026/09/22 10:44:42 OK 20260920000000_drop_claims.sql (8.22ms)10812026/09/22 10:44:42 goose: successfully migrated database to version: 2026092000000010822026/09/22 10:44:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10832026/09/22 10:44:42 OK 20260920000000_drop_claims.sql (8.96ms)10842026/09/22 10:44:42 goose: successfully migrated database to version: 2026092000000010852026/09/22 10:44:42 INFO Signed narinfos id=2 count=110862026/09/22 10:44:42 INFO Uploading 1 narinfos10872026/09/22 10:44:42 WARN Failed to register uploaded object key=m0vbyyxgmhbk6p95v1g77gmg2kmi7drn.ls error="server returned 404: 404 page not found\n"10882026/09/22 10:44:42 OK 1_commit_pending_closure.sql (2.11ms)10892026/09/22 10:44:42 OK 1_commit_pending_closure.sql (1.22ms)10902026/09/22 10:44:42 OK 2_object_stats_trigger.sql (402.21µs)10912026/09/22 10:44:42 goose: up to current file version: 210922026/09/22 10:44:42 OK 2_object_stats_trigger.sql (291.29µs)10932026/09/22 10:44:42 goose: up to current file version: 210942026/09/22 10:44:42 OK 20241026095416_initial_model.sql (62.72ms)10952026/09/22 10:44:42 OK 20251210153512_drop_unused_gin_index.sql (6.8ms)10962026/09/22 10:44:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10972026/09/22 10:44:42 WARN Failed to register uploaded object key=m0vbyyxgmhbk6p95v1g77gmg2kmi7drn.narinfo error="server returned 404: 404 page not found\n"10982026/09/22 10:44:42 INFO Completed upload id=210992026/09/22 10:44:42 INFO Upload complete. (68ms)1100 metadata_upload_test.go:76: Retrieved narinfo from S3:1101 StorePath: /nix/var/nix/builds/nix-28854-4210868838/TestNARDeduplicationMetadataUploadBug1255628358/001/store/m0vbyyxgmhbk6p95v1g77gmg2kmi7drn-file2.txt1102 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1103 Compression: zstd1104 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1105 NarSize: 1601106 References: 1107 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1108 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1109 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1110 {"version":1,"root":{"type":"regular","size":44}}11112026/09/22 10:44:42 OK 20251218171726_add_pins.sql (23.97ms)11122026/09/22 10:44:42 OK 20260628120000_add_object_size_and_stats.sql (25.18ms)1113--- PASS: TestNARDeduplicationMetadataUploadBug (2.62s)1114=== CONT TestIsValidUploadKey1115=== RUN TestIsValidUploadKey/narinfo1116=== PAUSE TestIsValidUploadKey/narinfo1117=== RUN TestIsValidUploadKey/nar_zst1118=== PAUSE TestIsValidUploadKey/nar_zst1119=== RUN TestIsValidUploadKey/nar_xz1120=== PAUSE TestIsValidUploadKey/nar_xz1121=== RUN TestIsValidUploadKey/nar_plain1122=== PAUSE TestIsValidUploadKey/nar_plain1123=== RUN TestIsValidUploadKey/listing1124=== PAUSE TestIsValidUploadKey/listing1125=== RUN TestIsValidUploadKey/build_log1126=== PAUSE TestIsValidUploadKey/build_log1127=== RUN TestIsValidUploadKey/build_log_home-manager_file1128=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1129=== RUN TestIsValidUploadKey/build_log_plus_in_name1130=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1131=== RUN TestIsValidUploadKey/build_log_question_mark1132=== PAUSE TestIsValidUploadKey/build_log_question_mark1133=== RUN TestIsValidUploadKey/build_log_equals1134=== PAUSE TestIsValidUploadKey/build_log_equals1135=== RUN TestIsValidUploadKey/realisation1136=== PAUSE TestIsValidUploadKey/realisation1137=== RUN TestIsValidUploadKey/realisation_plus_in_output1138=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1139=== RUN TestIsValidUploadKey/nix-cache-info1140=== PAUSE TestIsValidUploadKey/nix-cache-info1141=== RUN TestIsValidUploadKey/index.html1142=== PAUSE TestIsValidUploadKey/index.html1143=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1144=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1145=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1146=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1147=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1148=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1149=== RUN TestIsValidUploadKey/traversal1150=== PAUSE TestIsValidUploadKey/traversal1151=== RUN TestIsValidUploadKey/traversal_nar1152=== PAUSE TestIsValidUploadKey/traversal_nar1153=== RUN TestIsValidUploadKey/absolute1154=== PAUSE TestIsValidUploadKey/absolute1155=== RUN TestIsValidUploadKey/empty_key1156=== PAUSE TestIsValidUploadKey/empty_key1157=== RUN TestIsValidUploadKey/unknown_type1158=== PAUSE TestIsValidUploadKey/unknown_type1159=== CONT TestReadProxyNarinfoAlreadyDecompressed1160--- PASS: TestReadProxyNarStreaming (1.92s)1161=== CONT TestReadProxyNarinfo11622026/09/22 10:44:42 OK 20260905000000_add_claims.sql (28.54ms)11632026/09/22 10:44:42 OK 20260920000000_drop_claims.sql (19.43ms)11642026/09/22 10:44:42 goose: successfully migrated database to version: 2026092000000011652026/09/22 10:44:42 OK 1_commit_pending_closure.sql (21.79ms)11662026/09/22 10:44:42 OK 2_object_stats_trigger.sql (258.25µs)11672026/09/22 10:44:42 goose: up to current file version: 21168--- PASS: TestReadRedirectNar (1.70s)1169=== CONT TestIsValidCachePath1170=== RUN TestIsValidCachePath/narinfo1171=== PAUSE TestIsValidCachePath/narinfo1172=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1173=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1174=== RUN TestIsValidCachePath/nar_zst1175=== PAUSE TestIsValidCachePath/nar_zst1176=== RUN TestIsValidCachePath/nar_xz1177=== PAUSE TestIsValidCachePath/nar_xz1178=== RUN TestIsValidCachePath/nar_bz21179=== PAUSE TestIsValidCachePath/nar_bz21180=== RUN TestIsValidCachePath/nar_uncompressed1181=== PAUSE TestIsValidCachePath/nar_uncompressed1182=== RUN TestIsValidCachePath/ls1183=== PAUSE TestIsValidCachePath/ls1184=== RUN TestIsValidCachePath/log1185=== PAUSE TestIsValidCachePath/log1186=== RUN TestIsValidCachePath/realisation1187=== PAUSE TestIsValidCachePath/realisation1188=== RUN TestIsValidCachePath/nix-cache-info1189=== PAUSE TestIsValidCachePath/nix-cache-info1190=== RUN TestIsValidCachePath/index.html1191=== PAUSE TestIsValidCachePath/index.html1192=== RUN TestIsValidCachePath/traversal_parent1193=== PAUSE TestIsValidCachePath/traversal_parent1194=== RUN TestIsValidCachePath/traversal_in_middle1195=== PAUSE TestIsValidCachePath/traversal_in_middle1196=== RUN TestIsValidCachePath/invalid_char_e1197=== PAUSE TestIsValidCachePath/invalid_char_e1198=== RUN TestIsValidCachePath/invalid_char_u1199=== PAUSE TestIsValidCachePath/invalid_char_u1200=== RUN TestIsValidCachePath/random_path1201=== PAUSE TestIsValidCachePath/random_path1202=== RUN TestIsValidCachePath/empty1203=== PAUSE TestIsValidCachePath/empty1204=== RUN TestIsValidCachePath/leading_slash1205=== PAUSE TestIsValidCachePath/leading_slash1206=== RUN TestIsValidCachePath/wrong_extension1207=== PAUSE TestIsValidCachePath/wrong_extension1208=== RUN TestIsValidCachePath/short_hash1209=== PAUSE TestIsValidCachePath/short_hash1210=== CONT TestParseSingleRange1211=== RUN TestParseSingleRange/none1212=== PAUSE TestParseSingleRange/none1213=== RUN TestParseSingleRange/unknown_unit1214=== PAUSE TestParseSingleRange/unknown_unit1215=== RUN TestParseSingleRange/multi-range_ignored1216=== PAUSE TestParseSingleRange/multi-range_ignored1217=== RUN TestParseSingleRange/malformed_no_dash1218=== PAUSE TestParseSingleRange/malformed_no_dash1219=== RUN TestParseSingleRange/malformed_both_empty1220=== PAUSE TestParseSingleRange/malformed_both_empty1221=== RUN TestParseSingleRange/malformed_end_before_start1222=== PAUSE TestParseSingleRange/malformed_end_before_start1223=== RUN TestParseSingleRange/closed1224=== PAUSE TestParseSingleRange/closed1225=== RUN TestParseSingleRange/open-ended1226=== PAUSE TestParseSingleRange/open-ended1227=== RUN TestParseSingleRange/end_clamped_to_size1228=== PAUSE TestParseSingleRange/end_clamped_to_size1229=== RUN TestParseSingleRange/suffix1230=== PAUSE TestParseSingleRange/suffix1231=== RUN TestParseSingleRange/suffix_exceeds_size1232=== PAUSE TestParseSingleRange/suffix_exceeds_size1233=== RUN TestParseSingleRange/single_byte1234=== PAUSE TestParseSingleRange/single_byte1235=== RUN TestParseSingleRange/start_past_EOF1236=== PAUSE TestParseSingleRange/start_past_EOF1237=== RUN TestParseSingleRange/start_far_past_EOF1238=== PAUSE TestParseSingleRange/start_far_past_EOF1239=== CONT TestCreatePin_ReservedPins12402026/09/22 10:44:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56696/oidc1241--- PASS: TestReadRedirectKeepsNarinfoProxied (2.00s)1242=== CONT TestResurrectedObjectNotDeleted12432026-09-22 10:44:43.003 UTC [29300] ERROR: relation "goose_db_version" does not exist at character 3612442026-09-22 10:44:43.003 UTC [29300] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1245--- PASS: TestReadProxyDisabled (1.80s)1246=== CONT TestOrphanedObjectsGCStressTest12472026/09/22 10:44:43 OK 20241026095416_initial_model.sql (65.09ms)12482026-09-22 10:44:43.100 UTC [29353] ERROR: relation "goose_db_version" does not exist at character 3612492026-09-22 10:44:43.100 UTC [29353] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12502026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (881.33µs)12512026/09/22 10:44:43 OK 20251218171726_add_pins.sql (12.73ms)12522026-09-22 10:44:43.121 UTC [29389] ERROR: relation "goose_db_version" does not exist at character 3612532026-09-22 10:44:43.121 UTC [29389] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12542026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (14.11ms)12552026/09/22 10:44:43 OK 20260905000000_add_claims.sql (3.61ms)12562026/09/22 10:44:43 OK 20241026095416_initial_model.sql (9.24ms)12572026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (705.88µs)12582026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (2.31ms)12592026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000012602026/09/22 10:44:43 OK 1_commit_pending_closure.sql (5.42ms)12612026/09/22 10:44:43 OK 20251218171726_add_pins.sql (7.03ms)12622026/09/22 10:44:43 OK 2_object_stats_trigger.sql (865.75µs)12632026/09/22 10:44:43 goose: up to current file version: 212642026/09/22 10:44:43 OK 20241026095416_initial_model.sql (9.86ms)12652026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (700.5µs)12662026/09/22 10:44:43 OK 20251218171726_add_pins.sql (890.08µs)12672026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (30.48ms)12682026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (28.13ms)12692026/09/22 10:44:43 OK 20260905000000_add_claims.sql (11.25ms)12702026/09/22 10:44:43 OK 20260905000000_add_claims.sql (12.47ms)12712026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (4.01ms)12722026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000012732026/09/22 10:44:43 OK 1_commit_pending_closure.sql (1.56ms)12742026/09/22 10:44:43 OK 2_object_stats_trigger.sql (605.29µs)12752026/09/22 10:44:43 goose: up to current file version: 212762026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (17.78ms)12772026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000012782026/09/22 10:44:43 OK 1_commit_pending_closure.sql (2.6ms)12792026/09/22 10:44:43 OK 2_object_stats_trigger.sql (458µs)12802026/09/22 10:44:43 goose: up to current file version: 212812026-09-22 10:44:43.253 UTC [29464] ERROR: relation "goose_db_version" does not exist at character 3612822026-09-22 10:44:43.253 UTC [29464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1283--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.48s)1284=== CONT TestOrphanedObjectsGC12852026/09/22 10:44:43 OK 20241026095416_initial_model.sql (77.12ms)12862026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)12872026/09/22 10:44:43 OK 20251218171726_add_pins.sql (23.27ms)12882026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (26.42ms)12892026/09/22 10:44:43 OK 20260905000000_add_claims.sql (24.36ms)1290--- PASS: TestReadProxyHead (1.35s)1291=== CONT TestObjectStatsTrigger12922026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (30.86ms)12932026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000012942026/09/22 10:44:43 OK 1_commit_pending_closure.sql (2.1ms)12952026/09/22 10:44:43 OK 2_object_stats_trigger.sql (244.46µs)12962026/09/22 10:44:43 goose: up to current file version: 212972026-09-22 10:44:43.516 UTC [29525] ERROR: relation "goose_db_version" does not exist at character 3612982026-09-22 10:44:43.516 UTC [29525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1299--- PASS: TestReadProxyConditionalGet (1.61s)1300=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13012026-09-22 10:44:43.713 UTC [29587] ERROR: relation "goose_db_version" does not exist at character 3613022026-09-22 10:44:43.713 UTC [29587] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13032026-09-22 10:44:43.713 UTC [29575] ERROR: relation "goose_db_version" does not exist at character 3613042026-09-22 10:44:43.713 UTC [29575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13052026/09/22 10:44:43 OK 20241026095416_initial_model.sql (155.14ms)13062026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (3.25ms)13072026/09/22 10:44:43 OK 20251218171726_add_pins.sql (16.86ms)13082026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (20.7ms)13092026/09/22 10:44:43 OK 20260905000000_add_claims.sql (31.52ms)1310--- PASS: TestReadProxyInvalidPath (1.52s)1311=== CONT TestParseSize1312--- PASS: TestParseSize (0.00s)1313=== CONT TestService_Rustfstest13142026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (14.9ms)13152026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000013162026/09/22 10:44:43 OK 1_commit_pending_closure.sql (1.74ms)13172026/09/22 10:44:43 OK 2_object_stats_trigger.sql (597.63µs)13182026/09/22 10:44:43 goose: up to current file version: 213192026/09/22 10:44:43 OK 20241026095416_initial_model.sql (81.23ms)13202026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (10.92ms)13212026/09/22 10:44:43 OK 20251218171726_add_pins.sql (7.64ms)13222026/09/22 10:44:43 OK 20241026095416_initial_model.sql (100.27ms)13232026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (6.51ms)13242026-09-22 10:44:43.856 UTC [29642] ERROR: relation "goose_db_version" does not exist at character 3613252026-09-22 10:44:43.856 UTC [29642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13262026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (16.81ms)13272026/09/22 10:44:43 OK 20251218171726_add_pins.sql (9.98ms)13282026/09/22 10:44:43 OK 20260905000000_add_claims.sql (17.26ms)13292026/09/22 10:44:43 OK 20260628120000_add_object_size_and_stats.sql (16.73ms)13302026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (9.75ms)13312026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000013322026-09-22 10:44:43.885 UTC [29647] ERROR: relation "goose_db_version" does not exist at character 3613332026-09-22 10:44:43.885 UTC [29647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13342026/09/22 10:44:43 OK 1_commit_pending_closure.sql (2.05ms)13352026/09/22 10:44:43 OK 2_object_stats_trigger.sql (544.67µs)13362026/09/22 10:44:43 goose: up to current file version: 213372026/09/22 10:44:43 OK 20260905000000_add_claims.sql (18.76ms)13382026/09/22 10:44:43 OK 20260920000000_drop_claims.sql (11ms)13392026/09/22 10:44:43 goose: successfully migrated database to version: 2026092000000013402026/09/22 10:44:43 OK 1_commit_pending_closure.sql (2.24ms)13412026/09/22 10:44:43 OK 2_object_stats_trigger.sql (581.38µs)13422026/09/22 10:44:43 goose: up to current file version: 213432026/09/22 10:44:43 OK 20241026095416_initial_model.sql (65.5ms)1344--- PASS: TestReadProxy404 (1.51s)1345=== CONT TestService_RequireScope_OIDC13462026/09/22 10:44:43 OK 20251210153512_drop_unused_gin_index.sql (8.1ms)13472026/09/22 10:44:43 OK 20241026095416_initial_model.sql (74.71ms)13482026/09/22 10:44:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56742/oidc13492026/09/22 10:44:44 OK 20251210153512_drop_unused_gin_index.sql (12.95ms)13502026/09/22 10:44:44 OK 20251218171726_add_pins.sql (28.97ms)13512026-09-22 10:44:44.015 UTC [29669] ERROR: relation "goose_db_version" does not exist at character 3613522026-09-22 10:44:44.015 UTC [29669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13532026/09/22 10:44:44 OK 20251218171726_add_pins.sql (15.47ms)13542026/09/22 10:44:44 OK 20260628120000_add_object_size_and_stats.sql (15.85ms)13552026/09/22 10:44:44 OK 20260628120000_add_object_size_and_stats.sql (12.25ms)13562026/09/22 10:44:44 OK 20260905000000_add_claims.sql (6.26ms)13572026/09/22 10:44:44 OK 20260920000000_drop_claims.sql (12.91ms)13582026/09/22 10:44:44 goose: successfully migrated database to version: 2026092000000013592026/09/22 10:44:44 OK 20260905000000_add_claims.sql (14.42ms)13602026/09/22 10:44:44 OK 1_commit_pending_closure.sql (2.01ms)13612026/09/22 10:44:44 OK 2_object_stats_trigger.sql (509.83µs)13622026/09/22 10:44:44 goose: up to current file version: 213632026/09/22 10:44:44 OK 20260920000000_drop_claims.sql (14.61ms)13642026/09/22 10:44:44 goose: successfully migrated database to version: 2026092000000013652026/09/22 10:44:44 OK 1_commit_pending_closure.sql (2ms)13662026/09/22 10:44:44 OK 2_object_stats_trigger.sql (448µs)13672026/09/22 10:44:44 goose: up to current file version: 213682026/09/22 10:44:44 OK 20241026095416_initial_model.sql (63.15ms)13692026/09/22 10:44:44 OK 20251210153512_drop_unused_gin_index.sql (7.99ms)13702026/09/22 10:44:44 OK 20251218171726_add_pins.sql (10.46ms)1371--- PASS: TestReadProxyNarinfo (1.50s)1372=== CONT TestClientCADerivations13732026/09/22 10:44:44 OK 20260628120000_add_object_size_and_stats.sql (37.11ms)13742026/09/22 10:44:44 OK 20260905000000_add_claims.sql (62.26ms)13752026/09/22 10:44:44 OK 20260920000000_drop_claims.sql (24.01ms)13762026/09/22 10:44:44 goose: successfully migrated database to version: 2026092000000013772026/09/22 10:44:44 OK 1_commit_pending_closure.sql (1.45ms)13782026/09/22 10:44:44 OK 2_object_stats_trigger.sql (616µs)13792026/09/22 10:44:44 goose: up to current file version: 213802026-09-22 10:44:44.300 UTC [29816] ERROR: relation "goose_db_version" does not exist at character 3613812026-09-22 10:44:44.300 UTC [29816] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1382--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.68s)1383=== CONT TestCacheStatsHandler13842026/09/22 10:44:44 OK 20241026095416_initial_model.sql (105.54ms)13852026/09/22 10:44:44 OK 20251210153512_drop_unused_gin_index.sql (5.41ms)13862026/09/22 10:44:44 OK 20251218171726_add_pins.sql (23.05ms)13872026/09/22 10:44:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13882026/09/22 10:44:44 WARN Refused reserved pin name=worker-x86_64-linux13892026/09/22 10:44:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13902026/09/22 10:44:44 INFO Received create pin request method=POST path=/api/pins/my-app13912026/09/22 10:44:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1392--- PASS: TestCreatePin_ReservedPins (1.70s)1393=== CONT TestClientErrorHandling1394=== RUN TestClientErrorHandling/InvalidStorePath1395=== PAUSE TestClientErrorHandling/InvalidStorePath1396=== RUN TestClientErrorHandling/InvalidAuthToken1397=== PAUSE TestClientErrorHandling/InvalidAuthToken1398=== RUN TestClientErrorHandling/ServerNotAvailable1399=== PAUSE TestClientErrorHandling/ServerNotAvailable1400=== CONT TestCacheConfigHandler1401=== RUN TestCacheConfigHandler/full_config,_no_issuer1402=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1403=== RUN TestCacheConfigHandler/no_cache_url_configured1404=== PAUSE TestCacheConfigHandler/no_cache_url_configured1405=== RUN TestCacheConfigHandler/no_signing_keys1406=== PAUSE TestCacheConfigHandler/no_signing_keys1407=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1408=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1409=== CONT TestGCBugBareHashReferences14102026/09/22 10:44:44 OK 20260628120000_add_object_size_and_stats.sql (46.19ms)14112026-09-22 10:44:44.573 UTC [29884] ERROR: relation "goose_db_version" does not exist at character 3614122026-09-22 10:44:44.573 UTC [29884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14132026/09/22 10:44:44 OK 20260905000000_add_claims.sql (57.7ms)14142026-09-22 10:44:44.592 UTC [29905] ERROR: relation "goose_db_version" does not exist at character 3614152026-09-22 10:44:44.592 UTC [29905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14162026/09/22 10:44:44 OK 20260920000000_drop_claims.sql (14.58ms)14172026/09/22 10:44:44 goose: successfully migrated database to version: 2026092000000014182026/09/22 10:44:44 OK 1_commit_pending_closure.sql (1.01ms)14192026/09/22 10:44:44 OK 2_object_stats_trigger.sql (367.92µs)14202026/09/22 10:44:44 goose: up to current file version: 214212026/09/22 10:44:44 OK 20241026095416_initial_model.sql (146.44ms)14222026/09/22 10:44:44 OK 20251210153512_drop_unused_gin_index.sql (16.42ms)14232026/09/22 10:44:44 OK 20241026095416_initial_model.sql (161.12ms)14242026/09/22 10:44:44 OK 20251218171726_add_pins.sql (27.71ms)14252026/09/22 10:44:44 OK 20251210153512_drop_unused_gin_index.sql (6.87ms)14262026/09/22 10:44:44 OK 20251218171726_add_pins.sql (6.86ms)14272026/09/22 10:44:44 OK 20260628120000_add_object_size_and_stats.sql (19.38ms)1428--- PASS: TestResurrectedObjectNotDeleted (1.89s)1429=== CONT TestService_ReadScope_PublicByDefault14302026/09/22 10:44:44 OK 20260628120000_add_object_size_and_stats.sql (45.97ms)14312026/09/22 10:44:44 OK 20260905000000_add_claims.sql (59.78ms)14322026/09/22 10:44:44 OK 20260920000000_drop_claims.sql (18.85ms)14332026/09/22 10:44:44 goose: successfully migrated database to version: 2026092000000014342026/09/22 10:44:44 OK 1_commit_pending_closure.sql (946.21µs)14352026/09/22 10:44:44 OK 2_object_stats_trigger.sql (240.88µs)14362026/09/22 10:44:44 goose: up to current file version: 214372026/09/22 10:44:44 OK 20260905000000_add_claims.sql (53.01ms)14382026/09/22 10:44:44 OK 20260920000000_drop_claims.sql (8.76ms)14392026/09/22 10:44:44 goose: successfully migrated database to version: 2026092000000014402026/09/22 10:44:44 OK 1_commit_pending_closure.sql (1.78ms)14412026/09/22 10:44:44 OK 2_object_stats_trigger.sql (456.83µs)14422026/09/22 10:44:44 goose: up to current file version: 214432026-09-22 10:44:45.019 UTC [30002] ERROR: relation "goose_db_version" does not exist at character 3614442026-09-22 10:44:45.019 UTC [30002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14452026/09/22 10:44:45 OK 20241026095416_initial_model.sql (184.26ms)14462026/09/22 10:44:45 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)14472026/09/22 10:44:45 OK 20251218171726_add_pins.sql (30.6ms)14482026/09/22 10:44:45 OK 20260628120000_add_object_size_and_stats.sql (31.4ms)14492026/09/22 10:44:45 OK 20260905000000_add_claims.sql (22.02ms)14502026/09/22 10:44:45 OK 20260920000000_drop_claims.sql (40.69ms)14512026/09/22 10:44:45 goose: successfully migrated database to version: 2026092000000014522026/09/22 10:44:45 OK 1_commit_pending_closure.sql (1.62ms)14532026/09/22 10:44:45 OK 2_object_stats_trigger.sql (545.88µs)14542026/09/22 10:44:45 goose: up to current file version: 21455--- PASS: TestObjectStatsTrigger (1.97s)1456=== CONT TestLeadEndsOnShutdown14572026-09-22 10:44:45.532 UTC [30151] ERROR: relation "goose_db_version" does not exist at character 3614582026-09-22 10:44:45.532 UTC [30151] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14592026/09/22 10:44:45 INFO Received uploads request method=POST path=/api/pending_closures14602026-09-22 10:44:45.608 UTC [30175] ERROR: relation "goose_db_version" does not exist at character 3614612026-09-22 10:44:45.608 UTC [30175] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14622026/09/22 10:44:45 OK 20241026095416_initial_model.sql (177.53ms)14632026/09/22 10:44:45 OK 20251210153512_drop_unused_gin_index.sql (5.16ms)14642026/09/22 10:44:45 OK 20251218171726_add_pins.sql (48.94ms)14652026-09-22 10:44:45.850 UTC [30209] ERROR: relation "goose_db_version" does not exist at character 3614662026-09-22 10:44:45.850 UTC [30209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14672026/09/22 10:44:45 OK 20260628120000_add_object_size_and_stats.sql (34.68ms)1468--- PASS: TestService_Rustfstest (2.08s)1469=== CONT TestService_ReadAuthMiddleware14702026/09/22 10:44:45 OK 20241026095416_initial_model.sql (206.91ms)14712026/09/22 10:44:45 OK 20251210153512_drop_unused_gin_index.sql (13.72ms)1472=== NAME TestOrphanedObjectsGC1473 orphaned_objects_gc_test.go:290: GC Test Summary:1474 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1475 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1476 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1477 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1478 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1479--- PASS: TestOrphanedObjectsGC (2.62s)1480=== CONT TestService_AuthMiddleware_OIDC14812026/09/22 10:44:45 OK 20260905000000_add_claims.sql (80.11ms)14822026/09/22 10:44:45 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56793/oidc14832026/09/22 10:44:45 OK 20251218171726_add_pins.sql (36.36ms)14842026/09/22 10:44:45 OK 20260920000000_drop_claims.sql (41.19ms)14852026/09/22 10:44:45 goose: successfully migrated database to version: 2026092000000014862026/09/22 10:44:45 OK 20260628120000_add_object_size_and_stats.sql (34.59ms)14872026/09/22 10:44:45 OK 1_commit_pending_closure.sql (3.96ms)14882026/09/22 10:44:45 OK 2_object_stats_trigger.sql (652.54µs)14892026/09/22 10:44:45 goose: up to current file version: 214902026/09/22 10:44:45 OK 20260905000000_add_claims.sql (12.44ms)14912026/09/22 10:44:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14922026/09/22 10:44:46 OK 20260920000000_drop_claims.sql (73.6ms)14932026/09/22 10:44:46 goose: successfully migrated database to version: 2026092000000014942026/09/22 10:44:46 OK 1_commit_pending_closure.sql (1.02ms)14952026/09/22 10:44:46 OK 2_object_stats_trigger.sql (288.08µs)14962026/09/22 10:44:46 goose: up to current file version: 214972026/09/22 10:44:46 OK 20241026095416_initial_model.sql (181.41ms)14982026-09-22 10:44:46.098 UTC [30278] ERROR: relation "goose_db_version" does not exist at character 3614992026-09-22 10:44:46.098 UTC [30278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15002026/09/22 10:44:46 OK 20251210153512_drop_unused_gin_index.sql (7.61ms)15012026/09/22 10:44:46 OK 20251218171726_add_pins.sql (26ms)15022026/09/22 10:44:46 OK 20260628120000_add_object_size_and_stats.sql (32.1ms)15032026/09/22 10:44:46 OK 20260905000000_add_claims.sql (59.72ms)1504=== RUN TestService_RequireScope_OIDC/builder_may_write1505=== PAUSE TestService_RequireScope_OIDC/builder_may_write1506=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1507=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1508=== RUN TestService_RequireScope_OIDC/ops_may_admin1509=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1510=== RUN TestService_RequireScope_OIDC/ops_may_not_write1511=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1512=== RUN TestService_RequireScope_OIDC/reader_may_not_write1513=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1514=== RUN TestService_RequireScope_OIDC/static_token_may_admin1515=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1516=== RUN TestService_RequireScope_OIDC/static_token_may_write1517=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1518=== RUN TestService_RequireScope_OIDC/reader_may_read1519=== PAUSE TestService_RequireScope_OIDC/reader_may_read1520=== RUN TestService_RequireScope_OIDC/writer_implies_read1521=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1522=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1523=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1524=== CONT TestClientWithDependencies15252026/09/22 10:44:46 OK 20260920000000_drop_claims.sql (41.13ms)15262026/09/22 10:44:46 goose: successfully migrated database to version: 2026092000000015272026/09/22 10:44:46 OK 1_commit_pending_closure.sql (1.4ms)15282026/09/22 10:44:46 OK 2_object_stats_trigger.sql (323.46µs)15292026/09/22 10:44:46 goose: up to current file version: 215302026/09/22 10:44:46 OK 20241026095416_initial_model.sql (218.86ms)15312026/09/22 10:44:46 OK 20251210153512_drop_unused_gin_index.sql (3.39ms)15322026/09/22 10:44:46 OK 20251218171726_add_pins.sql (43.26ms)15332026/09/22 10:44:46 OK 20260628120000_add_object_size_and_stats.sql (40.6ms)15342026-09-22 10:44:46.479 UTC [30359] ERROR: relation "goose_db_version" does not exist at character 3615352026-09-22 10:44:46.479 UTC [30359] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15362026/09/22 10:44:46 OK 20260905000000_add_claims.sql (43.75ms)15372026/09/22 10:44:46 OK 20260920000000_drop_claims.sql (15.43ms)15382026/09/22 10:44:46 goose: successfully migrated database to version: 2026092000000015392026/09/22 10:44:46 OK 1_commit_pending_closure.sql (1.66ms)15402026/09/22 10:44:46 OK 2_object_stats_trigger.sql (500.46µs)15412026/09/22 10:44:46 goose: up to current file version: 215422026/09/22 10:44:46 OK 20241026095416_initial_model.sql (208.76ms)15432026/09/22 10:44:46 OK 20251210153512_drop_unused_gin_index.sql (10.37ms)1544--- PASS: TestCacheStatsHandler (2.47s)1545=== CONT TestClientMultipleUploads15462026/09/22 10:44:46 OK 20251218171726_add_pins.sql (35.45ms)15472026/09/22 10:44:46 OK 20260628120000_add_object_size_and_stats.sql (31.65ms)15482026/09/22 10:44:46 OK 20260905000000_add_claims.sql (52.07ms)15492026/09/22 10:44:46 OK 20260920000000_drop_claims.sql (22.2ms)15502026/09/22 10:44:46 goose: successfully migrated database to version: 2026092000000015512026/09/22 10:44:46 OK 1_commit_pending_closure.sql (1.57ms)15522026/09/22 10:44:46 OK 2_object_stats_trigger.sql (408.08µs)15532026/09/22 10:44:46 goose: up to current file version: 21554=== NAME TestClientCADerivations1555 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-28854-4210868838/TestClientCADerivations1499386230/001/store/sfyrxxqldizink6x5rzqbwyjmi3y9nws-ca-test1556 client_ca_test.go:139: Found 1 dependencies (including self)1557--- PASS: TestService_ReadScope_PublicByDefault (2.36s)1558=== CONT TestClientIntegration15592026/09/22 10:44:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1560--- PASS: TestGCBugBareHashReferences (2.72s)1561=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15622026/09/22 10:44:47 INFO Received uploads request method=POST path=/api/pending_closures15632026-09-22 10:44:47.251 UTC [30548] ERROR: relation "goose_db_version" does not exist at character 3615642026-09-22 10:44:47.251 UTC [30548] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15652026/09/22 10:44:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15662026/09/22 10:44:47 INFO Uploading sfyrxxqldizink6x5rzqbwyjmi3y9nws-ca-test (144B)15672026/09/22 10:44:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15682026/09/22 10:44:47 WARN Failed to register uploaded object key=log/qxvsdp60460dd4q5sahpj2w37bin6y8l-ca-test.drv error="server returned 404: 404 page not found\n"15692026/09/22 10:44:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15702026/09/22 10:44:47 WARN Failed to register uploaded object key=sfyrxxqldizink6x5rzqbwyjmi3y9nws.ls error="server returned 404: 404 page not found\n"15712026/09/22 10:44:47 INFO Signed narinfos id=1 count=115722026/09/22 10:44:47 INFO Uploading 1 narinfos15732026/09/22 10:44:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15742026/09/22 10:44:47 WARN Failed to register uploaded object key=sfyrxxqldizink6x5rzqbwyjmi3y9nws.narinfo error="server returned 404: 404 page not found\n"15752026/09/22 10:44:47 INFO Completed upload id=115762026/09/22 10:44:47 INFO Upload complete. (225ms)1577=== NAME TestClientCADerivations1578 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-28854-4210868838/TestClientCADerivations1499386230/001/store/sfyrxxqldizink6x5rzqbwyjmi3y9nws-ca-test1579 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1580 Compression: zstd1581 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1582 NarSize: 1441583 References: 1584 Deriver: /nix/var/nix/builds/nix-28854-4210868838/TestClientCADerivations1499386230/001/store/qxvsdp60460dd4q5sahpj2w37bin6y8l-ca-test.drv1585 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1586 client_ca_test.go:185: Checking for realisation files in S3...1587 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1588 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15892026/09/22 10:44:47 OK 20241026095416_initial_model.sql (125.49ms)15902026/09/22 10:44:47 OK 20251210153512_drop_unused_gin_index.sql (13.9ms)1591 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket40?endpoint=http://localhost:56521®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-28854-4210868838/TestClientCADerivations1499386230/001/store'1592 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115932026/09/22 10:44:47 OK 20251218171726_add_pins.sql (14.92ms)1594--- PASS: TestClientCADerivations (3.42s)1595=== CONT TestResolveDBConnectionString1596=== RUN TestResolveDBConnectionString/flag_wins1597=== PAUSE TestResolveDBConnectionString/flag_wins1598=== RUN TestResolveDBConnectionString/file_when_flag_empty1599=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1600=== RUN TestResolveDBConnectionString/missing_file_is_an_error1601=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1602=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1603=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1604=== RUN TestResolveDBConnectionString/nothing_configured1605=== PAUSE TestResolveDBConnectionString/nothing_configured1606=== CONT TestLeadElectsOneAndHandsOver16072026/09/22 10:44:47 OK 20260628120000_add_object_size_and_stats.sql (93.54ms)16082026/09/22 10:44:47 OK 20260905000000_add_claims.sql (65.47ms)16092026-09-22 10:44:47.652 UTC [30638] ERROR: relation "goose_db_version" does not exist at character 3616102026-09-22 10:44:47.652 UTC [30638] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16112026-09-22 10:44:47.652 UTC [30635] ERROR: relation "goose_db_version" does not exist at character 3616122026-09-22 10:44:47.652 UTC [30635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16132026/09/22 10:44:47 OK 20260920000000_drop_claims.sql (16.19ms)16142026/09/22 10:44:47 goose: successfully migrated database to version: 2026092000000016152026/09/22 10:44:47 OK 1_commit_pending_closure.sql (2.62ms)16162026/09/22 10:44:47 OK 2_object_stats_trigger.sql (428.71µs)16172026/09/22 10:44:47 goose: up to current file version: 216182026/09/22 10:44:47 OK 20241026095416_initial_model.sql (191.33ms)16192026/09/22 10:44:47 INFO lead: acquired remote=192.0.2.1:123416202026/09/22 10:44:47 INFO lead: released remote=192.0.2.1:12341621--- PASS: TestLeadEndsOnShutdown (2.49s)1622=== CONT TestClientSharedPathCommittedMidPush16232026/09/22 10:44:47 OK 20251210153512_drop_unused_gin_index.sql (13.29ms)16242026/09/22 10:44:47 OK 20241026095416_initial_model.sql (211.38ms)16252026/09/22 10:44:47 OK 20251210153512_drop_unused_gin_index.sql (8.66ms)16262026/09/22 10:44:47 OK 20251218171726_add_pins.sql (29.05ms)16272026/09/22 10:44:47 OK 20251218171726_add_pins.sql (27.03ms)16282026/09/22 10:44:47 OK 20260628120000_add_object_size_and_stats.sql (24.92ms)16292026/09/22 10:44:47 OK 20260628120000_add_object_size_and_stats.sql (29.06ms)16302026/09/22 10:44:48 OK 20260905000000_add_claims.sql (50.03ms)16312026/09/22 10:44:48 OK 20260905000000_add_claims.sql (33.46ms)16322026/09/22 10:44:48 OK 20260920000000_drop_claims.sql (21.38ms)16332026/09/22 10:44:48 goose: successfully migrated database to version: 2026092000000016342026/09/22 10:44:48 OK 1_commit_pending_closure.sql (1.51ms)16352026/09/22 10:44:48 OK 2_object_stats_trigger.sql (309.25µs)16362026/09/22 10:44:48 goose: up to current file version: 216372026/09/22 10:44:48 OK 20260920000000_drop_claims.sql (23.41ms)16382026/09/22 10:44:48 goose: successfully migrated database to version: 2026092000000016392026-09-22 10:44:48.042 UTC [30710] ERROR: relation "goose_db_version" does not exist at character 3616402026-09-22 10:44:48.042 UTC [30710] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16412026/09/22 10:44:48 OK 1_commit_pending_closure.sql (3.25ms)16422026/09/22 10:44:48 OK 2_object_stats_trigger.sql (589.5µs)16432026/09/22 10:44:48 goose: up to current file version: 216442026/09/22 10:44:48 OK 20241026095416_initial_model.sql (131.41ms)16452026/09/22 10:44:48 OK 20251210153512_drop_unused_gin_index.sql (12.35ms)16462026/09/22 10:44:48 OK 20251218171726_add_pins.sql (22.82ms)1647=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1648=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1649=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1650=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1651=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1652=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1653=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1654=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1655=== CONT TestService_AuthMiddleware_MTLSProxyHeader16562026/09/22 10:44:48 OK 20260628120000_add_object_size_and_stats.sql (9.98ms)16572026/09/22 10:44:48 OK 20260905000000_add_claims.sql (65.93ms)16582026/09/22 10:44:48 OK 20260920000000_drop_claims.sql (24.96ms)16592026/09/22 10:44:48 goose: successfully migrated database to version: 2026092000000016602026/09/22 10:44:48 OK 1_commit_pending_closure.sql (1.87ms)16612026/09/22 10:44:48 OK 2_object_stats_trigger.sql (564.13µs)16622026/09/22 10:44:48 goose: up to current file version: 216632026-09-22 10:44:48.444 UTC [30724] ERROR: relation "goose_db_version" does not exist at character 3616642026-09-22 10:44:48.444 UTC [30724] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1665--- PASS: TestService_ReadAuthMiddleware (2.67s)1666=== CONT TestPinProtectsFromGC16672026/09/22 10:44:48 OK 20241026095416_initial_model.sql (130.44ms)16682026/09/22 10:44:48 OK 20251210153512_drop_unused_gin_index.sql (8.67ms)16692026/09/22 10:44:48 OK 20251218171726_add_pins.sql (12.59ms)16702026-09-22 10:44:48.657 UTC [30731] ERROR: relation "goose_db_version" does not exist at character 3616712026-09-22 10:44:48.657 UTC [30731] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16722026/09/22 10:44:48 OK 20260628120000_add_object_size_and_stats.sql (26.7ms)16732026/09/22 10:44:48 OK 20260905000000_add_claims.sql (31.24ms)16742026-09-22 10:44:48.703 UTC [30732] ERROR: relation "goose_db_version" does not exist at character 3616752026-09-22 10:44:48.703 UTC [30732] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16762026/09/22 10:44:48 OK 20260920000000_drop_claims.sql (29.48ms)16772026/09/22 10:44:48 goose: successfully migrated database to version: 2026092000000016782026/09/22 10:44:48 OK 1_commit_pending_closure.sql (3.31ms)16792026/09/22 10:44:48 OK 2_object_stats_trigger.sql (557.63µs)16802026/09/22 10:44:48 goose: up to current file version: 216812026/09/22 10:44:48 OK 20241026095416_initial_model.sql (79.47ms)16822026/09/22 10:44:48 OK 20251210153512_drop_unused_gin_index.sql (11.96ms)16832026/09/22 10:44:48 OK 20251218171726_add_pins.sql (17.85ms)16842026/09/22 10:44:48 OK 20260628120000_add_object_size_and_stats.sql (27.58ms)16852026/09/22 10:44:48 OK 20260905000000_add_claims.sql (40.93ms)16862026/09/22 10:44:48 OK 20241026095416_initial_model.sql (114.29ms)16872026/09/22 10:44:48 OK 20251210153512_drop_unused_gin_index.sql (9.01ms)16882026/09/22 10:44:48 OK 20260920000000_drop_claims.sql (19.28ms)16892026/09/22 10:44:48 goose: successfully migrated database to version: 2026092000000016902026/09/22 10:44:48 OK 1_commit_pending_closure.sql (1.97ms)16912026/09/22 10:44:48 OK 2_object_stats_trigger.sql (761µs)16922026/09/22 10:44:48 goose: up to current file version: 216932026/09/22 10:44:48 OK 20251218171726_add_pins.sql (29.77ms)16942026-09-22 10:44:48.922 UTC [30738] ERROR: relation "goose_db_version" does not exist at character 3616952026-09-22 10:44:48.922 UTC [30738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16962026/09/22 10:44:48 OK 20260628120000_add_object_size_and_stats.sql (31.28ms)16972026/09/22 10:44:49 OK 20260905000000_add_claims.sql (62.92ms)16982026/09/22 10:44:49 OK 20260920000000_drop_claims.sql (20.93ms)16992026/09/22 10:44:49 goose: successfully migrated database to version: 2026092000000017002026/09/22 10:44:49 OK 1_commit_pending_closure.sql (1.08ms)17012026/09/22 10:44:49 OK 2_object_stats_trigger.sql (530.38µs)17022026/09/22 10:44:49 goose: up to current file version: 217032026/09/22 10:44:49 OK 20241026095416_initial_model.sql (127.13ms)17042026/09/22 10:44:49 OK 20251210153512_drop_unused_gin_index.sql (7.54ms)17052026/09/22 10:44:49 OK 20251218171726_add_pins.sql (31.61ms)17062026/09/22 10:44:49 OK 20260628120000_add_object_size_and_stats.sql (43ms)17072026-09-22 10:44:49.181 UTC [30766] ERROR: relation "goose_db_version" does not exist at character 3617082026-09-22 10:44:49.181 UTC [30766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17092026/09/22 10:44:49 OK 20260905000000_add_claims.sql (45.29ms)17102026/09/22 10:44:49 OK 20260920000000_drop_claims.sql (16.97ms)17112026/09/22 10:44:49 goose: successfully migrated database to version: 2026092000000017122026/09/22 10:44:49 OK 1_commit_pending_closure.sql (1.68ms)17132026/09/22 10:44:49 OK 2_object_stats_trigger.sql (346.25µs)17142026/09/22 10:44:49 goose: up to current file version: 21715=== NAME TestClientWithDependencies1716 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-28854-4210868838/TestClientWithDependencies2369389542/001/store/i8qammzhfyyqk38q74kbrljcc62la23f-test-script1717=== NAME TestClientMultipleUploads1718 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-28854-4210868838/TestClientMultipleUploads804918114/001/store/53zjv7l6iav9sbvcgr9v7lf1r3z205cb-test-file-0.txt1719=== NAME TestClientWithDependencies1720 client_integration_test.go:615: Found 1 dependencies (including self)17212026/09/22 10:44:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17222026/09/22 10:44:49 WARN mTLS auth: bound subjects configured but subject DN unavailable17232026/09/22 10:44:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1724--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.11s)1725=== CONT TestProxyWriteTimeout/narinfo1726=== CONT TestProxyWriteTimeout/unknown_size1727=== CONT TestProxyWriteTimeout/10_GiB_nar1728=== CONT TestProxyWriteTimeout/1_GiB_nar1729--- PASS: TestProxyWriteTimeout (0.00s)1730 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1731 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1732 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1733 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1734=== CONT TestCompletedNarNotReofferedAcrossClosures1735=== NAME TestClientMultipleUploads1736 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-28854-4210868838/TestClientMultipleUploads804918114/001/store/n837hzcgs8ldankwb24jwvgmz4n498n7-test-file-1.txt17372026/09/22 10:44:49 OK 20241026095416_initial_model.sql (181.9ms)17382026/09/22 10:44:49 OK 20251210153512_drop_unused_gin_index.sql (5.58ms)17392026/09/22 10:44:49 OK 20251218171726_add_pins.sql (10.83ms)17402026/09/22 10:44:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17412026/09/22 10:44:49 INFO Received uploads request method=POST path=/api/pending_closures1742 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-28854-4210868838/TestClientMultipleUploads804918114/001/store/p37bzdgkjnk490d615mzf0wpk3f29w55-test-file-2.txt17432026/09/22 10:44:49 OK 20260628120000_add_object_size_and_stats.sql (38.39ms)17442026/09/22 10:44:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17452026/09/22 10:44:49 INFO Uploading i8qammzhfyyqk38q74kbrljcc62la23f-test-script (136B)17462026/09/22 10:44:49 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17472026/09/22 10:44:49 OK 20260905000000_add_claims.sql (18.99ms)17482026/09/22 10:44:49 WARN Failed to register uploaded object key=log/b9h2744l88yl0v86lzhy5wvyk4xfm3dg-test-script.drv error="server returned 404: 404 page not found\n"17492026/09/22 10:44:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17502026/09/22 10:44:49 WARN Failed to register uploaded object key=i8qammzhfyyqk38q74kbrljcc62la23f.ls error="server returned 404: 404 page not found\n"17512026/09/22 10:44:49 INFO Signed narinfos id=1 count=117522026/09/22 10:44:49 INFO Uploading 1 narinfos17532026/09/22 10:44:49 OK 20260920000000_drop_claims.sql (27.43ms)17542026/09/22 10:44:49 goose: successfully migrated database to version: 2026092000000017552026/09/22 10:44:49 OK 1_commit_pending_closure.sql (1.82ms)17562026/09/22 10:44:49 OK 2_object_stats_trigger.sql (466.58µs)17572026/09/22 10:44:49 goose: up to current file version: 217582026/09/22 10:44:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17592026/09/22 10:44:49 WARN Failed to register uploaded object key=i8qammzhfyyqk38q74kbrljcc62la23f.narinfo error="server returned 404: 404 page not found\n"17602026/09/22 10:44:49 INFO Completed upload id=117612026/09/22 10:44:49 INFO Upload complete. (167ms)1762=== NAME TestClientWithDependencies1763 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-28854-4210868838/TestClientWithDependencies2369389542/001/store) requires matching store prefix17642026/09/22 10:44:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17652026/09/22 10:44:49 INFO Received uploads request method=POST path=/api/pending_closures1766--- PASS: TestClientWithDependencies (3.35s)1767=== CONT TestServerTLSConfig/no_client_CA1768=== CONT TestServerTLSConfig/not_a_PEM_file1769=== CONT TestServerTLSConfig/missing_CA_file1770--- PASS: TestServerTLSConfig (0.00s)1771 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1772 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1773 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1774=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17752026/09/22 10:44:49 INFO Received uploads request method=POST path=/1776=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17772026/09/22 10:44:49 INFO Received complete multipart upload request method=POST path=/1778=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17792026/09/22 10:44:49 INFO Received request for more parts method=POST path=/1780=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17812026/09/22 10:44:49 INFO Received uploads request method=POST path=/1782--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1783 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1784 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1785 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1786 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1787=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17882026/09/22 10:44:49 INFO Received uploads request method=POST path=/17892026/09/22 10:44:49 INFO Received uploads request method=POST path=/api/pending_closures17902026/09/22 10:44:49 INFO Received uploads request method=POST path=/api/pending_closures17912026/09/22 10:44:49 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17922026/09/22 10:44:49 INFO Uploading 53zjv7l6iav9sbvcgr9v7lf1r3z205cb-test-file-0.txt (160B)17932026/09/22 10:44:49 INFO Uploading n837hzcgs8ldankwb24jwvgmz4n498n7-test-file-1.txt (160B)17942026/09/22 10:44:49 INFO Uploading p37bzdgkjnk490d615mzf0wpk3f29w55-test-file-2.txt (160B)17952026/09/22 10:44:49 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17962026/09/22 10:44:49 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17972026/09/22 10:44:49 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17982026/09/22 10:44:49 WARN Failed to register uploaded object key=53zjv7l6iav9sbvcgr9v7lf1r3z205cb.ls error="server returned 404: 404 page not found\n"17992026/09/22 10:44:49 WARN Failed to register uploaded object key=n837hzcgs8ldankwb24jwvgmz4n498n7.ls error="server returned 404: 404 page not found\n"18002026/09/22 10:44:49 WARN Failed to register uploaded object key=p37bzdgkjnk490d615mzf0wpk3f29w55.ls error="server returned 404: 404 page not found\n"18012026/09/22 10:44:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18022026/09/22 10:44:49 INFO Signed narinfos id=1 count=118032026/09/22 10:44:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18042026/09/22 10:44:49 INFO Signed narinfos id=2 count=118052026/09/22 10:44:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign18062026/09/22 10:44:49 INFO Signed narinfos id=3 count=118072026/09/22 10:44:49 INFO Uploading 3 narinfos18082026-09-22 10:44:49.658 UTC [31053] ERROR: relation "goose_db_version" does not exist at character 3618092026-09-22 10:44:49.658 UTC [31053] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18102026/09/22 10:44:49 WARN Failed to register uploaded object key=p37bzdgkjnk490d615mzf0wpk3f29w55.narinfo error="server returned 404: 404 page not found\n"18112026/09/22 10:44:49 WARN Failed to register uploaded object key=n837hzcgs8ldankwb24jwvgmz4n498n7.narinfo error="server returned 404: 404 page not found\n"18122026/09/22 10:44:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18132026/09/22 10:44:49 WARN Failed to register uploaded object key=53zjv7l6iav9sbvcgr9v7lf1r3z205cb.narinfo error="server returned 404: 404 page not found\n"18142026-09-22 10:44:49.680 UTC [31060] ERROR: relation "goose_db_version" does not exist at character 3618152026-09-22 10:44:49.680 UTC [31060] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18162026/09/22 10:44:49 INFO Completed upload id=118172026/09/22 10:44:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18182026/09/22 10:44:49 INFO Completed upload id=218192026/09/22 10:44:49 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete18202026/09/22 10:44:49 INFO Completed upload id=318212026/09/22 10:44:49 INFO Upload complete. (193ms)1822=== NAME TestClientMultipleUploads1823 client_integration_test.go:369: Uploaded 3 paths in 242.306542ms18242026/09/22 10:44:49 OK 20241026095416_initial_model.sql (15.76ms)18252026/09/22 10:44:49 OK 20251210153512_drop_unused_gin_index.sql (16.79ms)1826--- PASS: TestClientMultipleUploads (2.96s)1827=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18282026/09/22 10:44:49 INFO Received request for more parts method=POST path=/18292026/09/22 10:44:49 OK 20251218171726_add_pins.sql (8.6ms)1830=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18312026/09/22 10:44:49 INFO Received complete multipart upload request method=POST path=/1832=== NAME TestClientIntegration1833 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-28854-4210868838/TestClientIntegration1454484216/002/store/yq9azblzvmgfi27ky6ipnlgl1k7sppws-test-file.txt18342026/09/22 10:44:49 OK 20260628120000_add_object_size_and_stats.sql (27.75ms)18352026/09/22 10:44:49 OK 20260905000000_add_claims.sql (17.99ms)18362026/09/22 10:44:49 OK 20241026095416_initial_model.sql (62.78ms)18372026/09/22 10:44:49 OK 20251210153512_drop_unused_gin_index.sql (4.22ms)1838=== CONT TestIsValidUploadKey/narinfo1839=== CONT TestIsValidUploadKey/nix-cache-info1840=== CONT TestIsValidUploadKey/unknown_type1841=== CONT TestIsValidUploadKey/empty_key1842=== CONT TestIsValidUploadKey/absolute1843=== CONT TestIsValidUploadKey/traversal_nar1844=== CONT TestIsValidUploadKey/traversal1845=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1846=== CONT TestIsValidUploadKey/nar_zst1847=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1848=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1849=== CONT TestIsValidUploadKey/index.html1850=== CONT TestIsValidUploadKey/build_log_plus_in_name1851=== CONT TestIsValidUploadKey/realisation_plus_in_output1852=== CONT TestIsValidUploadKey/realisation1853=== CONT TestIsValidUploadKey/build_log_equals1854=== CONT TestIsValidUploadKey/build_log_question_mark1855=== CONT TestIsValidUploadKey/build_log_home-manager_file1856=== CONT TestIsValidUploadKey/nar_plain1857=== CONT TestIsValidUploadKey/build_log1858=== CONT TestIsValidUploadKey/nar_xz1859=== CONT TestIsValidUploadKey/listing1860--- PASS: TestIsValidUploadKey (0.00s)1861 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1862 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1863 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1864 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1865 --- PASS: TestIsValidUploadKey/absolute (0.00s)1866 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1867 --- PASS: TestIsValidUploadKey/traversal (0.00s)1868 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1869 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1870 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1871 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1872 --- PASS: TestIsValidUploadKey/index.html (0.00s)1873 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1874 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1875 --- PASS: TestIsValidUploadKey/realisation (0.00s)1876 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1877 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1878 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1879 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1880 --- PASS: TestIsValidUploadKey/build_log (0.00s)1881 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1882 --- PASS: TestIsValidUploadKey/listing (0.00s)1883=== CONT TestIsValidCachePath/narinfo1884=== CONT TestIsValidCachePath/index.html1885=== CONT TestIsValidCachePath/short_hash1886=== CONT TestIsValidCachePath/wrong_extension1887=== CONT TestIsValidCachePath/leading_slash1888=== CONT TestIsValidCachePath/invalid_char_e1889=== CONT TestIsValidCachePath/traversal_in_middle1890=== CONT TestIsValidCachePath/traversal_parent1891=== CONT TestIsValidCachePath/invalid_char_u1892=== CONT TestIsValidCachePath/empty1893=== CONT TestIsValidCachePath/random_path1894=== CONT TestIsValidCachePath/realisation1895=== CONT TestIsValidCachePath/nar_uncompressed1896=== CONT TestIsValidCachePath/nix-cache-info1897=== CONT TestIsValidCachePath/log1898=== CONT TestIsValidCachePath/ls1899=== CONT TestIsValidCachePath/nar_xz1900=== CONT TestIsValidCachePath/nar_bz21901=== CONT TestIsValidCachePath/nar_zst1902=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1903--- PASS: TestIsValidCachePath (0.00s)1904 --- PASS: TestIsValidCachePath/narinfo (0.00s)1905 --- PASS: TestIsValidCachePath/index.html (0.00s)1906 --- PASS: TestIsValidCachePath/short_hash (0.00s)1907 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1908 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1909 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1910 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1911 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1912 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1913 --- PASS: TestIsValidCachePath/empty (0.00s)1914 --- PASS: TestIsValidCachePath/random_path (0.00s)1915 --- PASS: TestIsValidCachePath/realisation (0.00s)1916 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1917 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1918 --- PASS: TestIsValidCachePath/log (0.00s)1919 --- PASS: TestIsValidCachePath/ls (0.00s)1920 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1921 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1922 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1923 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1924=== CONT TestParseSingleRange/none1925=== CONT TestParseSingleRange/open-ended1926=== CONT TestParseSingleRange/start_far_past_EOF1927=== CONT TestParseSingleRange/start_past_EOF1928=== CONT TestParseSingleRange/single_byte1929=== CONT TestParseSingleRange/suffix_exceeds_size1930=== CONT TestParseSingleRange/suffix1931=== CONT TestParseSingleRange/end_clamped_to_size1932=== CONT TestParseSingleRange/malformed_both_empty1933=== CONT TestParseSingleRange/closed1934=== CONT TestParseSingleRange/malformed_end_before_start1935=== CONT TestParseSingleRange/multi-range_ignored1936=== CONT TestParseSingleRange/malformed_no_dash1937=== CONT TestParseSingleRange/unknown_unit1938--- PASS: TestParseSingleRange (0.00s)1939 --- PASS: TestParseSingleRange/none (0.00s)1940 --- PASS: TestParseSingleRange/open-ended (0.00s)1941 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1942 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1943 --- PASS: TestParseSingleRange/single_byte (0.00s)1944 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1945 --- PASS: TestParseSingleRange/suffix (0.00s)1946 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1947 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1948 --- PASS: TestParseSingleRange/closed (0.00s)1949 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1950 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1951 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1952 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1953=== CONT TestClientErrorHandling/InvalidStorePath19542026/09/22 10:44:49 OK 20260920000000_drop_claims.sql (16.71ms)19552026/09/22 10:44:49 goose: successfully migrated database to version: 2026092000000019562026/09/22 10:44:49 OK 1_commit_pending_closure.sql (2.21ms)19572026/09/22 10:44:49 OK 2_object_stats_trigger.sql (499.79µs)19582026/09/22 10:44:49 goose: up to current file version: 219592026/09/22 10:44:49 OK 20251218171726_add_pins.sql (24.56ms)19602026/09/22 10:44:49 OK 20260628120000_add_object_size_and_stats.sql (17.04ms)19612026/09/22 10:44:49 INFO lead: acquired remote=192.0.2.1:123419622026/09/22 10:44:49 OK 20260905000000_add_claims.sql (42.42ms)19632026/09/22 10:44:49 OK 20260920000000_drop_claims.sql (27.86ms)19642026/09/22 10:44:49 goose: successfully migrated database to version: 2026092000000019652026/09/22 10:44:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19662026/09/22 10:44:49 INFO Received uploads request method=POST path=/api/pending_closures19672026/09/22 10:44:49 WARN Rate limiter enabled after throttle name=s3-test rate=519682026/09/22 10:44:49 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1969=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1970 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101971 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001972--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.30s)1973=== CONT TestClientErrorHandling/ServerNotAvailable19742026/09/22 10:44:49 OK 1_commit_pending_closure.sql (29.04ms)19752026/09/22 10:44:49 OK 2_object_stats_trigger.sql (990.21µs)19762026/09/22 10:44:49 goose: up to current file version: 219772026/09/22 10:44:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19782026/09/22 10:44:49 INFO Uploading yq9azblzvmgfi27ky6ipnlgl1k7sppws-test-file.txt (152B)19792026/09/22 10:44:49 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19802026/09/22 10:44:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19812026/09/22 10:44:49 WARN Failed to register uploaded object key=yq9azblzvmgfi27ky6ipnlgl1k7sppws.ls error="server returned 404: 404 page not found\n"19822026/09/22 10:44:49 INFO Signed narinfos id=1 count=119832026/09/22 10:44:49 INFO Uploading 1 narinfos19842026/09/22 10:44:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19852026/09/22 10:44:49 WARN Failed to register uploaded object key=yq9azblzvmgfi27ky6ipnlgl1k7sppws.narinfo error="server returned 404: 404 page not found\n"19862026/09/22 10:44:50 INFO Completed upload id=119872026/09/22 10:44:50 INFO Upload complete. (180ms)19882026/09/22 10:44:50 INFO lead: released remote=192.0.2.1:12341989--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1990 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1991 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1992 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.47s)1993=== CONT TestClientErrorHandling/InvalidAuthToken19942026/09/22 10:44:50 INFO lead: acquired remote=192.0.2.1:123419952026/09/22 10:44:50 INFO lead: released remote=192.0.2.1:12341996--- PASS: TestLeadElectsOneAndHandsOver (2.52s)1997=== CONT TestCacheConfigHandler/full_config,_no_issuer1998=== CONT TestCacheConfigHandler/no_signing_keys1999=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2000=== CONT TestCacheConfigHandler/no_cache_url_configured2001--- PASS: TestCacheConfigHandler (0.00s)2002 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2003 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2004 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2005 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2006=== CONT TestService_RequireScope_OIDC/builder_may_write2007=== CONT TestService_RequireScope_OIDC/static_token_may_admin2008=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2009=== CONT TestService_RequireScope_OIDC/writer_implies_read2010=== CONT TestService_RequireScope_OIDC/reader_may_read2011=== CONT TestService_RequireScope_OIDC/static_token_may_write2012=== CONT TestService_RequireScope_OIDC/ops_may_not_write2013=== CONT TestService_RequireScope_OIDC/reader_may_not_write2014=== CONT TestService_RequireScope_OIDC/ops_may_admin2015=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2016--- PASS: TestService_RequireScope_OIDC (2.25s)2017 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.01s)2018 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2026 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2027=== CONT TestResolveDBConnectionString/flag_wins2028=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2029=== CONT TestResolveDBConnectionString/nothing_configured2030=== CONT TestResolveDBConnectionString/missing_file_is_an_error2031=== CONT TestResolveDBConnectionString/file_when_flag_empty2032=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2033--- PASS: TestResolveDBConnectionString (0.01s)2034 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2035 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2036 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2037 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2038 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2039=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured20402026-09-22 10:44:50.095 UTC [31342] ERROR: relation "goose_db_version" does not exist at character 3620412026-09-22 10:44:50.095 UTC [31342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2042=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20432026/09/22 10:44:50 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2044=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20452026/09/22 10:44:50 WARN Authentication failed token_preview=eyJhbGciOi...P799Kvgz7Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2046--- PASS: TestService_AuthMiddleware_OIDC (2.37s)2047 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2048 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2049 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2050 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)20512026/09/22 10:44:50 INFO All 1 paths already cached2052=== NAME TestClientIntegration2053 client_integration_test.go:312: Retrieved narinfo from S3:2054 StorePath: /nix/var/nix/builds/nix-28854-4210868838/TestClientIntegration1454484216/002/store/yq9azblzvmgfi27ky6ipnlgl1k7sppws-test-file.txt2055 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2056 Compression: zstd2057 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12058 NarSize: 1522059 References: 2060 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12061 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2062 client_integration_test.go:313: Decompressed .ls content (64 bytes):2063 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2064 client_integration_test.go:316: Testing garbage collection...20652026/09/22 10:44:50 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20662026/09/22 10:44:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures20672026/09/22 10:44:50 INFO Garbage collection started20682026/09/22 10:44:50 INFO Aborted multipart uploads count=020692026/09/22 10:44:50 WARN Force mode enabled - objects will be deleted immediately without grace period20702026/09/22 10:44:50 OK 20241026095416_initial_model.sql (85.05ms)20712026/09/22 10:44:50 OK 20251210153512_drop_unused_gin_index.sql (7.44ms)20722026/09/22 10:44:50 OK 20251218171726_add_pins.sql (22.35ms)20732026/09/22 10:44:50 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=212.070162ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20742026/09/22 10:44:50 OK 20260628120000_add_object_size_and_stats.sql (26.25ms)20752026/09/22 10:44:50 OK 20260905000000_add_claims.sql (52.25ms)20762026/09/22 10:44:50 OK 20260920000000_drop_claims.sql (28.69ms)20772026/09/22 10:44:50 goose: successfully migrated database to version: 2026092000000020782026/09/22 10:44:50 OK 1_commit_pending_closure.sql (1.56ms)20792026/09/22 10:44:50 OK 2_object_stats_trigger.sql (676.38µs)20802026/09/22 10:44:50 goose: up to current file version: 22081--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.12s)20822026/09/22 10:44:50 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=407.948158ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20832026-09-22 10:44:50.547 UTC [32252] ERROR: relation "goose_db_version" does not exist at character 3620842026-09-22 10:44:50.547 UTC [32252] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20852026/09/22 10:44:50 OK 20241026095416_initial_model.sql (36.65ms)20862026/09/22 10:44:50 OK 20251210153512_drop_unused_gin_index.sql (10.85ms)20872026/09/22 10:44:50 OK 20251218171726_add_pins.sql (18.98ms)20882026/09/22 10:44:50 OK 20260628120000_add_object_size_and_stats.sql (10.75ms)20892026/09/22 10:44:50 OK 20260905000000_add_claims.sql (4.07ms)20902026/09/22 10:44:50 OK 20260920000000_drop_claims.sql (2.88ms)20912026/09/22 10:44:50 goose: successfully migrated database to version: 2026092000000020922026/09/22 10:44:50 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"20932026/09/22 10:44:50 INFO Received uploads request method=POST path=/api/pending_closures20942026/09/22 10:44:50 OK 1_commit_pending_closure.sql (2.16ms)20952026/09/22 10:44:50 OK 2_object_stats_trigger.sql (516.54µs)20962026/09/22 10:44:50 goose: up to current file version: 220972026-09-22 10:44:50.651 UTC [32506] ERROR: relation "goose_db_version" does not exist at character 3620982026-09-22 10:44:50.651 UTC [32506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20992026/09/22 10:44:50 OK 20241026095416_initial_model.sql (5.2ms)21002026/09/22 10:44:50 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)21012026/09/22 10:44:50 OK 20251218171726_add_pins.sql (5.99ms)21022026/09/22 10:44:50 OK 20260628120000_add_object_size_and_stats.sql (2.82ms)21032026/09/22 10:44:50 OK 20260905000000_add_claims.sql (6.54ms)21042026/09/22 10:44:50 OK 20260920000000_drop_claims.sql (10.66ms)21052026/09/22 10:44:50 goose: successfully migrated database to version: 2026092000000021062026/09/22 10:44:50 OK 1_commit_pending_closure.sql (2.49ms)21072026/09/22 10:44:50 OK 2_object_stats_trigger.sql (667.67µs)21082026/09/22 10:44:50 goose: up to current file version: 22109=== NAME TestOrphanedObjectsGCStressTest2110 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2111 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion21122026/09/22 10:44:50 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21132026/09/22 10:44:50 INFO Received uploads request method=POST path=/api/pending_closures21142026/09/22 10:44:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21152026/09/22 10:44:50 INFO Uploading c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4-shared-dep (136B)21162026/09/22 10:44:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21172026/09/22 10:44:50 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign21182026/09/22 10:44:50 WARN Failed to register uploaded object key=c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4.ls error="server returned 404: 404 page not found\n"21192026/09/22 10:44:50 INFO Signed narinfos id=2 count=121202026/09/22 10:44:50 INFO Uploading 1 narinfos21212026/09/22 10:44:50 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21222026/09/22 10:44:50 WARN Failed to register uploaded object key=c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4.narinfo error="server returned 404: 404 page not found\n"21232026/09/22 10:44:50 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=812.490965ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21242026/09/22 10:44:50 INFO Completed upload id=221252026/09/22 10:44:50 INFO Received uploads request method=POST path=/api/pending_closures21262026/09/22 10:44:50 INFO Upload complete. (112ms)21272026/09/22 10:44:50 INFO Received uploads request method=POST path=/api/pending_closures21282026/09/22 10:44:50 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21292026/09/22 10:44:50 INFO Uploading aahs44kw5fjykf0pwvywjn99gn0kls5s-top (256B)21302026/09/22 10:44:50 INFO Uploading c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4-shared-dep (136B)2131=== NAME TestPinProtectsFromGC2132 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-28854-4210868838/TestPinProtectsFromGC110533587/001/store/p0ada2cr3w3xsl9x28pp85dp6wbrgy4b-pinned-file.txt2133 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-28854-4210868838/TestPinProtectsFromGC110533587/001/store/r4z3w1vl5dfw66gbph4x4nzzwf3kdf0p-unpinned-file.txt21342026/09/22 10:44:50 WARN Failed to register uploaded object key=nar/1wj49q5pfaw63xp9dv9y0rdc9ffmcfkls6q2cz1fq3pwrjdr2ifz.nar.zst error="server returned 404: 404 page not found\n"21352026/09/22 10:44:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21362026/09/22 10:44:50 WARN Failed to register uploaded object key=aahs44kw5fjykf0pwvywjn99gn0kls5s.ls error="server returned 404: 404 page not found\n"21372026/09/22 10:44:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=021382026/09/22 10:44:50 INFO Vacuumed table table=pending_closures21392026/09/22 10:44:50 WARN Failed to register uploaded object key=c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4.ls error="server returned 404: 404 page not found\n"21402026/09/22 10:44:50 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21412026/09/22 10:44:50 INFO Signed narinfos id=1 count=121422026/09/22 10:44:50 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign21432026/09/22 10:44:50 INFO Signed narinfos id=3 count=121442026/09/22 10:44:50 INFO Uploading 2 narinfos21452026/09/22 10:44:50 INFO Vacuumed table table=pending_objects21462026/09/22 10:44:50 INFO Vacuumed table table=multipart_uploads21472026/09/22 10:44:50 WARN Failed to register uploaded object key=aahs44kw5fjykf0pwvywjn99gn0kls5s.narinfo error="server returned 404: 404 page not found\n"21482026/09/22 10:44:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21492026/09/22 10:44:50 WARN Failed to register uploaded object key=c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4.narinfo error="server returned 404: 404 page not found\n"21502026/09/22 10:44:50 INFO Completed upload id=121512026/09/22 10:44:50 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete21522026/09/22 10:44:50 INFO Completed upload id=321532026/09/22 10:44:50 INFO Upload complete. (409ms)21542026/09/22 10:44:50 INFO Vacuumed table table=closures2155=== NAME TestClientSharedPathCommittedMidPush2156 client_integration_test.go:680: Retrieved narinfo from S3:2157 StorePath: /nix/var/nix/builds/nix-28854-4210868838/TestClientSharedPathCommittedMidPush476341360/001/store/c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4-shared-dep2158 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2159 Compression: zstd2160 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822161 NarSize: 1362162 References: 2163 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2164 client_integration_test.go:680: Retrieved narinfo from S3:2165 StorePath: /nix/var/nix/builds/nix-28854-4210868838/TestClientSharedPathCommittedMidPush476341360/001/store/aahs44kw5fjykf0pwvywjn99gn0kls5s-top2166 URL: nar/1wj49q5pfaw63xp9dv9y0rdc9ffmcfkls6q2cz1fq3pwrjdr2ifz.nar.zst2167 Compression: zstd2168 NarHash: sha256:1wj49q5pfaw63xp9dv9y0rdc9ffmcfkls6q2cz1fq3pwrjdr2ifz2169 NarSize: 2562170 References: /nix/var/nix/builds/nix-28854-4210868838/TestClientSharedPathCommittedMidPush476341360/001/store/c2ni8wl6pnl8mjki4ffrfvsm3k0gx6m4-shared-dep2171 CA: text:sha256:0zlb1cs4l976is175zrv844frzjj4i3kd3a52nf5ahbf15h0y8qc21722026/09/22 10:44:51 INFO Vacuumed table table=objects21732026/09/22 10:44:51 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21742026/09/22 10:44:51 INFO Received uploads request method=POST path=/api/pending_closures21752026/09/22 10:44:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21762026/09/22 10:44:51 INFO Uploading p0ada2cr3w3xsl9x28pp85dp6wbrgy4b-pinned-file.txt (128B)2177--- PASS: TestClientSharedPathCommittedMidPush (3.15s)21782026/09/22 10:44:51 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21792026/09/22 10:44:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21802026/09/22 10:44:51 INFO Signed narinfos id=1 count=121812026/09/22 10:44:51 WARN Failed to register uploaded object key=p0ada2cr3w3xsl9x28pp85dp6wbrgy4b.ls error="server returned 404: 404 page not found\n"21822026/09/22 10:44:51 INFO Uploading 1 narinfos21832026/09/22 10:44:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21842026/09/22 10:44:51 WARN Failed to register uploaded object key=p0ada2cr3w3xsl9x28pp85dp6wbrgy4b.narinfo error="server returned 404: 404 page not found\n"21852026/09/22 10:44:51 INFO Completed upload id=121862026/09/22 10:44:51 INFO Upload complete. (181ms)21872026/09/22 10:44:51 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21882026/09/22 10:44:51 INFO Received uploads request method=POST path=/api/pending_closures21892026/09/22 10:44:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21902026/09/22 10:44:51 INFO Uploading r4z3w1vl5dfw66gbph4x4nzzwf3kdf0p-unpinned-file.txt (128B)21912026/09/22 10:44:51 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"21922026/09/22 10:44:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign21932026/09/22 10:44:51 INFO Signed narinfos id=2 count=121942026/09/22 10:44:51 WARN Failed to register uploaded object key=r4z3w1vl5dfw66gbph4x4nzzwf3kdf0p.ls error="server returned 404: 404 page not found\n"21952026/09/22 10:44:51 INFO Uploading 1 narinfos21962026/09/22 10:44:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21972026/09/22 10:44:51 WARN Failed to register uploaded object key=r4z3w1vl5dfw66gbph4x4nzzwf3kdf0p.narinfo error="server returned 404: 404 page not found\n"21982026/09/22 10:44:51 INFO Completed upload id=221992026/09/22 10:44:51 INFO Upload complete. (128ms)22002026/09/22 10:44:51 INFO Received create pin request method=POST path=/api/pins/myapp22012026/09/22 10:44:51 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-28854-4210868838/TestPinProtectsFromGC110533587/001/store/p0ada2cr3w3xsl9x28pp85dp6wbrgy4b-pinned-file.txt narinfo_key=p0ada2cr3w3xsl9x28pp85dp6wbrgy4b.narinfo22022026/09/22 10:44:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures22032026/09/22 10:44:51 INFO Garbage collection started22042026/09/22 10:44:51 INFO Aborted multipart uploads count=022052026/09/22 10:44:51 WARN Force mode enabled - objects will be deleted immediately without grace period22062026/09/22 10:44:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22072026/09/22 10:44:51 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22082026/09/22 10:44:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22092026/09/22 10:44:51 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.633567177s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22102026/09/22 10:44:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22112026/09/22 10:44:51 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MjJlNzkzYWYtZjI4NC00MTdlLTg2YjktMWVkOWJiNDdmZDgyLmUyZjdhZWIwLTgyNzUtNDViYi04ZDcwLTlhZDZhNjhmZDljNHgxNzkwMDczODkwOTAyMzY0MDAw parts=1222122026/09/22 10:44:51 INFO Received uploads request method=POST path=/api/pending_closures2213--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.63s)22142026/09/22 10:44:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=02215=== NAME TestOrphanedObjectsGCStressTest2216 orphaned_objects_gc_test.go:509: Stress test completed successfully:2217 orphaned_objects_gc_test.go:510: - Active objects preserved: 202218 orphaned_objects_gc_test.go:511: - Objects deleted: 2102219 orphaned_objects_gc_test.go:512: - Total GC'd: 2102220--- PASS: TestOrphanedObjectsGCStressTest (9.04s)22212026/09/22 10:44:52 INFO Vacuumed table table=pending_closures22222026/09/22 10:44:52 INFO Vacuumed table table=pending_objects22232026/09/22 10:44:52 INFO Vacuumed table table=multipart_uploads22242026/09/22 10:44:52 INFO Vacuumed table table=closures22252026/09/22 10:44:52 INFO Vacuumed table table=objects22262026/09/22 10:44:52 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02227=== NAME TestClientIntegration2228 client_integration_test.go:323: Objects in database after GC:2229 client_integration_test.go:323: Successfully deleted all objects with GC --force2230--- PASS: TestClientIntegration (5.02s)22312026/09/22 10:44:53 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/09/22 10:44:53 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02233=== NAME TestPinProtectsFromGC2234 client_integration_test.go:794: Pin successfully protected closure from garbage collection2235--- PASS: TestPinProtectsFromGC (4.91s)22362026/09/22 10:44:53 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=185.236297ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22372026/09/22 10:44:53 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=437.014474ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22382026/09/22 10:44:54 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=871.075688ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22392026/09/22 10:44:54 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.711548993s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22402026/09/22 10:44:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused"22412026/09/22 10:44:56 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22422026/09/22 10:44:56 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.140075ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22432026/09/22 10:44:57 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=384.660732ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22442026/09/22 10:44:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=874.550069ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22452026/09/22 10:44:58 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.574541331s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2246--- PASS: TestClientErrorHandling (0.00s)2247 --- PASS: TestClientErrorHandling/InvalidStorePath (1.44s)2248 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.56s)2249 --- PASS: TestClientErrorHandling/ServerNotAvailable (9.93s)2250PASS2251{"timestamp":"2026-09-22T10:44:59.85359Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56648","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2260,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}22522026-09-22 10:45:00.018 UTC [28963] LOG: received smart shutdown request22532026-09-22 10:45:00.020 UTC [28963] LOG: background worker "logical replication launcher" (PID 28973) exited with exit code 122542026-09-22 10:45:00.028 UTC [28968] LOG: shutting down22552026-09-22 10:45:00.028 UTC [28968] LOG: checkpoint starting: shutdown immediate22562026-09-22 10:45:03.352 UTC [28968] LOG: checkpoint complete: wrote 13264 buffers (81.0%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=0.740 s, sync=2.566 s, total=3.324 s; sync files=19072, longest=0.168 s, average=0.001 s; distance=264770 kB, estimate=264770 kB; lsn=0/11A1D9D8, redo lsn=0/11A1D9D822572026-09-22 10:45:03.392 UTC [28963] LOG: database system is shut down2258Running OIDC tests...2259=== RUN TestAudienceForIssuer2260=== PAUSE TestAudienceForIssuer2261=== RUN TestGlobMatch2262=== PAUSE TestGlobMatch2263=== RUN TestValidateToken_ValidToken2264=== PAUSE TestValidateToken_ValidToken2265=== RUN TestValidateToken_WrongAudience2266=== PAUSE TestValidateToken_WrongAudience2267=== RUN TestValidateToken_Expired2268=== PAUSE TestValidateToken_Expired2269=== RUN TestValidateToken_BoundClaimsMismatch2270=== PAUSE TestValidateToken_BoundClaimsMismatch2271=== RUN TestValidateToken_BoundSubjectMismatch2272=== PAUSE TestValidateToken_BoundSubjectMismatch2273=== RUN TestValidateToken_MultipleProviders2274=== PAUSE TestValidateToken_MultipleProviders2275=== RUN TestValidateToken_NoMatchingProvider2276=== PAUSE TestValidateToken_NoMatchingProvider2277=== RUN TestValidateToken_KubernetesServiceAccount2278=== PAUSE TestValidateToken_KubernetesServiceAccount2279=== RUN TestNewValidator_KubernetesRequiresCA2280=== PAUSE TestNewValidator_KubernetesRequiresCA2281=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2282=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2283=== RUN TestPins_ReservedForMatchingRule2284=== PAUSE TestPins_ReservedForMatchingRule2285=== RUN TestPins_TopLevelShorthand2286=== PAUSE TestPins_TopLevelShorthand2287=== RUN TestPins_ConfigValidation2288=== PAUSE TestPins_ConfigValidation2289=== RUN TestScopes_LegacyProviderDefaultsToWrite2290=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2291=== RUN TestScopes_Rules2292=== PAUSE TestScopes_Rules2293=== RUN TestScopes_ConfigValidation2294=== PAUSE TestScopes_ConfigValidation2295=== CONT TestAudienceForIssuer2296--- PASS: TestAudienceForIssuer (0.00s)2297=== CONT TestValidateToken_NoMatchingProvider2298=== CONT TestValidateToken_KubernetesServiceAccount2299=== CONT TestPins_ConfigValidation2300=== CONT TestScopes_Rules2301=== CONT TestValidateToken_Expired2302=== CONT TestScopes_ConfigValidation2303=== CONT TestScopes_LegacyProviderDefaultsToWrite2304=== CONT TestPins_ReservedForMatchingRule2305=== CONT TestValidateToken_BoundSubjectMismatch2306=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2307--- PASS: TestScopes_ConfigValidation (0.00s)2308--- PASS: TestPins_ConfigValidation (0.00s)2309=== CONT TestValidateToken_ValidToken2310=== CONT TestValidateToken_WrongAudience23112026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57114/oidc2312--- PASS: TestScopes_Rules (0.04s)2313=== CONT TestGlobMatch2314=== RUN TestGlobMatch/foo_foo2315=== PAUSE TestGlobMatch/foo_foo2316=== RUN TestGlobMatch/foo_bar2317=== PAUSE TestGlobMatch/foo_bar2318=== RUN TestGlobMatch/*_2319=== PAUSE TestGlobMatch/*_2320=== RUN TestGlobMatch/*_anything2321=== PAUSE TestGlobMatch/*_anything2322=== RUN TestGlobMatch/foo*_foo2323=== PAUSE TestGlobMatch/foo*_foo2324=== RUN TestGlobMatch/foo*_foobar2325=== PAUSE TestGlobMatch/foo*_foobar2326=== RUN TestGlobMatch/foo*_bar2327=== PAUSE TestGlobMatch/foo*_bar2328=== RUN TestGlobMatch/*bar_bar2329=== PAUSE TestGlobMatch/*bar_bar2330=== RUN TestGlobMatch/*bar_foobar2331=== PAUSE TestGlobMatch/*bar_foobar2332=== RUN TestGlobMatch/*bar_foo2333=== PAUSE TestGlobMatch/*bar_foo2334=== RUN TestGlobMatch/foo*bar_foobar2335=== PAUSE TestGlobMatch/foo*bar_foobar2336=== RUN TestGlobMatch/foo*bar_foo123bar2337=== PAUSE TestGlobMatch/foo*bar_foo123bar2338=== RUN TestGlobMatch/foo*bar_foobarbaz2339=== PAUSE TestGlobMatch/foo*bar_foobarbaz2340=== RUN TestGlobMatch/*/*_foo/bar2341=== PAUSE TestGlobMatch/*/*_foo/bar2342=== RUN TestGlobMatch/*/*_foo2343=== PAUSE TestGlobMatch/*/*_foo2344=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2345=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2346=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02347=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02348=== RUN TestGlobMatch/refs/*/main_refs/heads/main2349=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2350=== RUN TestGlobMatch/fo?_foo2351=== PAUSE TestGlobMatch/fo?_foo2352=== RUN TestGlobMatch/fo?_fo2353=== PAUSE TestGlobMatch/fo?_fo2354=== RUN TestGlobMatch/fo?_fooo2355=== PAUSE TestGlobMatch/fo?_fooo2356=== RUN TestGlobMatch/?oo_foo2357=== PAUSE TestGlobMatch/?oo_foo2358=== RUN TestGlobMatch/?oo_boo2359=== PAUSE TestGlobMatch/?oo_boo2360=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2361=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2362=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2363=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2364=== CONT TestNewValidator_KubernetesRequiresCA23652026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57117/oidc23662026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57116/oidc2367--- PASS: TestValidateToken_Expired (0.05s)2368=== CONT TestValidateToken_BoundClaimsMismatch2369--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)2370=== CONT TestValidateToken_MultipleProviders23712026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57122/oidc23722026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57123/oidc2373--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)2374=== CONT TestPins_TopLevelShorthand2375--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.15s)2376=== CONT TestGlobMatch/foo_foo2377=== CONT TestGlobMatch/*/*_foo/bar2378=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2379=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2380=== CONT TestGlobMatch/?oo_boo2381=== CONT TestGlobMatch/?oo_foo2382=== CONT TestGlobMatch/fo?_fooo2383=== CONT TestGlobMatch/fo?_fo2384=== CONT TestGlobMatch/fo?_foo2385=== CONT TestGlobMatch/refs/*/main_refs/heads/main2386=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02387=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2388=== CONT TestGlobMatch/*/*_foo2389=== CONT TestGlobMatch/*bar_bar2390=== CONT TestGlobMatch/foo*bar_foobarbaz2391=== CONT TestGlobMatch/foo*bar_foo123bar2392=== CONT TestGlobMatch/foo*bar_foobar2393=== CONT TestGlobMatch/*bar_foo2394=== CONT TestGlobMatch/*bar_foobar2395=== CONT TestGlobMatch/foo*_foo2396=== CONT TestGlobMatch/foo*_bar2397=== CONT TestGlobMatch/foo*_foobar2398=== CONT TestGlobMatch/*_2399=== CONT TestGlobMatch/*_anything2400=== CONT TestGlobMatch/foo_bar2401--- PASS: TestGlobMatch (0.00s)2402 --- PASS: TestGlobMatch/foo_foo (0.00s)2403 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2404 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2405 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2406 --- PASS: TestGlobMatch/?oo_boo (0.00s)2407 --- PASS: TestGlobMatch/?oo_foo (0.00s)2408 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2409 --- PASS: TestGlobMatch/fo?_fo (0.00s)2410 --- PASS: TestGlobMatch/fo?_foo (0.00s)2411 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2412 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2413 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2414 --- PASS: TestGlobMatch/*/*_foo (0.00s)2415 --- PASS: TestGlobMatch/*bar_bar (0.00s)2416 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2417 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2418 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2419 --- PASS: TestGlobMatch/*bar_foo (0.00s)2420 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2421 --- PASS: TestGlobMatch/foo*_foo (0.00s)2422 --- PASS: TestGlobMatch/foo*_bar (0.00s)2423 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2424 --- PASS: TestGlobMatch/*_ (0.00s)2425 --- PASS: TestGlobMatch/*_anything (0.00s)2426 --- PASS: TestGlobMatch/foo_bar (0.00s)24272026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57126/oidc2428--- PASS: TestPins_ReservedForMatchingRule (0.16s)24292026/09/22 10:45:05 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232430--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.17s)24312026/09/22 10:45:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57130/oidc2432--- PASS: TestValidateToken_WrongAudience (0.26s)24332026/09/22 10:45:06 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:571322434--- PASS: TestValidateToken_KubernetesServiceAccount (0.31s)24352026/09/22 10:45:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57134/oidc2436--- PASS: TestValidateToken_ValidToken (0.32s)24372026/09/22 10:45:06 http: TLS handshake error from 127.0.0.1:57139: read tcp 127.0.0.1:57138->127.0.0.1:57139: use of closed network connection2438--- PASS: TestNewValidator_KubernetesRequiresCA (0.39s)24392026/09/22 10:45:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57141/oidc2440--- PASS: TestPins_TopLevelShorthand (0.30s)24412026/09/22 10:45:06 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57140/oidc2442--- PASS: TestValidateToken_NoMatchingProvider (1.17s)24432026/09/22 10:45:06 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57145/oidc24442026/09/22 10:45:06 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57150/oidc2445--- PASS: TestValidateToken_MultipleProviders (1.13s)2446PASS2447Running hook tests...2448=== RUN TestSendPathsEmpty2449=== PAUSE TestSendPathsEmpty2450=== RUN TestQueueEnqueueAndFetch2451=== PAUSE TestQueueEnqueueAndFetch2452=== RUN TestQueueDeduplication2453=== PAUSE TestQueueDeduplication2454=== RUN TestQueueRemove2455=== PAUSE TestQueueRemove2456=== RUN TestQueueFetchBatchLimit2457=== PAUSE TestQueueFetchBatchLimit2458=== RUN TestQueueRetryMovesToBack2459=== PAUSE TestQueueRetryMovesToBack2460=== RUN TestQueueFetchRemoveLifecycle2461=== PAUSE TestQueueFetchRemoveLifecycle2462=== RUN TestQueueConcurrentWriters2463=== PAUSE TestQueueConcurrentWriters2464=== RUN TestQueueRemoveLargeClosure2465=== PAUSE TestQueueRemoveLargeClosure2466=== RUN TestServerClientIntegration2467=== PAUSE TestServerClientIntegration2468=== RUN TestServerQueueError2469=== PAUSE TestServerQueueError2470=== RUN TestGetListenerSocketActivation2471 server_test.go:210: === RUN TestGetListenerSocketActivation2472 --- PASS: TestGetListenerSocketActivation (0.00s)2473 PASS2474 2475--- PASS: TestGetListenerSocketActivation (0.02s)2476=== RUN TestDrainIsolatesPoisonPath2477=== PAUSE TestDrainIsolatesPoisonPath2478=== RUN TestRunNotBlockedByPoisonHead2479=== PAUSE TestRunNotBlockedByPoisonHead2480=== RUN TestDrainGivesUpWhenServerDown2481=== PAUSE TestDrainGivesUpWhenServerDown2482=== RUN TestFailedPathPrunedByLaterClosure2483=== PAUSE TestFailedPathPrunedByLaterClosure2484=== RUN TestWorkerUploadsAndRemoves2485=== PAUSE TestWorkerUploadsAndRemoves2486=== RUN TestWorkerSkipsGCdPaths2487=== PAUSE TestWorkerSkipsGCdPaths2488=== RUN TestWorkerPrunesClosureDeps2489=== PAUSE TestWorkerPrunesClosureDeps2490=== RUN TestDrainTimeout2491=== PAUSE TestDrainTimeout2492=== CONT TestSendPathsEmpty2493=== CONT TestServerQueueError2494--- PASS: TestSendPathsEmpty (0.00s)2495=== CONT TestQueueFetchBatchLimit2496=== CONT TestQueueRemoveLargeClosure2497=== CONT TestQueueDeduplication2498=== CONT TestQueueEnqueueAndFetch2499=== CONT TestWorkerUploadsAndRemoves2500=== CONT TestServerClientIntegration2501=== CONT TestQueueConcurrentWriters2502=== CONT TestQueueFetchRemoveLifecycle2503=== CONT TestQueueRetryMovesToBack25042026/09/22 10:45:07 ERROR Failed to queue paths error="permission denied" count=12505--- PASS: TestServerQueueError (0.00s)2506=== CONT TestWorkerPrunesClosureDeps2507--- PASS: TestServerClientIntegration (0.00s)2508=== CONT TestDrainTimeout25092026/09/22 10:45:07 INFO Uploading batch count=22510--- PASS: TestQueueRetryMovesToBack (0.01s)2511=== CONT TestDrainGivesUpWhenServerDown2512--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2513=== CONT TestFailedPathPrunedByLaterClosure2514--- PASS: TestQueueFetchBatchLimit (0.01s)2515=== CONT TestRunNotBlockedByPoisonHead2516--- PASS: TestQueueEnqueueAndFetch (0.01s)2517=== CONT TestDrainIsolatesPoisonPath25182026/09/22 10:45:07 INFO Upload queue status pending=225192026/09/22 10:45:07 INFO Uploading batch count=125202026/09/22 10:45:07 INFO Upload queue status pending=225212026/09/22 10:45:07 INFO Uploading batch count=22522--- PASS: TestQueueDeduplication (0.01s)2523=== CONT TestWorkerSkipsGCdPaths25242026/09/22 10:45:07 INFO Uploading batch count=125252026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=125262026/09/22 10:45:07 INFO Uploading batch count=125272026/09/22 10:45:07 INFO Uploading batch count=225282026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=225292026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainGivesUpWhenServerDown2517962041/002/a25302026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainGivesUpWhenServerDown2517962041/002/b25312026/09/22 10:45:07 INFO Uploading batch count=125322026/09/22 10:45:07 INFO Uploading batch count=225332026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=225342026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainGivesUpWhenServerDown2517962041/002/c25352026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainGivesUpWhenServerDown2517962041/002/d25362026/09/22 10:45:07 INFO Upload queue status pending=225372026/09/22 10:45:07 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-28854-4210868838/TestWorkerSkipsGCdPaths4112447617/002/nonexistent25382026/09/22 10:45:07 INFO Uploading batch count=225392026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=225402026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainGivesUpWhenServerDown2517962041/002/e25412026/09/22 10:45:07 INFO Uploading batch count=125422026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainGivesUpWhenServerDown2517962041/002/f25432026/09/22 10:45:07 INFO Uploading batch count=425442026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=425452026/09/22 10:45:07 ERROR Drain finished with paths left in queue remaining=1025462026/09/22 10:45:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28854-4210868838/TestDrainIsolatesPoisonPath484588615/002/bbb25472026/09/22 10:45:07 INFO Upload queue status pending=325482026/09/22 10:45:07 INFO Uploading batch count=125492026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=12550--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2551=== CONT TestQueueRemove25522026/09/22 10:45:07 INFO Uploading batch count=125532026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=125542026/09/22 10:45:07 INFO Uploading batch count=125552026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=125562026/09/22 10:45:07 INFO Uploading batch count=125572026/09/22 10:45:07 ERROR Upload failed error="upload failed" count=12558--- PASS: TestDrainGivesUpWhenServerDown (0.01s)25592026/09/22 10:45:07 ERROR Drain finished with paths left in queue remaining=12560--- PASS: TestQueueRemove (0.00s)2561--- PASS: TestDrainIsolatesPoisonPath (0.01s)2562--- PASS: TestWorkerPrunesClosureDeps (0.03s)2563--- PASS: TestWorkerUploadsAndRemoves (0.03s)2564--- PASS: TestWorkerSkipsGCdPaths (0.03s)2565--- PASS: TestQueueRemoveLargeClosure (0.06s)2566--- PASS: TestQueueConcurrentWriters (0.13s)25672026/09/22 10:45:07 ERROR Upload failed error="context deadline exceeded" count=225682026/09/22 10:45:07 ERROR Drain finished with paths left in queue remaining=42569--- PASS: TestDrainTimeout (0.21s)25702026/09/22 10:45:08 INFO Uploading batch count=125712026/09/22 10:45:08 INFO Uploading batch count=125722026/09/22 10:45:08 INFO Uploading batch count=125732026/09/22 10:45:08 ERROR Upload failed error="upload failed" count=125742026/09/22 10:45:08 INFO Uploading batch count=125752026/09/22 10:45:08 ERROR Upload failed error="upload failed" count=125762026/09/22 10:45:08 INFO Uploading batch count=125772026/09/22 10:45:08 ERROR Upload failed error="upload failed" count=125782026/09/22 10:45:08 INFO Uploading batch count=125792026/09/22 10:45:08 ERROR Upload failed error="upload failed" count=125802026/09/22 10:45:08 ERROR Drain finished with paths left in queue remaining=12581--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2582PASS