niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #314
· 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.05s)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 TestShellSplit96=== CONT TestSetClientTLSErrors97--- PASS: TestShellSplit (0.00s)98=== CONT TestFileTokenMissing99=== CONT TestScriptTokenEmptyCommand100--- PASS: TestScriptTokenEmptyCommand (0.00s)101=== CONT TestFileTokenReadsAndCaches102=== CONT TestScriptTokenScriptFails103=== CONT TestScriptTokenBadJSON104=== CONT TestScriptTokenEmptyToken105--- PASS: TestFileTokenMissing (0.00s)106=== CONT TestStaticToken107--- PASS: TestStaticToken (0.00s)108=== CONT TestStreamPushRequestLine109--- PASS: TestFileTokenReadsAndCaches (0.00s)110=== CONT TestSetClientTLSDoesNotMutateDefaultTransport111=== CONT TestScriptTokenCachesUntilRefresh112=== CONT TestScriptTokenNoExpiryRerunsEveryCall113=== CONT TestFileTokenEmpty114=== RUN TestSetClientTLSErrors/missing_cert_file115=== CONT TestSetClientTLS116--- PASS: TestFileTokenEmpty (0.00s)117=== PAUSE TestSetClientTLSErrors/missing_cert_file1182026/10/01 09:42:40 ERROR Upload failed error=boom count=1119=== RUN TestSetClientTLSErrors/missing_key_file120=== PAUSE TestSetClientTLSErrors/missing_key_file121=== RUN TestSetClientTLSErrors/missing_ca_file122=== PAUSE TestSetClientTLSErrors/missing_ca_file123=== RUN TestSetClientTLSErrors/invalid_ca_file124=== PAUSE TestSetClientTLSErrors/invalid_ca_file125=== CONT TestClientSignaturesByStorePath126--- PASS: TestClientSignaturesByStorePath (0.00s)127=== CONT TestStreamPushReportsSignatures1282026/10/01 09:42:40 ERROR Upload failed error=boom count=1129--- PASS: TestStreamPushReportsSignatures (0.00s)130=== CONT TestEncodeNixBase32WithRealHash131--- PASS: TestEncodeNixBase32WithRealHash (0.00s)132=== CONT TestDoWithRetry_BodyReplayedViaGetBody133--- PASS: TestScriptTokenScriptFails (0.01s)134--- PASS: TestDoServerRequestAttachesToken (0.01s)135=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess136=== CONT TestResolveStorePath1372026/10/01 09:42:40 WARN Rate limiter enabled after throttle name=server-test rate=5138--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)139=== CONT TestRateLimiterFeedback140=== RUN TestRateLimiterFeedback/429_enables_limiter141=== PAUSE TestRateLimiterFeedback/429_enables_limiter142=== RUN TestRateLimiterFeedback/503_enables_limiter143=== PAUSE TestRateLimiterFeedback/503_enables_limiter144=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1452026/10/01 09:42:40 WARN Rate limiter enabled after throttle name=server-test rate=51462026/10/01 09:42:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50862147=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter148=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter149=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter1502026/10/01 09:42:40 WARN Rate limiter backed off name=server-test rate=5151=== CONT TestPathInfoCACompatibility1522026/10/01 09:42:40 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50862153=== RUN TestPathInfoCACompatibility/null_ca_field154=== PAUSE TestPathInfoCACompatibility/null_ca_field155=== RUN TestPathInfoCACompatibility/old_string_format_-_text156=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text157=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive158=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive159=== RUN TestPathInfoCACompatibility/new_structured_format_-_text160=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text161=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method162=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method163=== CONT TestParsePathInfoJSONMultiplePaths164=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths165=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths166=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths167=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths168=== CONT TestParsePathInfoJSON169=== RUN TestParsePathInfoJSON/Nix_format170=== PAUSE TestParsePathInfoJSON/Nix_format171=== RUN TestParsePathInfoJSON/Lix_format172=== PAUSE TestParsePathInfoJSON/Lix_format173=== RUN TestParsePathInfoJSON/empty_input174=== PAUSE TestParsePathInfoJSON/empty_input175=== RUN TestParsePathInfoJSON/whitespace_only176=== PAUSE TestParsePathInfoJSON/whitespace_only177=== RUN TestParsePathInfoJSON/invalid_JSON178=== PAUSE TestParsePathInfoJSON/invalid_JSON179=== CONT TestPathInfoHashCompatibility180=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)181--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)182=== CONT TestGetStorePathHash183=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)184=== RUN TestGetStorePathHash/valid_store_path185=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon186=== PAUSE TestGetStorePathHash/valid_store_path187=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon188=== RUN TestGetStorePathHash/basename_without_hyphen_should_error189=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error190=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI191=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error192=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI193=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error194=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512195=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error196=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512197=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error198=== CONT TestStreamPushBatchesUnderLoad199=== CONT TestConvertHashToNix32200=== RUN TestConvertHashToNix32/SRI_format_to_Nix32201=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32202=== RUN TestConvertHashToNix32/already_Nix32_format203=== PAUSE TestConvertHashToNix32/already_Nix32_format204=== RUN TestConvertHashToNix32/invalid_format205--- PASS: TestResolveStorePath (0.00s)206=== PAUSE TestConvertHashToNix32/invalid_format207=== CONT TestStreamPushGivesUpOnDeadServer208=== CONT TestStreamPushIsolatesFailures2092026/10/01 09:42:40 ERROR Upload failed error="connection refused" count=202102026/10/01 09:42:40 ERROR Server seems unavailable, giving up on batch untried=172112026/10/01 09:42:40 ERROR Upload failed error="bad path" count=3212--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)213=== CONT TestFilterOversizedClosures214=== RUN TestFilterOversizedClosures/no_limit_keeps_everything215=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything216=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped217=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped218=== RUN TestFilterOversizedClosures/all_closures_skipped219=== PAUSE TestFilterOversizedClosures/all_closures_skipped220=== CONT TestPartSizeForNAR221=== RUN TestPartSizeForNAR/zero_stays_at_minimum222=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum223=== RUN TestPartSizeForNAR/small_stays_at_minimum224=== PAUSE TestPartSizeForNAR/small_stays_at_minimum225--- PASS: TestStreamPushIsolatesFailures (0.00s)226=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum227=== CONT TestUploadMultipart_SupersededByPeer228=== RUN TestUploadMultipart_SupersededByPeer/exists229=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum230=== PAUSE TestUploadMultipart_SupersededByPeer/exists231=== RUN TestUploadMultipart_SupersededByPeer/missing232=== PAUSE TestUploadMultipart_SupersededByPeer/missing233=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts234=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts235=== RUN TestPartSizeForNAR/1_TiB236=== PAUSE TestPartSizeForNAR/1_TiB237=== RUN TestPartSizeForNAR/5_TiB_S3_max_object238=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object239=== RUN TestPartSizeForNAR/capped_at_5_GiB240=== PAUSE TestPartSizeForNAR/capped_at_5_GiB241=== CONT TestEncodeNixBase32242=== CONT TestDumpPathWriterError243=== RUN TestEncodeNixBase32/test_string_hash244=== PAUSE TestEncodeNixBase32/test_string_hash245=== RUN TestEncodeNixBase32/empty_input246=== PAUSE TestEncodeNixBase32/empty_input247=== CONT TestDumpPathSingleFile248=== RUN TestSetClientTLS/rejects_connection_without_client_cert249=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert250=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA251=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA252=== RUN TestSetClientTLS/preserves_debug_logging_transport253=== PAUSE TestSetClientTLS/preserves_debug_logging_transport254=== CONT TestDumpPathMatchesNix255--- PASS: TestScriptTokenBadJSON (0.01s)256=== CONT TestUploadMultipart_PartsInParallel257--- PASS: TestScriptTokenEmptyToken (0.01s)258=== CONT TestCaseHackSuffix259--- PASS: TestStreamPushRequestLine (0.02s)260=== CONT TestRegisterUploadedObjectReusesConnections261--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)262=== CONT TestStreamPushReportsEveryPath263--- PASS: TestStreamPushReportsEveryPath (0.00s)264=== CONT TestShellSplitErrors265--- PASS: TestShellSplitErrors (0.00s)266=== CONT TestSetClientTLSErrors/missing_cert_file267=== CONT TestSetClientTLSErrors/missing_ca_file268=== CONT TestSetClientTLSErrors/invalid_ca_file269=== CONT TestSetClientTLSErrors/missing_key_file270--- PASS: TestSetClientTLSErrors (0.01s)271 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)272 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)273 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)274 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)275=== CONT TestRateLimiterFeedback/429_enables_limiter2762026/10/01 09:42:40 WARN Rate limiter enabled after throttle name=server-test rate=52772026/10/01 09:42:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:509372782026/10/01 09:42:40 WARN Rate limiter backed off name=server-test rate=5279=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter280=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter281=== CONT TestRateLimiterFeedback/503_enables_limiter2822026/10/01 09:42:40 WARN Rate limiter enabled after throttle name=server-test rate=52832026/10/01 09:42:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:509432842026/10/01 09:42:40 WARN Rate limiter backed off name=server-test rate=5285--- PASS: TestRateLimiterFeedback (0.00s)286 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)287 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)288 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)289 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)290=== CONT TestPathInfoCACompatibility/null_ca_field291=== CONT TestPathInfoCACompatibility/new_structured_format_-_text292=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method293=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive294=== CONT TestPathInfoCACompatibility/old_string_format_-_text295--- PASS: TestPathInfoCACompatibility (0.00s)296 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)297 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)298 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)299 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)300 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)301=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths302=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths303--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)304 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)305 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)306=== CONT TestParsePathInfoJSON/Nix_format307=== CONT TestParsePathInfoJSON/whitespace_only308=== CONT TestParsePathInfoJSON/invalid_JSON309=== CONT TestParsePathInfoJSON/empty_input310=== CONT TestParsePathInfoJSON/Lix_format311--- PASS: TestParsePathInfoJSON (0.00s)312 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)313 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)314 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)315 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)316 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)317=== CONT TestGetStorePathHash/valid_store_path318=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error319=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)320=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error321=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI322=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512323=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon324--- PASS: TestPathInfoHashCompatibility (0.00s)325 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)326 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)327 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)328 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)329=== CONT TestGetStorePathHash/basename_without_hyphen_should_error330--- PASS: TestGetStorePathHash (0.00s)331 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)332 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)333 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)334 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)335=== CONT TestConvertHashToNix32/SRI_format_to_Nix32336=== CONT TestConvertHashToNix32/invalid_format337=== CONT TestConvertHashToNix32/already_Nix32_format338--- PASS: TestConvertHashToNix32 (0.00s)339 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)340 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)341 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)342=== CONT TestFilterOversizedClosures/no_limit_keeps_everything343=== CONT TestFilterOversizedClosures/all_closures_skipped3442026/10/01 09:42:40 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/10/01 09:42:40 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=== CONT TestUploadMultipart_SupersededByPeer/exists352--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)353=== CONT TestUploadMultipart_SupersededByPeer/missing354=== CONT TestPartSizeForNAR/zero_stays_at_minimum355=== CONT TestPartSizeForNAR/1_TiB356=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts357=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum358=== CONT TestPartSizeForNAR/small_stays_at_minimum359=== CONT TestPartSizeForNAR/capped_at_5_GiB360=== CONT TestPartSizeForNAR/5_TiB_S3_max_object361--- PASS: TestPartSizeForNAR (0.00s)362 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)363 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)364 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)365 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)366 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)367 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)368 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)369=== CONT TestEncodeNixBase32/test_string_hash370=== CONT TestEncodeNixBase32/empty_input371--- PASS: TestEncodeNixBase32 (0.00s)372 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)373 --- PASS: TestEncodeNixBase32/empty_input (0.00s)374=== CONT TestSetClientTLS/rejects_connection_without_client_cert375--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)376 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)377 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)378=== CONT TestSetClientTLS/preserves_debug_logging_transport379--- PASS: TestDumpPathWriterError (0.04s)380=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA381--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)3822026/10/01 09:42:40 http: TLS handshake error from 127.0.0.1:50949: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.00s)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.01s)387--- PASS: TestDumpPathSingleFile (0.05s)388--- PASS: TestCaseHackSuffix (0.05s)389--- PASS: TestDumpPathMatchesNix (0.07s)390--- PASS: TestStreamPushBatchesUnderLoad (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-60884-3569518374/postgres3925003432/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-60884-3569518374/postgres3925003432/data -l logfile start421422/nix/var/nix/builds/nix-60884-3569518374/postgres3925003432:5432 - no response4232026-10-01 09:42:47.006 UTC [61049] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:42:47.014 UTC [61049] LOG: listening on Unix socket "/nix/var/nix/builds/nix-60884-3569518374/postgres3925003432/.s.PGSQL.5432"4252026-10-01 09:42:47.034 UTC [61056] LOG: database system was shut down at 2026-10-01 09:42:46 UTC4262026-10-01 09:42:47.039 UTC [61049] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-60884-3569518374/postgres3925003432:5432 - accepting connections428{"timestamp":"2026-10-01T09:42:47.348304Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7398279e-12ae-43ff-9633-722719435b71","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}429{"timestamp":"2026-10-01T09:42:47.451991Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ac557d90-26f6-4a7a-ba3f-1329c8794d0f","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}430{"timestamp":"2026-10-01T09:42:47.555835Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"d26e304c-cb43-4049-a7de-be76fad1a941","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}431{"timestamp":"2026-10-01T09:42:47.65927Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ed9a4786-b53b-470a-8c68-49de3461427a","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}432{"timestamp":"2026-10-01T09:42:47.761898Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"170b3024-fc72-406e-97d9-f8bebbd9491e","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}433{"timestamp":"2026-10-01T09:42:47.863478Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"00504236-da47-41d6-a5f9-361e9916b31c","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}434=== RUN TestService_AuthMiddleware435=== PAUSE TestService_AuthMiddleware436=== RUN TestService_AuthMiddleware_MTLSProxyHeader437=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader438=== RUN TestService_AuthMiddleware_MTLSBoundSubjects439=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects440=== RUN TestService_ReadAuthMiddleware441=== PAUSE TestService_ReadAuthMiddleware442=== RUN TestService_AuthMiddleware_OIDC443=== PAUSE TestService_AuthMiddleware_OIDC444=== RUN TestService_RequireScope_OIDC445=== PAUSE TestService_RequireScope_OIDC446=== RUN TestService_ReadScope_PublicByDefault447=== PAUSE TestService_ReadScope_PublicByDefault448=== RUN TestCacheConfigHandler449=== PAUSE TestCacheConfigHandler450=== RUN TestCacheStatsHandler451=== PAUSE TestCacheStatsHandler452=== RUN TestClientCADerivations453=== PAUSE TestClientCADerivations454=== RUN TestClientErrorHandling455=== PAUSE TestClientErrorHandling456=== RUN TestClientIntegration457=== PAUSE TestClientIntegration458=== RUN TestClientMultipleUploads459=== PAUSE TestClientMultipleUploads460=== RUN TestClientWithDependencies461=== PAUSE TestClientWithDependencies462=== RUN TestClientSharedPathCommittedMidPush463=== PAUSE TestClientSharedPathCommittedMidPush464=== RUN TestPinProtectsFromGC465=== PAUSE TestPinProtectsFromGC466=== RUN TestClientPushesUseOnePush467=== PAUSE TestClientPushesUseOnePush468=== RUN TestClientFallsBackToClosures469=== PAUSE TestClientFallsBackToClosures470=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock471=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock472=== RUN TestResolveDBConnectionString473=== PAUSE TestResolveDBConnectionString474=== RUN TestLeadElectsOneAndHandsOver475=== PAUSE TestLeadElectsOneAndHandsOver476=== RUN TestLeadIncumbentWinsAfterRestart4772026-10-01 09:42:50.875 UTC [61117] ERROR: relation "goose_db_version" does not exist at character 364782026-10-01 09:42:50.875 UTC [61117] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4792026/10/01 09:42:51 OK 20241026095416_initial_model.sql (189.14ms)4802026/10/01 09:42:51 OK 20251210153512_drop_unused_gin_index.sql (23.49ms)4812026/10/01 09:42:51 OK 20251218171726_add_pins.sql (22.92ms)4822026/10/01 09:42:51 OK 20260628120000_add_object_size_and_stats.sql (46.39ms)4832026/10/01 09:42:51 OK 20260905000000_add_claims.sql (125.7ms)4842026/10/01 09:42:51 OK 20260920000000_drop_claims.sql (39.16ms)4852026/10/01 09:42:51 OK 20260923120000_add_pushes.sql (42.43ms)4862026/10/01 09:42:51 goose: successfully migrated database to version: 202609231200004872026/10/01 09:42:51 OK 1_commit_pending_closure.sql (2.96ms)4882026/10/01 09:42:51 OK 2_object_stats_trigger.sql (668.79µs)4892026/10/01 09:42:51 OK 3_commit_push.sql (504.13µs)4902026/10/01 09:42:51 goose: up to current file version: 34912026/10/01 09:42:51 INFO lead: acquired remote=192.0.2.1:12344922026/10/01 09:42:52 INFO lead: released remote=192.0.2.1:12344932026/10/01 09:42:52 INFO lead: acquired remote=192.0.2.1:12344942026/10/01 09:42:52 INFO lead: released remote=192.0.2.1:1234495--- PASS: TestLeadIncumbentWinsAfterRestart (4.45s)496=== RUN TestLeadEndsOnShutdown497=== PAUSE TestLeadEndsOnShutdown498=== RUN TestGCAdvisoryLockBlocksConcurrentRun4992026-10-01 09:42:53.894 UTC [61148] ERROR: relation "goose_db_version" does not exist at character 365002026-10-01 09:42:53.894 UTC [61148] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5012026/10/01 09:42:54 OK 20241026095416_initial_model.sql (143.47ms)5022026/10/01 09:42:54 OK 20251210153512_drop_unused_gin_index.sql (13.6ms)5032026/10/01 09:42:54 OK 20251218171726_add_pins.sql (14.66ms)5042026/10/01 09:42:54 OK 20260628120000_add_object_size_and_stats.sql (12.62ms)5052026/10/01 09:42:54 OK 20260905000000_add_claims.sql (5.68ms)5062026/10/01 09:42:54 OK 20260920000000_drop_claims.sql (2.25ms)5072026/10/01 09:42:54 OK 20260923120000_add_pushes.sql (841.21µs)5082026/10/01 09:42:54 goose: successfully migrated database to version: 202609231200005092026/10/01 09:42:54 OK 1_commit_pending_closure.sql (1.41ms)5102026/10/01 09:42:54 OK 2_object_stats_trigger.sql (300.46µs)5112026/10/01 09:42:54 OK 3_commit_push.sql (243.92µs)5122026/10/01 09:42:54 goose: up to current file version: 3513--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.95s)514=== RUN TestGCBugBareHashReferences515=== PAUSE TestGCBugBareHashReferences516=== RUN TestGCMetrics517=== PAUSE TestGCMetrics518=== RUN TestPushDedupSurvivesConcurrentGC519=== PAUSE TestPushDedupSurvivesConcurrentGC520=== RUN TestDeduplicatedObjectsRecordedAsPending521=== PAUSE TestDeduplicatedObjectsRecordedAsPending522=== RUN TestGCSweepSkipsPendingObjects523=== PAUSE TestGCSweepSkipsPendingObjects524=== RUN TestTombstonedObjectOfferedWithoutWaiting525=== PAUSE TestTombstonedObjectOfferedWithoutWaiting526=== RUN TestGCSweepDeliversEachKeyOnce527=== PAUSE TestGCSweepDeliversEachKeyOnce528=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection529=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection530=== RUN TestForceGCDuringPushOffersSweptObject531=== PAUSE TestForceGCDuringPushOffersSweptObject532=== RUN TestFailedS3DeleteKeepsTombstone533=== PAUSE TestFailedS3DeleteKeepsTombstone534=== RUN TestSweepSkipsRowsLockedByPush535=== PAUSE TestSweepSkipsRowsLockedByPush536=== RUN TestRegisterCompletedObjectNeedsPendingRow537=== PAUSE TestRegisterCompletedObjectNeedsPendingRow538=== RUN TestGetExistingObjectsLocksRows539=== PAUSE TestGetExistingObjectsLocksRows540=== RUN TestSweepRechecksPendingAfterLocking541=== PAUSE TestSweepRechecksPendingAfterLocking542=== RUN TestPushWaitsForSweepHoldingRow543=== PAUSE TestPushWaitsForSweepHoldingRow544=== RUN TestCommitRacingPendingCleanupKeepsObjects545=== PAUSE TestCommitRacingPendingCleanupKeepsObjects546=== RUN TestGCEndsOnShutdown547=== PAUSE TestGCEndsOnShutdown548=== RUN TestGCTaskStore_StartNew549=== PAUSE TestGCTaskStore_StartNew550=== RUN TestGCTaskStore_DeduplicateSameParams551=== PAUSE TestGCTaskStore_DeduplicateSameParams552=== RUN TestGCTaskStore_ConflictDifferentParams553=== PAUSE TestGCTaskStore_ConflictDifferentParams554=== RUN TestGCTaskStore_GetEmpty555=== PAUSE TestGCTaskStore_GetEmpty556=== RUN TestGCTaskStore_GetReturnsLatest557=== PAUSE TestGCTaskStore_GetReturnsLatest558=== RUN TestGCTaskStore_CompletedAllowsNewTask559=== PAUSE TestGCTaskStore_CompletedAllowsNewTask560=== RUN TestGCTaskStore_PhaseUpdates561=== PAUSE TestGCTaskStore_PhaseUpdates562=== RUN TestGCTaskStore_Fail563=== PAUSE TestGCTaskStore_Fail564=== RUN TestGracefulShutdownDrainsInflight565=== PAUSE TestGracefulShutdownDrainsInflight566=== RUN TestService_healthCheckHandler567=== PAUSE TestService_healthCheckHandler568=== RUN TestService_readinessHandler569=== PAUSE TestService_readinessHandler570=== RUN TestGenerateLandingPage571=== PAUSE TestGenerateLandingPage572=== RUN TestCacheConfigHandlerMaxNarSize573=== PAUSE TestCacheConfigHandlerMaxNarSize574=== RUN TestCreatePendingClosureRejectsOversizedNAR575=== PAUSE TestCreatePendingClosureRejectsOversizedNAR576=== RUN TestNARDeduplicationMetadataUploadBug577=== PAUSE TestNARDeduplicationMetadataUploadBug578=== RUN TestMetricsInventory579=== PAUSE TestMetricsInventory580=== RUN TestService_NativeMTLS581=== PAUSE TestService_NativeMTLS582=== RUN TestServerTLSConfig583=== PAUSE TestServerTLSConfig584=== RUN TestMultipartCleanup585=== PAUSE TestMultipartCleanup586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.05s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"668--- PASS: TestWatchdogSkipsWhenUnhealthy (0.22s)669=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle670=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== RUN TestProxyWriteTimeout672=== PAUSE TestProxyWriteTimeout673=== RUN TestIsValidUploadKey674=== PAUSE TestIsValidUploadKey675=== RUN TestUploadHandlersRejectInvalidKeys676=== PAUSE TestUploadHandlersRejectInvalidKeys677=== RUN TestUploadHandlersRejectOversizedBody678=== PAUSE TestUploadHandlersRejectOversizedBody679=== RUN TestService_cleanupPendingClosuresHandler680=== PAUSE TestService_cleanupPendingClosuresHandler681=== RUN TestService_createPendingClosureHandler682=== PAUSE TestService_createPendingClosureHandler683=== RUN TestService_verifyS3Integrity684=== PAUSE TestService_verifyS3Integrity685=== RUN TestCompleteMultipartUnregistered686=== PAUSE TestCompleteMultipartUnregistered687=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT688=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT689=== CONT TestService_createPendingClosureHandler690=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle691=== CONT TestCompleteMultipartUnregistered692=== CONT TestService_verifyS3Integrity693=== CONT TestService_AuthMiddleware694=== CONT TestService_cleanupPendingClosuresHandler695=== CONT TestUploadHandlersRejectOversizedBody696=== CONT TestUploadHandlersRejectInvalidKeys697=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info698=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info699=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal700=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal701=== CONT TestIsValidUploadKey702=== RUN TestIsValidUploadKey/narinfo703=== CONT TestProxyWriteTimeout704=== RUN TestProxyWriteTimeout/narinfo705=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key706=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key707=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key708=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key709=== PAUSE TestIsValidUploadKey/narinfo710=== RUN TestIsValidUploadKey/nar_zst711=== PAUSE TestIsValidUploadKey/nar_zst712=== RUN TestIsValidUploadKey/nar_xz713=== PAUSE TestIsValidUploadKey/nar_xz714=== RUN TestIsValidUploadKey/nar_plain715=== PAUSE TestProxyWriteTimeout/narinfo716=== RUN TestProxyWriteTimeout/1_GiB_nar717=== PAUSE TestIsValidUploadKey/nar_plain718=== CONT TestGCTaskStore_Fail719=== RUN TestIsValidUploadKey/listing720=== PAUSE TestProxyWriteTimeout/1_GiB_nar721--- PASS: TestGCTaskStore_Fail (0.00s)722=== CONT TestSkippedUploadsHandler723=== RUN TestProxyWriteTimeout/10_GiB_nar7242026/10/01 09:42:54 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000725=== PAUSE TestIsValidUploadKey/listing726=== RUN TestIsValidUploadKey/build_log727=== PAUSE TestIsValidUploadKey/build_log728=== RUN TestIsValidUploadKey/build_log_home-manager_file729=== PAUSE TestIsValidUploadKey/build_log_home-manager_file730=== RUN TestIsValidUploadKey/build_log_plus_in_name731=== PAUSE TestIsValidUploadKey/build_log_plus_in_name732=== RUN TestIsValidUploadKey/build_log_question_mark733=== PAUSE TestIsValidUploadKey/build_log_question_mark734=== RUN TestIsValidUploadKey/build_log_equals735=== PAUSE TestIsValidUploadKey/build_log_equals736=== RUN TestIsValidUploadKey/realisation737=== PAUSE TestIsValidUploadKey/realisation738=== PAUSE TestProxyWriteTimeout/10_GiB_nar739=== RUN TestProxyWriteTimeout/unknown_size740=== PAUSE TestProxyWriteTimeout/unknown_size741=== RUN TestIsValidUploadKey/realisation_plus_in_output742=== PAUSE TestIsValidUploadKey/realisation_plus_in_output743=== RUN TestIsValidUploadKey/nix-cache-info744=== PAUSE TestIsValidUploadKey/nix-cache-info745=== RUN TestIsValidUploadKey/index.html746=== PAUSE TestIsValidUploadKey/index.html747=== RUN TestIsValidUploadKey/narinfo_key,_nar_type748=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type749=== CONT TestParseSize750--- PASS: TestParseSize (0.00s)751=== CONT TestService_Rustfstest752=== RUN TestIsValidUploadKey/nar_key,_narinfo_type753=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type754=== RUN TestIsValidUploadKey/listing_key,_narinfo_type755=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type756=== RUN TestIsValidUploadKey/traversal757=== PAUSE TestIsValidUploadKey/traversal758=== RUN TestIsValidUploadKey/traversal_nar759=== PAUSE TestIsValidUploadKey/traversal_nar760=== RUN TestIsValidUploadKey/absolute761=== PAUSE TestIsValidUploadKey/absolute762=== RUN TestIsValidUploadKey/empty_key763=== PAUSE TestIsValidUploadKey/empty_key764=== RUN TestIsValidUploadKey/unknown_type765=== PAUSE TestIsValidUploadKey/unknown_type766=== CONT TestPresignedUploadRegisteredBeforeCommit767--- PASS: TestSkippedUploadsHandler (0.00s)768=== CONT TestCompletedNarNotReofferedAcrossClosures769=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure770=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure771=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart772=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart773=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts774=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts775=== CONT TestCompleteMultipartUpload_ErrorButObjectExists7762026-10-01 09:42:56.720 UTC [61203] ERROR: relation "goose_db_version" does not exist at character 367772026-10-01 09:42:56.720 UTC [61203] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026-10-01 09:42:56.763 UTC [61205] ERROR: relation "goose_db_version" does not exist at character 367792026-10-01 09:42:56.763 UTC [61205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7802026-10-01 09:42:56.774 UTC [61206] ERROR: relation "goose_db_version" does not exist at character 367812026-10-01 09:42:56.774 UTC [61206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026-10-01 09:42:56.782 UTC [61204] ERROR: relation "goose_db_version" does not exist at character 367832026-10-01 09:42:56.782 UTC [61204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026-10-01 09:42:56.813 UTC [61207] ERROR: relation "goose_db_version" does not exist at character 367852026-10-01 09:42:56.813 UTC [61207] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026-10-01 09:42:56.852 UTC [61209] ERROR: relation "goose_db_version" does not exist at character 367872026-10-01 09:42:56.852 UTC [61209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7882026-10-01 09:42:56.893 UTC [61208] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 09:42:56.893 UTC [61208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026-10-01 09:42:56.895 UTC [61210] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 09:42:56.895 UTC [61210] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 09:42:56.895 UTC [61211] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 09:42:56.895 UTC [61211] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026/10/01 09:42:56 OK 20241026095416_initial_model.sql (139.67ms)7952026/10/01 09:42:56 OK 20251210153512_drop_unused_gin_index.sql (12.02ms)7962026/10/01 09:42:56 OK 20251218171726_add_pins.sql (50.24ms)7972026/10/01 09:42:56 OK 20241026095416_initial_model.sql (133.2ms)7982026/10/01 09:42:56 OK 20251210153512_drop_unused_gin_index.sql (13.87ms)7992026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (71.39ms)8002026/10/01 09:42:57 OK 20251218171726_add_pins.sql (58.24ms)8012026/10/01 09:42:57 OK 20241026095416_initial_model.sql (197.13ms)8022026/10/01 09:42:57 OK 20241026095416_initial_model.sql (199.26ms)8032026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (9.77ms)8042026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (9.11ms)8052026-10-01 09:42:57.090 UTC [61212] ERROR: relation "goose_db_version" does not exist at character 368062026-10-01 09:42:57.090 UTC [61212] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8072026/10/01 09:42:57 OK 20260905000000_add_claims.sql (52.75ms)8082026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (51.99ms)8092026/10/01 09:42:57 OK 20251218171726_add_pins.sql (24.64ms)8102026/10/01 09:42:57 OK 20251218171726_add_pins.sql (32.28ms)8112026/10/01 09:42:57 OK 20241026095416_initial_model.sql (231.76ms)8122026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (14.93ms)8132026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (43.08ms)8142026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (39.45ms)8152026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (64.79ms)8162026/10/01 09:42:57 OK 20260905000000_add_claims.sql (70.54ms)8172026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (16.32ms)8182026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008192026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.12ms)8202026/10/01 09:42:57 OK 2_object_stats_trigger.sql (237.13µs)8212026/10/01 09:42:57 OK 3_commit_push.sql (224.38µs)8222026/10/01 09:42:57 goose: up to current file version: 38232026/10/01 09:42:57 OK 20251218171726_add_pins.sql (52.7ms)8242026/10/01 09:42:57 OK 20241026095416_initial_model.sql (277.84ms)8252026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (16.62ms)8262026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (72.68ms)8272026/10/01 09:42:57 OK 20260905000000_add_claims.sql (95.61ms)8282026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (50.67ms)8292026/10/01 09:42:57 OK 20260905000000_add_claims.sql (101.81ms)8302026/10/01 09:42:57 OK 20241026095416_initial_model.sql (269.59ms)8312026/10/01 09:42:57 OK 20241026095416_initial_model.sql (254.51ms)8322026/10/01 09:42:57 OK 20251218171726_add_pins.sql (34.56ms)8332026/10/01 09:42:57 OK 20241026095416_initial_model.sql (278.17ms)8342026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (19.37ms)8352026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008362026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.53ms)8372026/10/01 09:42:57 OK 2_object_stats_trigger.sql (367.13µs)8382026/10/01 09:42:57 OK 3_commit_push.sql (264.13µs)8392026/10/01 09:42:57 goose: up to current file version: 38402026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (22.7ms)8412026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (22.77ms)8422026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (22.52ms)8432026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (31.18ms)8442026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (57.51ms)8452026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (58.46ms)8462026/10/01 09:42:57 OK 20251218171726_add_pins.sql (35.48ms)8472026/10/01 09:42:57 OK 20251218171726_add_pins.sql (43.29ms)8482026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (23.46ms)8492026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008502026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.7ms)8512026/10/01 09:42:57 OK 2_object_stats_trigger.sql (367.04µs)8522026/10/01 09:42:57 OK 3_commit_push.sql (327.88µs)8532026/10/01 09:42:57 goose: up to current file version: 38542026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (31.48ms)8552026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008562026/10/01 09:42:57 OK 20251218171726_add_pins.sql (50.37ms)8572026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.91ms)8582026/10/01 09:42:57 OK 2_object_stats_trigger.sql (358.29µs)8592026/10/01 09:42:57 OK 3_commit_push.sql (301.75µs)8602026/10/01 09:42:57 goose: up to current file version: 38612026/10/01 09:42:57 OK 20260905000000_add_claims.sql (108.07ms)8622026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (54.61ms)8632026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (46.94ms)8642026/10/01 09:42:57 OK 20260905000000_add_claims.sql (93.87ms)8652026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (45.83ms)8662026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (48.23ms)8672026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (53.36ms)8682026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (31.84ms)8692026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008702026/10/01 09:42:57 OK 20260905000000_add_claims.sql (76.31ms)8712026/10/01 09:42:57 OK 20260905000000_add_claims.sql (76.39ms)8722026/10/01 09:42:57 OK 20241026095416_initial_model.sql (241.8ms)8732026/10/01 09:42:57 OK 20260905000000_add_claims.sql (56.39ms)8742026/10/01 09:42:57 OK 1_commit_pending_closure.sql (3.22ms)8752026/10/01 09:42:57 OK 2_object_stats_trigger.sql (401.92µs)8762026/10/01 09:42:57 OK 3_commit_push.sql (261.79µs)8772026/10/01 09:42:57 goose: up to current file version: 38782026/10/01 09:42:57 OK 20251210153512_drop_unused_gin_index.sql (4.56ms)8792026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (6.35ms)8802026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008812026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.53ms)8822026/10/01 09:42:57 OK 2_object_stats_trigger.sql (305.46µs)8832026/10/01 09:42:57 OK 3_commit_push.sql (266.46µs)8842026/10/01 09:42:57 goose: up to current file version: 38852026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (25.5ms)8862026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (30.25ms)8872026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (31.25ms)8882026/10/01 09:42:57 OK 20251218171726_add_pins.sql (28.33ms)8892026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (15.64ms)8902026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008912026/10/01 09:42:57 INFO Received uploads request method=POST path=/api/pending_closures8922026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.86ms)8932026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (10.58ms)8942026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008952026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (13.02ms)8962026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200008972026/10/01 09:42:57 OK 2_object_stats_trigger.sql (317.17µs)8982026/10/01 09:42:57 OK 3_commit_push.sql (270.96µs)8992026/10/01 09:42:57 goose: up to current file version: 39002026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.14ms)9012026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.13ms)9022026/10/01 09:42:57 OK 2_object_stats_trigger.sql (249.75µs)9032026/10/01 09:42:57 OK 2_object_stats_trigger.sql (258.58µs)9042026/10/01 09:42:57 OK 3_commit_push.sql (200.08µs)9052026/10/01 09:42:57 goose: up to current file version: 39062026/10/01 09:42:57 OK 3_commit_push.sql (193.21µs)9072026/10/01 09:42:57 goose: up to current file version: 39082026/10/01 09:42:57 OK 20260628120000_add_object_size_and_stats.sql (32.46ms)9092026/10/01 09:42:57 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9102026/10/01 09:42:57 INFO Received uploads request method=POST path=/api/pending_closures911--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.88s)912=== CONT TestRedundantMultipartUpload9132026/10/01 09:42:57 OK 20260905000000_add_claims.sql (107.08ms)9142026/10/01 09:42:57 OK 20260920000000_drop_claims.sql (65.27ms)9152026/10/01 09:42:57 OK 20260923120000_add_pushes.sql (24.59ms)9162026/10/01 09:42:57 goose: successfully migrated database to version: 202609231200009172026/10/01 09:42:57 OK 1_commit_pending_closure.sql (1.25ms)9182026/10/01 09:42:57 OK 2_object_stats_trigger.sql (334.79µs)9192026/10/01 09:42:57 OK 3_commit_push.sql (213.63µs)9202026/10/01 09:42:57 goose: up to current file version: 39212026/10/01 09:42:57 INFO Received uploads request method=POST path=/api/pending_closures9222026/10/01 09:42:58 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"923--- PASS: TestService_AuthMiddleware (3.46s)924=== CONT TestPush_SignsNarinfosOfItsPendingObjects9252026/10/01 09:42:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9262026/10/01 09:42:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9272026/10/01 09:42:58 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst928--- PASS: TestCompleteMultipartUnregistered (3.88s)929=== CONT TestPush_RejectsBadRequests9302026/10/01 09:42:58 INFO Received cleanup request method=DELETE path=/api/pending_closures9312026/10/01 09:42:58 INFO Aborted multipart uploads count=0 kept=09322026/10/01 09:42:58 INFO Received uploads request method=POST path=/api/pending_closures9332026/10/01 09:42:59 INFO Received cleanup request method=DELETE path=/api/pending_closures9342026/10/01 09:42:59 INFO Aborted multipart uploads count=1 kept=09352026/10/01 09:42:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9362026-10-01 09:42:59.058 UTC [61207] ERROR: Closure does not exist: id=19372026-10-01 09:42:59.058 UTC [61207] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE9382026-10-01 09:42:59.058 UTC [61207] STATEMENT: -- name: CommitPendingClosure :exec939 SELECT commit_pending_closure($1::bigint)940 941--- PASS: TestService_cleanupPendingClosuresHandler (4.42s)942=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9432026/10/01 09:42:59 INFO Received uploads request method=POST path=/api/pending_closures9442026/10/01 09:42:59 INFO Received uploads request method=POST path=/api/pending_closures9452026/10/01 09:43:00 INFO Received uploads request method=POST path=/api/pending_closures9462026/10/01 09:43:00 INFO Received uploads request method=POST path=/api/pending_closures9472026/10/01 09:43:00 INFO Received uploads request method=POST path=/api/pending_closures948--- PASS: TestService_Rustfstest (6.20s)949=== CONT TestPush_CompleteCommitsEveryRoot9502026-10-01 09:43:01.003 UTC [61253] ERROR: relation "goose_db_version" does not exist at character 369512026-10-01 09:43:01.003 UTC [61253] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9522026/10/01 09:43:01 INFO Received uploads request method=POST path=/api/pending_closures9532026/10/01 09:43:01 OK 20241026095416_initial_model.sql (463.77ms)9542026/10/01 09:43:01 OK 20251210153512_drop_unused_gin_index.sql (23.6ms)9552026/10/01 09:43:01 OK 20251218171726_add_pins.sql (60.97ms)9562026-10-01 09:43:01.858 UTC [61261] ERROR: relation "goose_db_version" does not exist at character 369572026-10-01 09:43:01.858 UTC [61261] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9582026/10/01 09:43:01 OK 20260628120000_add_object_size_and_stats.sql (251.23ms)9592026/10/01 09:43:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9602026/10/01 09:43:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9612026/10/01 09:43:02 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLmRjOGEzNjk3LTJjOGMtNGY2Yi04MDlmLWJkZjUwYjcyZDE4NXgxNzkwODQ3NzgxNTIxNjYwMDAw9622026/10/01 09:43:02 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLmRjOGEzNjk3LTJjOGMtNGY2Yi04MDlmLWJkZjUwYjcyZDE4NXgxNzkwODQ3NzgxNTIxNjYwMDAw parts=1963--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.43s)964=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9652026/10/01 09:43:02 OK 20260905000000_add_claims.sql (211.08ms)9662026/10/01 09:43:02 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLmE3YjY2YTU4LWJkZmItNDEyNC04OWNiLTU3ZDY1Y2Q0MmY1N3gxNzkwODQ3Nzc5NDA0MDIxMDAw parts=109672026/10/01 09:43:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9682026/10/01 09:43:02 INFO Completed upload id=19692026/10/01 09:43:02 INFO Received uploads request method=POST path=/api/pending_closures9702026/10/01 09:43:02 INFO Received uploads request method=POST path=/api/pending_closures9712026/10/01 09:43:02 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9722026/10/01 09:43:02 WARN Found objects in DB but missing from S3, will re-upload count=1973--- PASS: TestService_verifyS3Integrity (7.52s)974=== CONT TestReadRedirectUsesPublicS3URL9752026/10/01 09:43:02 OK 20260920000000_drop_claims.sql (90.12ms)9762026/10/01 09:43:02 OK 20260923120000_add_pushes.sql (29.11ms)9772026/10/01 09:43:02 goose: successfully migrated database to version: 202609231200009782026/10/01 09:43:02 OK 1_commit_pending_closure.sql (1.52ms)9792026/10/01 09:43:02 OK 2_object_stats_trigger.sql (326.75µs)9802026/10/01 09:43:02 OK 3_commit_push.sql (286.79µs)9812026/10/01 09:43:02 goose: up to current file version: 39822026/10/01 09:43:02 OK 20241026095416_initial_model.sql (329.19ms)9832026/10/01 09:43:02 OK 20251210153512_drop_unused_gin_index.sql (5.17ms)9842026/10/01 09:43:02 OK 20251218171726_add_pins.sql (55.1ms)9852026/10/01 09:43:02 OK 20260628120000_add_object_size_and_stats.sql (63.26ms)9862026-10-01 09:43:02.570 UTC [61273] ERROR: relation "goose_db_version" does not exist at character 369872026-10-01 09:43:02.570 UTC [61273] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9882026/10/01 09:43:02 OK 20260905000000_add_claims.sql (99.21ms)9892026/10/01 09:43:02 OK 20260920000000_drop_claims.sql (97.15ms)9902026/10/01 09:43:02 INFO Received uploads request method=POST path=/api/pending_closures9912026/10/01 09:43:02 OK 20260923120000_add_pushes.sql (50.59ms)9922026/10/01 09:43:02 goose: successfully migrated database to version: 202609231200009932026/10/01 09:43:02 OK 1_commit_pending_closure.sql (4.75ms)9942026/10/01 09:43:02 OK 2_object_stats_trigger.sql (1.01ms)9952026/10/01 09:43:02 OK 3_commit_push.sql (791.38µs)9962026/10/01 09:43:02 goose: up to current file version: 39972026/10/01 09:43:02 INFO Received uploads request method=POST path=/api/pending_closures9982026/10/01 09:43:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9992026/10/01 09:43:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10002026/10/01 09:43:03 OK 20241026095416_initial_model.sql (396.91ms)10012026/10/01 09:43:03 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLjA5MWMzMmEyLTc0ZmEtNDQ3NC05N2NmLWE0NDc0NDE5MjkwNHgxNzkwODQ3NzgwNDAxMDAxMDAw parts=1010022026/10/01 09:43:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10032026/10/01 09:43:03 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLmMzOGUxMzRiLWU4ZTAtNDE5Ni05MWVlLWQ5ZjhkZGYwNDI4M3gxNzkwODQ3Nzc5ODcyMjI5MDAw parts=1210042026/10/01 09:43:03 INFO Received uploads request method=POST path=/api/pending_closures1005--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.43s)1006=== CONT TestReadProxyRangeRequest10072026/10/01 09:43:03 OK 20251210153512_drop_unused_gin_index.sql (30.75ms)10082026/10/01 09:43:03 INFO Completed upload id=110092026/10/01 09:43:03 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010102026/10/01 09:43:03 INFO Received uploads request method=POST path=/api/pending_closures10112026/10/01 09:43:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures10122026/10/01 09:43:03 INFO Aborted multipart uploads count=0 kept=010132026/10/01 09:43:03 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010142026/10/01 09:43:03 OK 20251218171726_add_pins.sql (62.35ms)10152026/10/01 09:43:03 INFO Vacuumed table table=pending_closures10162026/10/01 09:43:03 INFO Received push request method=POST path=/api/pushes10172026/10/01 09:43:03 OK 20260628120000_add_object_size_and_stats.sql (63.11ms)10182026/10/01 09:43:03 INFO Vacuumed table table=pending_objects10192026/10/01 09:43:03 INFO Vacuumed table table=multipart_uploads10202026-10-01 09:43:03.296 UTC [61278] ERROR: relation "goose_db_version" does not exist at character 3610212026-10-01 09:43:03.296 UTC [61278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10222026/10/01 09:43:03 WARN Rate limiter enabled after throttle name=s3-test rate=510232026/10/01 09:43:03 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1024=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1025 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101026 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001027--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.67s)1028=== CONT TestReadRedirectKeepsNarinfoProxied10292026/10/01 09:43:03 OK 20260905000000_add_claims.sql (111.01ms)10302026/10/01 09:43:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10312026/10/01 09:43:03 INFO Signed narinfos id=1 count=11032--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.26s)1033=== CONT TestReadRedirectNar10342026/10/01 09:43:03 INFO Vacuumed table table=closures10352026/10/01 09:43:03 INFO Vacuumed table table=objects10362026/10/01 09:43:03 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001037--- PASS: TestService_createPendingClosureHandler (8.80s)1038=== CONT TestReadProxyDisabled10392026/10/01 09:43:03 OK 20260920000000_drop_claims.sql (95.6ms)10402026/10/01 09:43:03 OK 20260923120000_add_pushes.sql (39.28ms)10412026/10/01 09:43:03 goose: successfully migrated database to version: 2026092312000010422026/10/01 09:43:03 OK 1_commit_pending_closure.sql (1.26ms)10432026/10/01 09:43:03 OK 2_object_stats_trigger.sql (317.63µs)10442026/10/01 09:43:03 OK 3_commit_push.sql (252.42µs)10452026/10/01 09:43:03 goose: up to current file version: 310462026/10/01 09:43:03 OK 20241026095416_initial_model.sql (451.73ms)10472026/10/01 09:43:03 OK 20251210153512_drop_unused_gin_index.sql (21.96ms)10482026/10/01 09:43:03 OK 20251218171726_add_pins.sql (62.63ms)1049=== RUN TestPush_RejectsBadRequests/no_roots1050=== PAUSE TestPush_RejectsBadRequests/no_roots1051=== RUN TestPush_RejectsBadRequests/no_objects1052=== PAUSE TestPush_RejectsBadRequests/no_objects1053=== RUN TestPush_RejectsBadRequests/bad_root1054=== PAUSE TestPush_RejectsBadRequests/bad_root1055=== RUN TestPush_RejectsBadRequests/root_not_in_objects1056=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1057=== CONT TestReadProxyRootRedirectsToIndexHTML10582026/10/01 09:43:04 OK 20260628120000_add_object_size_and_stats.sql (94.26ms)10592026/10/01 09:43:04 OK 20260905000000_add_claims.sql (118.57ms)10602026/10/01 09:43:04 OK 20260920000000_drop_claims.sql (79.35ms)10612026/10/01 09:43:04 OK 20260923120000_add_pushes.sql (33.37ms)10622026/10/01 09:43:04 goose: successfully migrated database to version: 2026092312000010632026/10/01 09:43:04 OK 1_commit_pending_closure.sql (50.45ms)10642026/10/01 09:43:04 OK 2_object_stats_trigger.sql (1.48ms)10652026/10/01 09:43:04 OK 3_commit_push.sql (913.92µs)10662026/10/01 09:43:04 goose: up to current file version: 310672026/10/01 09:43:04 INFO Received push request method=POST path=/api/pushes10682026/10/01 09:43:04 INFO Received complete push request method=POST path=/api/pushes/1/complete10692026/10/01 09:43:04 INFO Received push request method=POST path=/api/pushes10702026/10/01 09:43:05 INFO Aborted multipart uploads count=0 kept=010712026/10/01 09:43:05 WARN Force mode enabled - objects will be deleted immediately without grace period10722026/10/01 09:43:05 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=010732026/10/01 09:43:05 INFO Vacuumed table table=pending_closures10742026/10/01 09:43:05 INFO Vacuumed table table=pending_objects10752026/10/01 09:43:05 INFO Vacuumed table table=multipart_uploads10762026/10/01 09:43:05 INFO Vacuumed table table=closures10772026/10/01 09:43:05 INFO Vacuumed table table=objects10782026/10/01 09:43:05 INFO Received complete push request method=POST path=/api/pushes/2/complete1079--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.37s)1080=== CONT TestReadProxyConditionalGet10812026/10/01 09:43:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10822026/10/01 09:43:05 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLjAxYTA0ZmRmLTM2OWYtNDNkMy1hNjJmLWZmNzMwM2M2MzJiZXgxNzkwODQ3NzgyNzcyMDExMDAw parts=1210832026/10/01 09:43:05 INFO Received uploads request method=POST path=/api/pending_closures10842026/10/01 09:43:05 INFO Received uploads request method=POST path=/api/pending_closures10852026-10-01 09:43:06.145 UTC [61301] ERROR: relation "goose_db_version" does not exist at character 3610862026-10-01 09:43:06.145 UTC [61301] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10872026-10-01 09:43:06.587 UTC [61308] ERROR: relation "goose_db_version" does not exist at character 3610882026-10-01 09:43:06.587 UTC [61308] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10892026-10-01 09:43:06.718 UTC [61312] ERROR: relation "goose_db_version" does not exist at character 3610902026-10-01 09:43:06.718 UTC [61312] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10912026/10/01 09:43:06 OK 20241026095416_initial_model.sql (340.02ms)10922026/10/01 09:43:06 OK 20251210153512_drop_unused_gin_index.sql (26.27ms)10932026/10/01 09:43:06 OK 20251218171726_add_pins.sql (51.63ms)10942026/10/01 09:43:06 OK 20260628120000_add_object_size_and_stats.sql (63.86ms)10952026/10/01 09:43:07 OK 20260905000000_add_claims.sql (143.35ms)10962026/10/01 09:43:07 OK 20241026095416_initial_model.sql (322.51ms)10972026/10/01 09:43:07 OK 20251210153512_drop_unused_gin_index.sql (8.76ms)10982026/10/01 09:43:07 OK 20251218171726_add_pins.sql (35.32ms)10992026/10/01 09:43:07 OK 20260920000000_drop_claims.sql (51.25ms)11002026/10/01 09:43:07 OK 20260923120000_add_pushes.sql (34.7ms)11012026/10/01 09:43:07 goose: successfully migrated database to version: 2026092312000011022026/10/01 09:43:07 OK 1_commit_pending_closure.sql (2.63ms)11032026/10/01 09:43:07 OK 2_object_stats_trigger.sql (558.96µs)11042026/10/01 09:43:07 OK 3_commit_push.sql (431.13µs)11052026/10/01 09:43:07 goose: up to current file version: 311062026/10/01 09:43:07 OK 20260628120000_add_object_size_and_stats.sql (72.1ms)11072026/10/01 09:43:07 OK 20241026095416_initial_model.sql (327.68ms)11082026/10/01 09:43:07 OK 20251210153512_drop_unused_gin_index.sql (19.78ms)11092026/10/01 09:43:07 OK 20251218171726_add_pins.sql (61.53ms)11102026/10/01 09:43:07 OK 20260905000000_add_claims.sql (148.47ms)11112026/10/01 09:43:07 OK 20260628120000_add_object_size_and_stats.sql (69.19ms)11122026/10/01 09:43:07 OK 20260920000000_drop_claims.sql (99.6ms)11132026/10/01 09:43:07 OK 20260923120000_add_pushes.sql (45.82ms)11142026/10/01 09:43:07 goose: successfully migrated database to version: 2026092312000011152026/10/01 09:43:07 OK 1_commit_pending_closure.sql (5.42ms)11162026/10/01 09:43:07 OK 2_object_stats_trigger.sql (872.13µs)11172026/10/01 09:43:07 OK 3_commit_push.sql (579.54µs)11182026/10/01 09:43:07 goose: up to current file version: 311192026/10/01 09:43:07 OK 20260905000000_add_claims.sql (162.16ms)11202026/10/01 09:43:07 OK 20260920000000_drop_claims.sql (95.76ms)11212026/10/01 09:43:07 OK 20260923120000_add_pushes.sql (24.31ms)11222026/10/01 09:43:07 goose: successfully migrated database to version: 2026092312000011232026/10/01 09:43:07 OK 1_commit_pending_closure.sql (2.77ms)11242026/10/01 09:43:07 OK 2_object_stats_trigger.sql (666.17µs)11252026/10/01 09:43:07 OK 3_commit_push.sql (404.21µs)11262026/10/01 09:43:07 goose: up to current file version: 311272026/10/01 09:43:07 INFO Received push request method=POST path=/api/pushes11282026/10/01 09:43:07 INFO Received complete push request method=POST path=/api/pushes/1/complete1129--- PASS: TestPush_CompleteCommitsEveryRoot (7.03s)1130=== CONT TestReadProxyHead11312026-10-01 09:43:08.113 UTC [61314] ERROR: relation "goose_db_version" does not exist at character 3611322026-10-01 09:43:08.113 UTC [61314] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11332026/10/01 09:43:08 INFO Received push request method=POST path=/api/pushes1134--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.30s)1135=== CONT TestReadProxyInvalidPath11362026-10-01 09:43:08.669 UTC [61325] ERROR: relation "goose_db_version" does not exist at character 3611372026-10-01 09:43:08.669 UTC [61325] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11382026/10/01 09:43:08 OK 20241026095416_initial_model.sql (394.53ms)11392026/10/01 09:43:08 OK 20251210153512_drop_unused_gin_index.sql (31.75ms)11402026/10/01 09:43:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11412026-10-01 09:43:08.763 UTC [61328] ERROR: relation "goose_db_version" does not exist at character 3611422026-10-01 09:43:08.763 UTC [61328] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11432026/10/01 09:43:08 OK 20251218171726_add_pins.sql (85.01ms)1144--- PASS: TestReadRedirectUsesPublicS3URL (6.63s)1145=== CONT TestReadProxy40411462026/10/01 09:43:08 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLjU5MDA5MjEzLWIxOTUtNGRhMS1hZTRlLTUzYTc1MmIzNDc1OHgxNzkwODQ3Nzg1OTE0MDM5MDAw error="Get \"http://127.0.0.1:1/bucket13/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11472026/10/01 09:43:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=M2YzN2I2NzktZGFmNi00MGQ2LTg1Y2MtNmQyMjU5MTVjNzhlLjU2NjYzMWMwLTBiMWQtNDhmMi1hODMzLTQ2NWUwNzI0NzVmOHgxNzkwODQ3Nzg1ODUyNjMwMDAw parts=1211482026/10/01 09:43:08 INFO Received cleanup request method=DELETE path=/api/pending_closures11492026-10-01 09:43:08.821 UTC [61330] ERROR: relation "goose_db_version" does not exist at character 3611502026-10-01 09:43:08.821 UTC [61330] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11512026/10/01 09:43:08 INFO Aborted multipart uploads count=1 kept=01152--- PASS: TestRedundantMultipartUpload (11.30s)1153=== CONT TestReadProxyNarStreaming11542026/10/01 09:43:08 OK 20260628120000_add_object_size_and_stats.sql (70.34ms)11552026/10/01 09:43:08 OK 20260905000000_add_claims.sql (96.46ms)11562026/10/01 09:43:08 OK 20260920000000_drop_claims.sql (36.72ms)11572026/10/01 09:43:09 OK 20260923120000_add_pushes.sql (19.65ms)11582026/10/01 09:43:09 goose: successfully migrated database to version: 2026092312000011592026/10/01 09:43:09 OK 1_commit_pending_closure.sql (851.46µs)11602026/10/01 09:43:09 OK 2_object_stats_trigger.sql (243.25µs)11612026/10/01 09:43:09 OK 3_commit_push.sql (165µs)11622026/10/01 09:43:09 goose: up to current file version: 311632026/10/01 09:43:09 OK 20241026095416_initial_model.sql (274.65ms)11642026/10/01 09:43:09 OK 20251210153512_drop_unused_gin_index.sql (18.43ms)11652026/10/01 09:43:09 OK 20241026095416_initial_model.sql (329.37ms)11662026-10-01 09:43:09.197 UTC [61344] ERROR: relation "goose_db_version" does not exist at character 3611672026-10-01 09:43:09.197 UTC [61344] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11682026/10/01 09:43:09 OK 20251218171726_add_pins.sql (60.5ms)11692026/10/01 09:43:09 OK 20241026095416_initial_model.sql (278.49ms)11702026/10/01 09:43:09 OK 20251210153512_drop_unused_gin_index.sql (28.82ms)11712026/10/01 09:43:09 OK 20251210153512_drop_unused_gin_index.sql (26.94ms)11722026/10/01 09:43:09 OK 20260628120000_add_object_size_and_stats.sql (71.89ms)11732026/10/01 09:43:09 OK 20251218171726_add_pins.sql (59.27ms)11742026/10/01 09:43:09 OK 20251218171726_add_pins.sql (59.56ms)11752026/10/01 09:43:09 OK 20260628120000_add_object_size_and_stats.sql (62.44ms)11762026/10/01 09:43:09 OK 20260628120000_add_object_size_and_stats.sql (70.48ms)11772026/10/01 09:43:09 OK 20260905000000_add_claims.sql (99.37ms)11782026/10/01 09:43:09 OK 20260920000000_drop_claims.sql (101.04ms)11792026/10/01 09:43:09 OK 20260905000000_add_claims.sql (122.46ms)11802026/10/01 09:43:09 OK 20260905000000_add_claims.sql (138.52ms)1181--- PASS: TestReadProxyRangeRequest (6.39s)1182=== CONT TestReadProxyNarinfoAlreadyDecompressed11832026/10/01 09:43:09 OK 20260923120000_add_pushes.sql (25.56ms)11842026/10/01 09:43:09 goose: successfully migrated database to version: 2026092312000011852026/10/01 09:43:09 OK 1_commit_pending_closure.sql (956.38µs)11862026/10/01 09:43:09 OK 2_object_stats_trigger.sql (225.17µs)11872026/10/01 09:43:09 OK 3_commit_push.sql (189.75µs)11882026/10/01 09:43:09 goose: up to current file version: 311892026/10/01 09:43:09 OK 20260920000000_drop_claims.sql (105.32ms)11902026/10/01 09:43:09 OK 20260920000000_drop_claims.sql (124.16ms)11912026/10/01 09:43:09 OK 20260923120000_add_pushes.sql (18.88ms)11922026/10/01 09:43:09 goose: successfully migrated database to version: 2026092312000011932026/10/01 09:43:09 OK 1_commit_pending_closure.sql (1.24ms)11942026/10/01 09:43:09 OK 2_object_stats_trigger.sql (940µs)11952026/10/01 09:43:09 OK 3_commit_push.sql (214.38µs)11962026/10/01 09:43:09 goose: up to current file version: 311972026/10/01 09:43:09 OK 20260923120000_add_pushes.sql (34.8ms)11982026/10/01 09:43:09 goose: successfully migrated database to version: 2026092312000011992026/10/01 09:43:09 OK 20241026095416_initial_model.sql (350.25ms)12002026/10/01 09:43:09 OK 1_commit_pending_closure.sql (1.58ms)12012026/10/01 09:43:09 OK 2_object_stats_trigger.sql (272.88µs)12022026/10/01 09:43:09 OK 3_commit_push.sql (215.92µs)12032026/10/01 09:43:09 goose: up to current file version: 312042026/10/01 09:43:09 OK 20251210153512_drop_unused_gin_index.sql (29.55ms)12052026/10/01 09:43:09 OK 20251218171726_add_pins.sql (67.6ms)12062026/10/01 09:43:09 OK 20260628120000_add_object_size_and_stats.sql (36.86ms)12072026-10-01 09:43:09.875 UTC [61361] ERROR: relation "goose_db_version" does not exist at character 3612082026-10-01 09:43:09.875 UTC [61361] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12092026/10/01 09:43:09 OK 20260905000000_add_claims.sql (128.88ms)1210--- PASS: TestReadRedirectNar (6.61s)1211=== CONT TestReadProxyNarinfo12122026/10/01 09:43:09 OK 20260920000000_drop_claims.sql (69.09ms)12132026/10/01 09:43:10 OK 20260923120000_add_pushes.sql (43.93ms)12142026/10/01 09:43:10 goose: successfully migrated database to version: 2026092312000012152026/10/01 09:43:10 OK 1_commit_pending_closure.sql (1.23ms)12162026/10/01 09:43:10 OK 2_object_stats_trigger.sql (249.5µs)12172026/10/01 09:43:10 OK 3_commit_push.sql (216.04µs)12182026/10/01 09:43:10 goose: up to current file version: 312192026/10/01 09:43:10 OK 20241026095416_initial_model.sql (367.72ms)12202026/10/01 09:43:10 OK 20251210153512_drop_unused_gin_index.sql (21.08ms)1221--- PASS: TestReadRedirectKeepsNarinfoProxied (7.10s)1222=== CONT TestIsValidCachePath1223=== RUN TestIsValidCachePath/narinfo1224=== PAUSE TestIsValidCachePath/narinfo1225=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1226=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1227=== RUN TestIsValidCachePath/nar_zst1228=== PAUSE TestIsValidCachePath/nar_zst1229=== RUN TestIsValidCachePath/nar_xz1230=== PAUSE TestIsValidCachePath/nar_xz1231=== RUN TestIsValidCachePath/nar_bz21232=== PAUSE TestIsValidCachePath/nar_bz21233=== RUN TestIsValidCachePath/nar_uncompressed1234=== PAUSE TestIsValidCachePath/nar_uncompressed1235=== RUN TestIsValidCachePath/ls1236=== PAUSE TestIsValidCachePath/ls1237=== RUN TestIsValidCachePath/log1238=== PAUSE TestIsValidCachePath/log1239=== RUN TestIsValidCachePath/realisation1240=== PAUSE TestIsValidCachePath/realisation1241=== RUN TestIsValidCachePath/nix-cache-info1242=== PAUSE TestIsValidCachePath/nix-cache-info1243=== RUN TestIsValidCachePath/index.html1244=== PAUSE TestIsValidCachePath/index.html1245=== RUN TestIsValidCachePath/traversal_parent1246=== PAUSE TestIsValidCachePath/traversal_parent1247=== RUN TestIsValidCachePath/traversal_in_middle1248=== PAUSE TestIsValidCachePath/traversal_in_middle1249=== RUN TestIsValidCachePath/invalid_char_e1250=== PAUSE TestIsValidCachePath/invalid_char_e1251=== RUN TestIsValidCachePath/invalid_char_u1252=== PAUSE TestIsValidCachePath/invalid_char_u1253=== RUN TestIsValidCachePath/random_path1254=== PAUSE TestIsValidCachePath/random_path1255=== RUN TestIsValidCachePath/empty1256=== PAUSE TestIsValidCachePath/empty1257=== RUN TestIsValidCachePath/leading_slash1258=== PAUSE TestIsValidCachePath/leading_slash1259=== RUN TestIsValidCachePath/wrong_extension1260=== PAUSE TestIsValidCachePath/wrong_extension1261=== RUN TestIsValidCachePath/short_hash1262=== PAUSE TestIsValidCachePath/short_hash1263=== CONT TestProxyHeadersOnlyTrustedOnSocket12642026/10/01 09:43:10 OK 20251218171726_add_pins.sql (72.38ms)12652026/10/01 09:43:10 OK 20260628120000_add_object_size_and_stats.sql (78.73ms)12662026/10/01 09:43:10 OK 20260905000000_add_claims.sql (140.03ms)12672026/10/01 09:43:10 OK 20260920000000_drop_claims.sql (73.93ms)12682026/10/01 09:43:10 OK 20260923120000_add_pushes.sql (13.07ms)12692026/10/01 09:43:10 goose: successfully migrated database to version: 2026092312000012702026/10/01 09:43:10 OK 1_commit_pending_closure.sql (1.05ms)12712026/10/01 09:43:10 OK 2_object_stats_trigger.sql (258.88µs)12722026/10/01 09:43:10 OK 3_commit_push.sql (170.33µs)12732026/10/01 09:43:10 goose: up to current file version: 31274--- PASS: TestReadProxyDisabled (7.44s)1275=== CONT TestParseSingleRange1276=== RUN TestParseSingleRange/none1277=== PAUSE TestParseSingleRange/none1278=== RUN TestParseSingleRange/unknown_unit1279=== PAUSE TestParseSingleRange/unknown_unit1280=== RUN TestParseSingleRange/multi-range_ignored1281=== PAUSE TestParseSingleRange/multi-range_ignored1282=== RUN TestParseSingleRange/malformed_no_dash1283=== PAUSE TestParseSingleRange/malformed_no_dash1284=== RUN TestParseSingleRange/malformed_both_empty1285=== PAUSE TestParseSingleRange/malformed_both_empty1286=== RUN TestParseSingleRange/malformed_end_before_start1287=== PAUSE TestParseSingleRange/malformed_end_before_start1288=== RUN TestParseSingleRange/closed1289=== PAUSE TestParseSingleRange/closed1290=== RUN TestParseSingleRange/open-ended1291=== PAUSE TestParseSingleRange/open-ended1292=== RUN TestParseSingleRange/end_clamped_to_size1293=== PAUSE TestParseSingleRange/end_clamped_to_size1294=== RUN TestParseSingleRange/suffix1295=== PAUSE TestParseSingleRange/suffix1296=== RUN TestParseSingleRange/suffix_exceeds_size1297=== PAUSE TestParseSingleRange/suffix_exceeds_size1298=== RUN TestParseSingleRange/single_byte1299=== PAUSE TestParseSingleRange/single_byte1300=== RUN TestParseSingleRange/start_past_EOF1301=== PAUSE TestParseSingleRange/start_past_EOF1302=== RUN TestParseSingleRange/start_far_past_EOF1303=== PAUSE TestParseSingleRange/start_far_past_EOF1304=== CONT TestPresentNotReportedWhileGCDeletesClosure1305--- PASS: TestReadProxyRootRedirectsToIndexHTML (7.32s)1306=== CONT TestPresentReportsOnlyClosureRoots1307--- PASS: TestReadProxyConditionalGet (6.36s)1308=== CONT TestCreatePin_ReservedPins13092026/10/01 09:43:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51358/oidc13102026-10-01 09:43:12.363 UTC [61420] ERROR: relation "goose_db_version" does not exist at character 3613112026-10-01 09:43:12.363 UTC [61420] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13122026-10-01 09:43:12.725 UTC [61433] ERROR: relation "goose_db_version" does not exist at character 3613132026-10-01 09:43:12.725 UTC [61433] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13142026/10/01 09:43:12 OK 20241026095416_initial_model.sql (305.5ms)13152026/10/01 09:43:12 OK 20251210153512_drop_unused_gin_index.sql (16.2ms)13162026/10/01 09:43:12 OK 20251218171726_add_pins.sql (35.97ms)13172026-10-01 09:43:12.858 UTC [61438] ERROR: relation "goose_db_version" does not exist at character 3613182026-10-01 09:43:12.858 UTC [61438] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13192026/10/01 09:43:12 OK 20260628120000_add_object_size_and_stats.sql (47.61ms)13202026/10/01 09:43:12 OK 20260905000000_add_claims.sql (28.98ms)13212026-10-01 09:43:12.924 UTC [61446] ERROR: relation "goose_db_version" does not exist at character 3613222026-10-01 09:43:12.924 UTC [61446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13232026/10/01 09:43:12 OK 20260920000000_drop_claims.sql (42.18ms)13242026/10/01 09:43:12 OK 20260923120000_add_pushes.sql (11.69ms)13252026/10/01 09:43:12 goose: successfully migrated database to version: 2026092312000013262026/10/01 09:43:12 OK 1_commit_pending_closure.sql (1.06ms)13272026/10/01 09:43:12 OK 2_object_stats_trigger.sql (227.21µs)13282026/10/01 09:43:12 OK 3_commit_push.sql (176.58µs)13292026/10/01 09:43:12 goose: up to current file version: 313302026/10/01 09:43:13 OK 20241026095416_initial_model.sql (206.73ms)13312026/10/01 09:43:13 OK 20251210153512_drop_unused_gin_index.sql (27.55ms)13322026/10/01 09:43:13 OK 20251218171726_add_pins.sql (48.24ms)13332026/10/01 09:43:13 OK 20260628120000_add_object_size_and_stats.sql (92.82ms)13342026/10/01 09:43:13 OK 20241026095416_initial_model.sql (281.04ms)13352026-10-01 09:43:13.210 UTC [61451] ERROR: relation "goose_db_version" does not exist at character 3613362026-10-01 09:43:13.210 UTC [61451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13372026/10/01 09:43:13 OK 20251210153512_drop_unused_gin_index.sql (18.8ms)13382026/10/01 09:43:13 OK 20251218171726_add_pins.sql (35.79ms)13392026/10/01 09:43:13 OK 20241026095416_initial_model.sql (256.35ms)13402026/10/01 09:43:13 OK 20251210153512_drop_unused_gin_index.sql (8.17ms)13412026/10/01 09:43:13 OK 20260905000000_add_claims.sql (73.48ms)13422026/10/01 09:43:13 OK 20260628120000_add_object_size_and_stats.sql (44.02ms)13432026/10/01 09:43:13 OK 20251218171726_add_pins.sql (36.05ms)13442026/10/01 09:43:13 OK 20260920000000_drop_claims.sql (42.51ms)1345--- PASS: TestReadProxyHead (5.41s)1346=== CONT TestOrphanedObjectsGCStressTest13472026/10/01 09:43:13 OK 20260923120000_add_pushes.sql (21.68ms)13482026/10/01 09:43:13 goose: successfully migrated database to version: 2026092312000013492026/10/01 09:43:13 OK 20260628120000_add_object_size_and_stats.sql (29.95ms)13502026/10/01 09:43:13 OK 20260905000000_add_claims.sql (39.59ms)13512026/10/01 09:43:13 OK 1_commit_pending_closure.sql (2.47ms)13522026/10/01 09:43:13 OK 2_object_stats_trigger.sql (252.46µs)13532026/10/01 09:43:13 OK 3_commit_push.sql (322.92µs)13542026/10/01 09:43:13 goose: up to current file version: 313552026-10-01 09:43:13.349 UTC [61458] ERROR: relation "goose_db_version" does not exist at character 3613562026-10-01 09:43:13.349 UTC [61458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13572026/10/01 09:43:13 OK 20260920000000_drop_claims.sql (56.6ms)13582026/10/01 09:43:13 OK 20260905000000_add_claims.sql (57.95ms)13592026/10/01 09:43:13 OK 20260923120000_add_pushes.sql (12.35ms)13602026/10/01 09:43:13 goose: successfully migrated database to version: 2026092312000013612026/10/01 09:43:13 OK 1_commit_pending_closure.sql (1.16ms)13622026/10/01 09:43:13 OK 2_object_stats_trigger.sql (221.33µs)13632026/10/01 09:43:13 OK 3_commit_push.sql (153.79µs)13642026/10/01 09:43:13 goose: up to current file version: 313652026/10/01 09:43:13 OK 20260920000000_drop_claims.sql (22.39ms)13662026/10/01 09:43:13 OK 20260923120000_add_pushes.sql (15.83ms)13672026/10/01 09:43:13 goose: successfully migrated database to version: 2026092312000013682026/10/01 09:43:13 OK 1_commit_pending_closure.sql (847.21µs)13692026/10/01 09:43:13 OK 2_object_stats_trigger.sql (219.17µs)13702026/10/01 09:43:13 OK 3_commit_push.sql (178.58µs)13712026/10/01 09:43:13 goose: up to current file version: 313722026/10/01 09:43:13 OK 20241026095416_initial_model.sql (174.9ms)13732026/10/01 09:43:13 OK 20251210153512_drop_unused_gin_index.sql (991.42µs)13742026/10/01 09:43:13 OK 20251218171726_add_pins.sql (34.81ms)13752026/10/01 09:43:13 OK 20260628120000_add_object_size_and_stats.sql (60.56ms)13762026/10/01 09:43:13 OK 20260905000000_add_claims.sql (101.9ms)13772026/10/01 09:43:13 OK 20241026095416_initial_model.sql (253.27ms)13782026/10/01 09:43:13 OK 20251210153512_drop_unused_gin_index.sql (8.07ms)1379--- PASS: TestReadProxyInvalidPath (5.27s)1380=== CONT TestOrphanedObjectsGC13812026/10/01 09:43:13 OK 20260920000000_drop_claims.sql (78.77ms)13822026-10-01 09:43:13.738 UTC [61465] ERROR: relation "goose_db_version" does not exist at character 3613832026-10-01 09:43:13.738 UTC [61465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13842026/10/01 09:43:13 OK 20251218171726_add_pins.sql (65.89ms)13852026/10/01 09:43:13 OK 20260923120000_add_pushes.sql (34.92ms)13862026/10/01 09:43:13 goose: successfully migrated database to version: 2026092312000013872026/10/01 09:43:13 OK 1_commit_pending_closure.sql (1.39ms)13882026/10/01 09:43:13 OK 2_object_stats_trigger.sql (330.42µs)13892026/10/01 09:43:13 OK 3_commit_push.sql (273.04µs)13902026/10/01 09:43:13 goose: up to current file version: 313912026/10/01 09:43:13 OK 20260628120000_add_object_size_and_stats.sql (56.95ms)13922026/10/01 09:43:13 OK 20260905000000_add_claims.sql (82.5ms)13932026/10/01 09:43:13 OK 20260920000000_drop_claims.sql (46.71ms)13942026/10/01 09:43:13 OK 20260923120000_add_pushes.sql (36.64ms)13952026/10/01 09:43:13 goose: successfully migrated database to version: 2026092312000013962026/10/01 09:43:13 OK 1_commit_pending_closure.sql (1.85ms)13972026/10/01 09:43:13 OK 2_object_stats_trigger.sql (331.88µs)13982026/10/01 09:43:13 OK 3_commit_push.sql (253.63µs)13992026/10/01 09:43:13 goose: up to current file version: 31400--- PASS: TestReadProxy404 (5.29s)1401=== CONT TestObjectStatsTrigger14022026/10/01 09:43:14 OK 20241026095416_initial_model.sql (289.23ms)14032026/10/01 09:43:14 OK 20251210153512_drop_unused_gin_index.sql (9.67ms)14042026/10/01 09:43:14 OK 20251218171726_add_pins.sql (56.78ms)14052026-10-01 09:43:14.189 UTC [61475] ERROR: relation "goose_db_version" does not exist at character 3614062026-10-01 09:43:14.189 UTC [61475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14072026/10/01 09:43:14 OK 20260628120000_add_object_size_and_stats.sql (43.47ms)14082026/10/01 09:43:14 OK 20260905000000_add_claims.sql (130.61ms)14092026/10/01 09:43:14 OK 20260920000000_drop_claims.sql (65.14ms)14102026/10/01 09:43:14 OK 20260923120000_add_pushes.sql (25.59ms)14112026/10/01 09:43:14 goose: successfully migrated database to version: 2026092312000014122026/10/01 09:43:14 OK 1_commit_pending_closure.sql (1.23ms)14132026/10/01 09:43:14 OK 2_object_stats_trigger.sql (311.54µs)14142026/10/01 09:43:14 OK 3_commit_push.sql (210.38µs)14152026/10/01 09:43:14 goose: up to current file version: 31416--- PASS: TestReadProxyNarStreaming (5.69s)1417=== CONT TestMultipartCleanup14182026/10/01 09:43:14 OK 20241026095416_initial_model.sql (277.03ms)14192026/10/01 09:43:14 OK 20251210153512_drop_unused_gin_index.sql (19.3ms)14202026/10/01 09:43:14 OK 20251218171726_add_pins.sql (50.77ms)14212026/10/01 09:43:14 OK 20260628120000_add_object_size_and_stats.sql (45.05ms)14222026-10-01 09:43:14.706 UTC [61480] ERROR: relation "goose_db_version" does not exist at character 3614232026-10-01 09:43:14.706 UTC [61480] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14242026/10/01 09:43:14 OK 20260905000000_add_claims.sql (48.91ms)14252026/10/01 09:43:14 OK 20260920000000_drop_claims.sql (49.03ms)14262026/10/01 09:43:14 OK 20260923120000_add_pushes.sql (21.52ms)14272026/10/01 09:43:14 goose: successfully migrated database to version: 2026092312000014282026/10/01 09:43:14 OK 1_commit_pending_closure.sql (1.01ms)14292026/10/01 09:43:14 OK 2_object_stats_trigger.sql (249.42µs)14302026/10/01 09:43:14 OK 3_commit_push.sql (189.13µs)14312026/10/01 09:43:14 goose: up to current file version: 31432--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.39s)1433=== CONT TestServerTLSConfig1434=== RUN TestServerTLSConfig/no_client_CA1435=== PAUSE TestServerTLSConfig/no_client_CA1436=== RUN TestServerTLSConfig/missing_CA_file1437=== PAUSE TestServerTLSConfig/missing_CA_file1438=== RUN TestServerTLSConfig/not_a_PEM_file1439=== PAUSE TestServerTLSConfig/not_a_PEM_file1440=== CONT TestService_NativeMTLS14412026-10-01 09:43:14.968 UTC [61483] ERROR: relation "goose_db_version" does not exist at character 3614422026-10-01 09:43:14.968 UTC [61483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14432026/10/01 09:43:15 OK 20241026095416_initial_model.sql (271.57ms)14442026/10/01 09:43:15 OK 20251210153512_drop_unused_gin_index.sql (17.81ms)14452026/10/01 09:43:15 OK 20251218171726_add_pins.sql (26.38ms)14462026/10/01 09:43:15 OK 20260628120000_add_object_size_and_stats.sql (119.44ms)1447--- PASS: TestReadProxyNarinfo (5.26s)1448=== CONT TestMetricsInventory14492026/10/01 09:43:15 OK 20260905000000_add_claims.sql (68.14ms)14502026/10/01 09:43:15 OK 20241026095416_initial_model.sql (238.94ms)14512026/10/01 09:43:15 OK 20260920000000_drop_claims.sql (39.74ms)14522026/10/01 09:43:15 OK 20251210153512_drop_unused_gin_index.sql (14.64ms)14532026/10/01 09:43:15 OK 20260923120000_add_pushes.sql (27.56ms)14542026/10/01 09:43:15 goose: successfully migrated database to version: 2026092312000014552026/10/01 09:43:15 OK 1_commit_pending_closure.sql (1.53ms)14562026/10/01 09:43:15 OK 2_object_stats_trigger.sql (293.92µs)14572026/10/01 09:43:15 OK 3_commit_push.sql (244.88µs)14582026/10/01 09:43:15 goose: up to current file version: 314592026/10/01 09:43:15 OK 20251218171726_add_pins.sql (36.63ms)14602026/10/01 09:43:15 OK 20260628120000_add_object_size_and_stats.sql (22.78ms)14612026/10/01 09:43:15 OK 20260905000000_add_claims.sql (50.14ms)14622026/10/01 09:43:15 OK 20260920000000_drop_claims.sql (41.17ms)14632026/10/01 09:43:15 INFO Starting HTTP server address=/nix/var/nix/builds/nix-60884-3569518374/TestProxyHeadersOnlyTrustedOnSocket3798799589/001/proxy.sock14642026/10/01 09:43:15 INFO Starting HTTP server address=127.0.0.1:5144814652026/10/01 09:43:15 WARN mTLS auth: subject not in bound subjects subject="CN=someone"14662026/10/01 09:43:15 INFO Shutdown signal received, draining in-flight requests timeout=10s14672026/10/01 09:43:15 OK 20260923120000_add_pushes.sql (5.68ms)14682026/10/01 09:43:15 goose: successfully migrated database to version: 2026092312000014692026/10/01 09:43:15 OK 1_commit_pending_closure.sql (1.7ms)14702026/10/01 09:43:15 OK 2_object_stats_trigger.sql (346.54µs)14712026/10/01 09:43:15 OK 3_commit_push.sql (273.58µs)14722026/10/01 09:43:15 goose: up to current file version: 31473--- PASS: TestProxyHeadersOnlyTrustedOnSocket (5.05s)1474=== CONT TestNARDeduplicationMetadataUploadBug14752026-10-01 09:43:15.811 UTC [61499] ERROR: relation "goose_db_version" does not exist at character 3614762026-10-01 09:43:15.811 UTC [61499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1477--- PASS: TestPresentReportsOnlyClosureRoots (4.85s)1478=== CONT TestCreatePendingClosureRejectsOversizedNAR14792026/10/01 09:43:16 INFO Received uploads request method=POST path=/api/pending_closures1480--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1481=== CONT TestCacheConfigHandlerMaxNarSize1482--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1483=== CONT TestGenerateLandingPage1484--- PASS: TestGenerateLandingPage (0.00s)1485=== CONT TestService_readinessHandler14862026/10/01 09:43:16 OK 20241026095416_initial_model.sql (337.81ms)14872026/10/01 09:43:16 OK 20251210153512_drop_unused_gin_index.sql (16.29ms)14882026/10/01 09:43:16 OK 20251218171726_add_pins.sql (121.05ms)1489--- PASS: TestPresentNotReportedWhileGCDeletesClosure (5.48s)1490=== CONT TestService_healthCheckHandler14912026/10/01 09:43:16 OK 20260628120000_add_object_size_and_stats.sql (55.25ms)14922026/10/01 09:43:16 OK 20260905000000_add_claims.sql (99.76ms)14932026/10/01 09:43:16 OK 20260920000000_drop_claims.sql (37.89ms)14942026/10/01 09:43:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14952026/10/01 09:43:16 WARN Refused reserved pin name=worker-x86_64-linux14962026/10/01 09:43:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14972026/10/01 09:43:16 INFO Received create pin request method=POST path=/api/pins/my-app14982026/10/01 09:43:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1499--- PASS: TestCreatePin_ReservedPins (4.78s)1500=== CONT TestGracefulShutdownDrainsInflight15012026/10/01 09:43:16 INFO Starting HTTP server address=127.0.0.1:5146915022026/10/01 09:43:16 INFO Shutdown signal received, draining in-flight requests timeout=10s15032026/10/01 09:43:16 OK 20260923120000_add_pushes.sql (35.17ms)15042026/10/01 09:43:16 goose: successfully migrated database to version: 2026092312000015052026-10-01 09:43:16.582 UTC [61505] ERROR: relation "goose_db_version" does not exist at character 3615062026-10-01 09:43:16.582 UTC [61505] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15072026/10/01 09:43:16 OK 1_commit_pending_closure.sql (3.53ms)15082026/10/01 09:43:16 OK 2_object_stats_trigger.sql (564.75µs)15092026/10/01 09:43:16 OK 3_commit_push.sql (321.92µs)15102026/10/01 09:43:16 goose: up to current file version: 31511--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1512=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT15132026-10-01 09:43:16.801 UTC [61508] ERROR: relation "goose_db_version" does not exist at character 3615142026-10-01 09:43:16.801 UTC [61508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15152026/10/01 09:43:16 OK 20241026095416_initial_model.sql (178.4ms)15162026/10/01 09:43:16 OK 20251210153512_drop_unused_gin_index.sql (12.33ms)15172026/10/01 09:43:16 OK 20251218171726_add_pins.sql (43.46ms)15182026/10/01 09:43:16 OK 20260628120000_add_object_size_and_stats.sql (36.48ms)15192026/10/01 09:43:16 OK 20241026095416_initial_model.sql (120.52ms)15202026/10/01 09:43:16 OK 20260905000000_add_claims.sql (25.5ms)15212026/10/01 09:43:16 OK 20251210153512_drop_unused_gin_index.sql (10.31ms)15222026/10/01 09:43:17 OK 20260920000000_drop_claims.sql (26.95ms)15232026/10/01 09:43:17 OK 20251218171726_add_pins.sql (20.39ms)15242026-10-01 09:43:17.023 UTC [61511] ERROR: relation "goose_db_version" does not exist at character 3615252026-10-01 09:43:17.023 UTC [61511] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15262026/10/01 09:43:17 OK 20260923120000_add_pushes.sql (13.68ms)15272026/10/01 09:43:17 goose: successfully migrated database to version: 2026092312000015282026/10/01 09:43:17 OK 20260628120000_add_object_size_and_stats.sql (14.85ms)15292026/10/01 09:43:17 OK 1_commit_pending_closure.sql (3.66ms)15302026/10/01 09:43:17 OK 2_object_stats_trigger.sql (674.54µs)15312026/10/01 09:43:17 OK 3_commit_push.sql (453.88µs)15322026/10/01 09:43:17 goose: up to current file version: 315332026/10/01 09:43:17 OK 20260905000000_add_claims.sql (61.14ms)15342026-10-01 09:43:17.090 UTC [61513] ERROR: relation "goose_db_version" does not exist at character 3615352026-10-01 09:43:17.090 UTC [61513] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15362026/10/01 09:43:17 OK 20260920000000_drop_claims.sql (24.04ms)15372026/10/01 09:43:17 OK 20260923120000_add_pushes.sql (32.56ms)15382026/10/01 09:43:17 goose: successfully migrated database to version: 2026092312000015392026/10/01 09:43:17 OK 1_commit_pending_closure.sql (2.07ms)15402026/10/01 09:43:17 OK 2_object_stats_trigger.sql (466.58µs)15412026/10/01 09:43:17 OK 3_commit_push.sql (373.08µs)15422026/10/01 09:43:17 goose: up to current file version: 315432026/10/01 09:43:17 OK 20241026095416_initial_model.sql (259.87ms)15442026/10/01 09:43:17 OK 20251210153512_drop_unused_gin_index.sql (18.11ms)15452026/10/01 09:43:17 OK 20251218171726_add_pins.sql (42.72ms)15462026/10/01 09:43:17 OK 20241026095416_initial_model.sql (312.69ms)15472026/10/01 09:43:17 OK 20260628120000_add_object_size_and_stats.sql (87.68ms)15482026/10/01 09:43:17 OK 20251210153512_drop_unused_gin_index.sql (28.68ms)15492026/10/01 09:43:17 OK 20251218171726_add_pins.sql (32.02ms)15502026/10/01 09:43:17 OK 20260905000000_add_claims.sql (101.45ms)15512026/10/01 09:43:17 OK 20260628120000_add_object_size_and_stats.sql (70.73ms)15522026/10/01 09:43:17 OK 20260920000000_drop_claims.sql (110.4ms)15532026/10/01 09:43:17 OK 20260905000000_add_claims.sql (122.12ms)15542026/10/01 09:43:17 OK 20260923120000_add_pushes.sql (30.87ms)15552026/10/01 09:43:17 goose: successfully migrated database to version: 2026092312000015562026/10/01 09:43:17 OK 1_commit_pending_closure.sql (3.25ms)15572026/10/01 09:43:17 OK 2_object_stats_trigger.sql (692.63µs)15582026/10/01 09:43:17 OK 3_commit_push.sql (423.83µs)15592026/10/01 09:43:17 goose: up to current file version: 315602026/10/01 09:43:17 OK 20260920000000_drop_claims.sql (83.46ms)15612026/10/01 09:43:17 OK 20260923120000_add_pushes.sql (30.57ms)15622026/10/01 09:43:17 goose: successfully migrated database to version: 2026092312000015632026/10/01 09:43:17 OK 1_commit_pending_closure.sql (4.67ms)15642026/10/01 09:43:17 OK 2_object_stats_trigger.sql (1.34ms)15652026/10/01 09:43:17 OK 3_commit_push.sql (1.36ms)15662026/10/01 09:43:17 goose: up to current file version: 31567--- PASS: TestObjectStatsTrigger (4.08s)1568=== CONT TestSweepRechecksPendingAfterLocking15692026/10/01 09:43:18 INFO Received uploads request method=POST path=/api/pending_closures15702026-10-01 09:43:18.436 UTC [61519] ERROR: relation "goose_db_version" does not exist at character 3615712026-10-01 09:43:18.436 UTC [61519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15722026/10/01 09:43:18 INFO Received cleanup request method=DELETE path=/api/pending_closures15732026/10/01 09:43:18 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket39/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""15742026/10/01 09:43:18 INFO Aborted multipart uploads count=0 kept=115752026/10/01 09:43:18 INFO Received cleanup request method=DELETE path=/api/pending_closures15762026/10/01 09:43:18 INFO Aborted multipart uploads count=1 kept=01577--- PASS: TestMultipartCleanup (4.08s)1578=== CONT TestGCTaskStore_PhaseUpdates1579--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1580=== CONT TestGCTaskStore_CompletedAllowsNewTask1581--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1582=== CONT TestGCTaskStore_GetReturnsLatest1583--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1584=== CONT TestGCTaskStore_GetEmpty1585--- PASS: TestGCTaskStore_GetEmpty (0.00s)1586=== CONT TestGCTaskStore_ConflictDifferentParams1587--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1588=== CONT TestGCTaskStore_DeduplicateSameParams1589--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1590=== CONT TestGCTaskStore_StartNew1591--- PASS: TestGCTaskStore_StartNew (0.00s)1592=== CONT TestGCEndsOnShutdown1593=== NAME TestOrphanedObjectsGC1594 orphaned_objects_gc_test.go:290: GC Test Summary:1595 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1596 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1597 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1598 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1599 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1600--- PASS: TestOrphanedObjectsGC (5.00s)1601=== CONT TestCommitRacingPendingCleanupKeepsObjects16022026/10/01 09:43:18 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16032026/10/01 09:43:18 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1604--- PASS: TestService_NativeMTLS (3.89s)1605=== CONT TestPushWaitsForSweepHoldingRow16062026/10/01 09:43:18 OK 20241026095416_initial_model.sql (301.39ms)16072026-10-01 09:43:18.831 UTC [61526] ERROR: relation "goose_db_version" does not exist at character 3616082026-10-01 09:43:18.831 UTC [61526] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16092026/10/01 09:43:18 OK 20251210153512_drop_unused_gin_index.sql (11.39ms)16102026/10/01 09:43:18 OK 20251218171726_add_pins.sql (38.56ms)16112026/10/01 09:43:18 OK 20260628120000_add_object_size_and_stats.sql (44.75ms)16122026/10/01 09:43:19 OK 20260905000000_add_claims.sql (87.13ms)16132026/10/01 09:43:19 OK 20260920000000_drop_claims.sql (45.86ms)16142026/10/01 09:43:19 OK 20260923120000_add_pushes.sql (15.05ms)16152026/10/01 09:43:19 goose: successfully migrated database to version: 2026092312000016162026/10/01 09:43:19 OK 1_commit_pending_closure.sql (1.04ms)16172026/10/01 09:43:19 OK 2_object_stats_trigger.sql (257.88µs)16182026/10/01 09:43:19 OK 3_commit_push.sql (200.13µs)16192026/10/01 09:43:19 goose: up to current file version: 316202026/10/01 09:43:19 OK 20241026095416_initial_model.sql (249.86ms)16212026/10/01 09:43:19 OK 20251210153512_drop_unused_gin_index.sql (10.53ms)16222026/10/01 09:43:19 OK 20251218171726_add_pins.sql (39.49ms)16232026/10/01 09:43:19 OK 20260628120000_add_object_size_and_stats.sql (34.38ms)16242026/10/01 09:43:19 OK 20260905000000_add_claims.sql (72.57ms)16252026/10/01 09:43:19 OK 20260920000000_drop_claims.sql (87.96ms)16262026/10/01 09:43:19 OK 20260923120000_add_pushes.sql (23.55ms)16272026/10/01 09:43:19 goose: successfully migrated database to version: 2026092312000016282026/10/01 09:43:19 OK 1_commit_pending_closure.sql (1.96ms)16292026/10/01 09:43:19 OK 2_object_stats_trigger.sql (415.83µs)16302026/10/01 09:43:19 OK 3_commit_push.sql (367.71µs)16312026/10/01 09:43:19 goose: up to current file version: 31632--- PASS: TestMetricsInventory (4.31s)1633=== CONT TestClientMultipleUploads16342026-10-01 09:43:19.537 UTC [61534] ERROR: relation "goose_db_version" does not exist at character 3616352026-10-01 09:43:19.537 UTC [61534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16362026-10-01 09:43:19.720 UTC [61540] ERROR: relation "goose_db_version" does not exist at character 3616372026-10-01 09:43:19.720 UTC [61540] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16382026-10-01 09:43:19.828 UTC [61541] ERROR: relation "goose_db_version" does not exist at character 3616392026-10-01 09:43:19.828 UTC [61541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16402026/10/01 09:43:19 OK 20241026095416_initial_model.sql (249.98ms)16412026/10/01 09:43:19 OK 20251210153512_drop_unused_gin_index.sql (15.95ms)16422026/10/01 09:43:19 OK 20251218171726_add_pins.sql (37.38ms)16432026/10/01 09:43:19 OK 20260628120000_add_object_size_and_stats.sql (56.81ms)16442026/10/01 09:43:19 OK 20241026095416_initial_model.sql (174.64ms)16452026/10/01 09:43:19 OK 20251210153512_drop_unused_gin_index.sql (8.81ms)16462026/10/01 09:43:20 OK 20260905000000_add_claims.sql (88.85ms)16472026/10/01 09:43:20 OK 20251218171726_add_pins.sql (78.86ms)1648=== NAME TestNARDeduplicationMetadataUploadBug1649 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-60884-3569518374/TestNARDeduplicationMetadataUploadBug3212340793/001/store/bz9d9qmk1jid6ldzp50xg0mpcz4wcq4m-file1.txt16502026/10/01 09:43:20 OK 20260920000000_drop_claims.sql (23.94ms)16512026/10/01 09:43:20 OK 20260628120000_add_object_size_and_stats.sql (31.82ms)16522026/10/01 09:43:20 OK 20241026095416_initial_model.sql (195.22ms)16532026/10/01 09:43:20 OK 20260923120000_add_pushes.sql (13.96ms)16542026/10/01 09:43:20 goose: successfully migrated database to version: 2026092312000016552026/10/01 09:43:20 OK 1_commit_pending_closure.sql (1.33ms)16562026/10/01 09:43:20 OK 2_object_stats_trigger.sql (297.46µs)16572026/10/01 09:43:20 OK 3_commit_push.sql (232.29µs)16582026/10/01 09:43:20 goose: up to current file version: 316592026/10/01 09:43:20 OK 20251210153512_drop_unused_gin_index.sql (18.42ms)16602026/10/01 09:43:20 OK 20251218171726_add_pins.sql (25.18ms)16612026/10/01 09:43:20 OK 20260905000000_add_claims.sql (61.18ms)16622026/10/01 09:43:20 INFO Received push request method=POST path=/api/pushes16632026/10/01 09:43:20 OK 20260628120000_add_object_size_and_stats.sql (42.05ms)16642026/10/01 09:43:20 OK 20260920000000_drop_claims.sql (37.39ms)16652026/10/01 09:43:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16662026/10/01 09:43:20 INFO Uploading bz9d9qmk1jid6ldzp50xg0mpcz4wcq4m-file1.txt (160B)16672026/10/01 09:43:20 OK 20260923120000_add_pushes.sql (29.86ms)16682026/10/01 09:43:20 goose: successfully migrated database to version: 2026092312000016692026/10/01 09:43:20 OK 1_commit_pending_closure.sql (925.92µs)16702026/10/01 09:43:20 OK 2_object_stats_trigger.sql (229.33µs)16712026/10/01 09:43:20 OK 3_commit_push.sql (186.83µs)16722026/10/01 09:43:20 goose: up to current file version: 316732026/10/01 09:43:20 WARN Failed to register uploaded object key=bz9d9qmk1jid6ldzp50xg0mpcz4wcq4m.ls error="server returned 404: 404 page not found\n"16742026/10/01 09:43:20 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16752026/10/01 09:43:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16762026/10/01 09:43:20 INFO Signed narinfos id=1 count=116772026/10/01 09:43:20 INFO Uploading 1 narinfos16782026/10/01 09:43:20 OK 20260905000000_add_claims.sql (71.33ms)16792026/10/01 09:43:20 INFO Received complete push request method=POST path=/api/pushes/1/complete16802026/10/01 09:43:20 WARN Failed to register uploaded object key=bz9d9qmk1jid6ldzp50xg0mpcz4wcq4m.narinfo error="server returned 404: 404 page not found\n"16812026/10/01 09:43:20 INFO Upload complete. (159ms)1682 metadata_upload_test.go:54: Retrieved narinfo from S3:1683 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestNARDeduplicationMetadataUploadBug3212340793/001/store/bz9d9qmk1jid6ldzp50xg0mpcz4wcq4m-file1.txt1684 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1685 Compression: zstd1686 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1687 NarSize: 1601688 References: 1689 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1690 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1691 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1692 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}16932026/10/01 09:43:20 OK 20260920000000_drop_claims.sql (42.08ms)16942026/10/01 09:43:20 OK 20260923120000_add_pushes.sql (21.76ms)16952026/10/01 09:43:20 goose: successfully migrated database to version: 2026092312000016962026/10/01 09:43:20 OK 1_commit_pending_closure.sql (1.23ms)16972026/10/01 09:43:20 OK 2_object_stats_trigger.sql (304.83µs)16982026/10/01 09:43:20 OK 3_commit_push.sql (228.25µs)16992026/10/01 09:43:20 goose: up to current file version: 31700 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-60884-3569518374/TestNARDeduplicationMetadataUploadBug3212340793/001/store/s544faycpk92q27ylsjlykqpsdg42a0v-file2.txt17012026/10/01 09:43:20 WARN readiness check failed error="closed pool"1702--- PASS: TestService_readinessHandler (4.19s)1703=== CONT TestGCBugBareHashReferences17042026/10/01 09:43:20 INFO Received push request method=POST path=/api/pushes17052026/10/01 09:43:20 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17062026/10/01 09:43:20 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17072026/10/01 09:43:20 INFO Signed narinfos id=2 count=117082026/10/01 09:43:20 INFO Uploading 1 narinfos17092026/10/01 09:43:20 WARN Failed to register uploaded object key=s544faycpk92q27ylsjlykqpsdg42a0v.ls error="server returned 404: 404 page not found\n"17102026/10/01 09:43:20 INFO Received complete push request method=POST path=/api/pushes/2/complete17112026/10/01 09:43:20 WARN Failed to register uploaded object key=s544faycpk92q27ylsjlykqpsdg42a0v.narinfo error="server returned 404: 404 page not found\n"17122026/10/01 09:43:20 INFO Upload complete. (119ms)1713=== NAME TestNARDeduplicationMetadataUploadBug1714 metadata_upload_test.go:76: Retrieved narinfo from S3:1715 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestNARDeduplicationMetadataUploadBug3212340793/001/store/s544faycpk92q27ylsjlykqpsdg42a0v-file2.txt1716 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1717 Compression: zstd1718 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1719 NarSize: 1601720 References: 1721 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1722 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1723 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1724 {"version":1,"root":{"type":"regular","size":44}}1725--- PASS: TestNARDeduplicationMetadataUploadBug (5.20s)1726=== CONT TestLeadEndsOnShutdown1727--- PASS: TestService_healthCheckHandler (4.39s)1728=== CONT TestLeadElectsOneAndHandsOver17292026/10/01 09:43:21 INFO Received uploads request method=POST path=/api/pending_closures17302026-10-01 09:43:21.201 UTC [61560] ERROR: relation "goose_db_version" does not exist at character 3617312026-10-01 09:43:21.201 UTC [61560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1732--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (4.62s)1733=== CONT TestResolveDBConnectionString1734=== RUN TestResolveDBConnectionString/flag_wins1735=== PAUSE TestResolveDBConnectionString/flag_wins1736=== RUN TestResolveDBConnectionString/file_when_flag_empty1737=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1738=== RUN TestResolveDBConnectionString/missing_file_is_an_error1739=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1740=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1741=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1742=== RUN TestResolveDBConnectionString/nothing_configured1743=== PAUSE TestResolveDBConnectionString/nothing_configured1744=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock17452026/10/01 09:43:21 OK 20241026095416_initial_model.sql (193.68ms)17462026/10/01 09:43:21 OK 20251210153512_drop_unused_gin_index.sql (17.21ms)17472026/10/01 09:43:21 OK 20251218171726_add_pins.sql (35.3ms)17482026-10-01 09:43:21.549 UTC [61563] ERROR: relation "goose_db_version" does not exist at character 3617492026-10-01 09:43:21.549 UTC [61563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17502026/10/01 09:43:21 OK 20260628120000_add_object_size_and_stats.sql (44.21ms)17512026/10/01 09:43:21 OK 20260905000000_add_claims.sql (75.62ms)17522026-10-01 09:43:21.659 UTC [61564] ERROR: relation "goose_db_version" does not exist at character 3617532026-10-01 09:43:21.659 UTC [61564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17542026-10-01 09:43:21.671 UTC [61565] ERROR: relation "goose_db_version" does not exist at character 3617552026-10-01 09:43:21.671 UTC [61565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17562026/10/01 09:43:21 OK 20260920000000_drop_claims.sql (105.44ms)17572026/10/01 09:43:21 OK 20260923120000_add_pushes.sql (29.03ms)17582026/10/01 09:43:21 goose: successfully migrated database to version: 2026092312000017592026/10/01 09:43:21 OK 1_commit_pending_closure.sql (5.42ms)17602026/10/01 09:43:21 OK 2_object_stats_trigger.sql (2.42ms)17612026/10/01 09:43:21 OK 3_commit_push.sql (1.62ms)17622026/10/01 09:43:21 goose: up to current file version: 317632026/10/01 09:43:21 OK 20241026095416_initial_model.sql (239.27ms)17642026/10/01 09:43:21 OK 20251210153512_drop_unused_gin_index.sql (18.19ms)17652026/10/01 09:43:21 OK 20251218171726_add_pins.sql (36.13ms)17662026/10/01 09:43:22 OK 20260628120000_add_object_size_and_stats.sql (70.17ms)17672026/10/01 09:43:22 OK 20241026095416_initial_model.sql (259.1ms)17682026/10/01 09:43:22 OK 20241026095416_initial_model.sql (255.18ms)17692026/10/01 09:43:22 OK 20251210153512_drop_unused_gin_index.sql (10.12ms)17702026/10/01 09:43:22 OK 20251210153512_drop_unused_gin_index.sql (19.75ms)17712026/10/01 09:43:22 OK 20251218171726_add_pins.sql (39.51ms)17722026/10/01 09:43:22 OK 20251218171726_add_pins.sql (44.17ms)17732026/10/01 09:43:22 OK 20260905000000_add_claims.sql (92.78ms)17742026/10/01 09:43:22 OK 20260628120000_add_object_size_and_stats.sql (49.4ms)17752026/10/01 09:43:22 OK 20260920000000_drop_claims.sql (37.46ms)17762026/10/01 09:43:22 OK 20260628120000_add_object_size_and_stats.sql (50.18ms)17772026/10/01 09:43:22 OK 20260923120000_add_pushes.sql (36.84ms)17782026/10/01 09:43:22 goose: successfully migrated database to version: 2026092312000017792026/10/01 09:43:22 OK 1_commit_pending_closure.sql (8.21ms)17802026/10/01 09:43:22 OK 20260905000000_add_claims.sql (56.16ms)17812026/10/01 09:43:22 OK 20260905000000_add_claims.sql (39.93ms)17822026/10/01 09:43:22 OK 2_object_stats_trigger.sql (2.26ms)17832026/10/01 09:43:22 OK 3_commit_push.sql (1.3ms)17842026/10/01 09:43:22 goose: up to current file version: 317852026/10/01 09:43:22 OK 20260920000000_drop_claims.sql (35.57ms)17862026/10/01 09:43:22 OK 20260920000000_drop_claims.sql (37.98ms)17872026/10/01 09:43:22 OK 20260923120000_add_pushes.sql (8.46ms)17882026/10/01 09:43:22 goose: successfully migrated database to version: 2026092312000017892026/10/01 09:43:22 OK 20260923120000_add_pushes.sql (14.04ms)17902026/10/01 09:43:22 goose: successfully migrated database to version: 2026092312000017912026/10/01 09:43:22 OK 1_commit_pending_closure.sql (4.08ms)17922026/10/01 09:43:22 OK 1_commit_pending_closure.sql (3.45ms)17932026/10/01 09:43:22 OK 2_object_stats_trigger.sql (963.88µs)17942026/10/01 09:43:22 OK 3_commit_push.sql (726.71µs)17952026/10/01 09:43:22 goose: up to current file version: 317962026/10/01 09:43:22 OK 2_object_stats_trigger.sql (902.75µs)17972026/10/01 09:43:22 OK 3_commit_push.sql (624.33µs)17982026/10/01 09:43:22 goose: up to current file version: 317992026/10/01 09:43:22 INFO Aborted multipart uploads count=0 kept=018002026/10/01 09:43:22 WARN Force mode enabled - objects will be deleted immediately without grace period18012026-10-01 09:43:22.300 UTC [61567] ERROR: relation "goose_db_version" does not exist at character 3618022026-10-01 09:43:22.300 UTC [61567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18032026/10/01 09:43:22 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=018042026/10/01 09:43:22 INFO Vacuumed table table=pending_closures18052026/10/01 09:43:22 INFO Vacuumed table table=pending_objects18062026/10/01 09:43:22 INFO Vacuumed table table=multipart_uploads18072026/10/01 09:43:22 INFO Vacuumed table table=closures18082026/10/01 09:43:22 INFO Vacuumed table table=objects1809--- PASS: TestSweepRechecksPendingAfterLocking (4.24s)1810=== CONT TestClientFallsBackToClosures1811--- PASS: TestGCEndsOnShutdown (3.91s)1812=== CONT TestClientPushesUseOnePush18132026/10/01 09:43:22 OK 20241026095416_initial_model.sql (183.56ms)18142026/10/01 09:43:22 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)18152026/10/01 09:43:22 OK 20251218171726_add_pins.sql (37.05ms)18162026/10/01 09:43:22 OK 20260628120000_add_object_size_and_stats.sql (25.84ms)18172026/10/01 09:43:22 OK 20260905000000_add_claims.sql (64.17ms)18182026/10/01 09:43:22 OK 20260920000000_drop_claims.sql (51.36ms)18192026/10/01 09:43:22 OK 20260923120000_add_pushes.sql (30.05ms)18202026/10/01 09:43:22 goose: successfully migrated database to version: 2026092312000018212026/10/01 09:43:22 OK 1_commit_pending_closure.sql (4.55ms)18222026/10/01 09:43:22 OK 2_object_stats_trigger.sql (923.13µs)18232026/10/01 09:43:22 OK 3_commit_push.sql (722.17µs)18242026/10/01 09:43:22 goose: up to current file version: 318252026/10/01 09:43:22 INFO Received uploads request method=POST path=/api/pending_closures18262026-10-01 09:43:23.004 UTC [61574] ERROR: relation "goose_db_version" does not exist at character 3618272026-10-01 09:43:23.004 UTC [61574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1828--- PASS: TestPushWaitsForSweepHoldingRow (4.56s)1829=== CONT TestPinProtectsFromGC18302026/10/01 09:43:23 INFO Aborted multipart uploads count=0 kept=018312026/10/01 09:43:23 WARN Force mode enabled - objects will be deleted immediately without grace period18322026/10/01 09:43:23 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=018332026/10/01 09:43:23 INFO Vacuumed table table=pending_closures18342026/10/01 09:43:23 INFO Vacuumed table table=pending_objects18352026/10/01 09:43:23 OK 20241026095416_initial_model.sql (438.78ms)18362026/10/01 09:43:23 INFO Vacuumed table table=multipart_uploads18372026/10/01 09:43:23 OK 20251210153512_drop_unused_gin_index.sql (17.91ms)18382026/10/01 09:43:23 INFO Vacuumed table table=closures18392026/10/01 09:43:23 INFO Vacuumed table table=objects1840--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.93s)1841=== CONT TestClientSharedPathCommittedMidPush18422026/10/01 09:43:23 OK 20251218171726_add_pins.sql (59.97ms)18432026/10/01 09:43:23 OK 20260628120000_add_object_size_and_stats.sql (42.06ms)18442026-10-01 09:43:23.684 UTC [61580] ERROR: relation "goose_db_version" does not exist at character 3618452026-10-01 09:43:23.684 UTC [61580] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18462026-10-01 09:43:23.717 UTC [61582] ERROR: relation "goose_db_version" does not exist at character 3618472026-10-01 09:43:23.717 UTC [61582] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18482026/10/01 09:43:23 OK 20260905000000_add_claims.sql (52.85ms)18492026/10/01 09:43:23 OK 20260920000000_drop_claims.sql (46.16ms)18502026/10/01 09:43:23 OK 20260923120000_add_pushes.sql (9.67ms)18512026/10/01 09:43:23 goose: successfully migrated database to version: 2026092312000018522026/10/01 09:43:23 OK 1_commit_pending_closure.sql (1.16ms)18532026/10/01 09:43:23 OK 2_object_stats_trigger.sql (250.71µs)18542026/10/01 09:43:23 OK 3_commit_push.sql (220.54µs)18552026/10/01 09:43:23 goose: up to current file version: 31856=== NAME TestClientMultipleUploads1857 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-60884-3569518374/TestClientMultipleUploads2194352453/001/store/9ab7cdp66b5wh1aazx5jj87z6xxzy6qj-test-file-0.txt18582026/10/01 09:43:23 OK 20241026095416_initial_model.sql (231.8ms)18592026/10/01 09:43:23 OK 20251210153512_drop_unused_gin_index.sql (11.32ms)18602026/10/01 09:43:23 OK 20241026095416_initial_model.sql (211.94ms)18612026/10/01 09:43:24 OK 20251210153512_drop_unused_gin_index.sql (8.39ms)18622026/10/01 09:43:24 OK 20251218171726_add_pins.sql (22.87ms)18632026/10/01 09:43:24 OK 20251218171726_add_pins.sql (35.77ms)18642026-10-01 09:43:24.046 UTC [61587] ERROR: relation "goose_db_version" does not exist at character 3618652026-10-01 09:43:24.046 UTC [61587] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18662026/10/01 09:43:24 OK 20260628120000_add_object_size_and_stats.sql (44.89ms)1867 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-60884-3569518374/TestClientMultipleUploads2194352453/001/store/1c4rvlkrg06ncnipp7bd49jd9qkianq3-test-file-1.txt18682026/10/01 09:43:24 OK 20260628120000_add_object_size_and_stats.sql (53.32ms)18692026/10/01 09:43:24 OK 20260905000000_add_claims.sql (44.53ms)18702026/10/01 09:43:24 OK 20260905000000_add_claims.sql (80.13ms)18712026/10/01 09:43:24 OK 20260920000000_drop_claims.sql (28.01ms)18722026/10/01 09:43:24 OK 20260920000000_drop_claims.sql (24.77ms)1873 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-60884-3569518374/TestClientMultipleUploads2194352453/001/store/w91z5al6adjdyk1m6mxbhbfhr1n277al-test-file-2.txt18742026/10/01 09:43:24 OK 20260923120000_add_pushes.sql (18.04ms)18752026/10/01 09:43:24 goose: successfully migrated database to version: 2026092312000018762026/10/01 09:43:24 OK 1_commit_pending_closure.sql (926.83µs)18772026/10/01 09:43:24 OK 2_object_stats_trigger.sql (245.46µs)18782026/10/01 09:43:24 OK 3_commit_push.sql (191.83µs)18792026/10/01 09:43:24 goose: up to current file version: 318802026/10/01 09:43:24 OK 20260923120000_add_pushes.sql (22.04ms)18812026/10/01 09:43:24 goose: successfully migrated database to version: 2026092312000018822026/10/01 09:43:24 OK 1_commit_pending_closure.sql (1.31ms)18832026/10/01 09:43:24 OK 2_object_stats_trigger.sql (295.58µs)18842026/10/01 09:43:24 OK 3_commit_push.sql (202.92µs)18852026/10/01 09:43:24 goose: up to current file version: 318862026/10/01 09:43:24 INFO Received push request method=POST path=/api/pushes18872026/10/01 09:43:24 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18882026/10/01 09:43:24 INFO Uploading 9ab7cdp66b5wh1aazx5jj87z6xxzy6qj-test-file-0.txt (160B)18892026/10/01 09:43:24 INFO Uploading w91z5al6adjdyk1m6mxbhbfhr1n277al-test-file-2.txt (160B)18902026/10/01 09:43:24 INFO Uploading 1c4rvlkrg06ncnipp7bd49jd9qkianq3-test-file-1.txt (160B)18912026/10/01 09:43:24 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18922026/10/01 09:43:24 WARN Failed to register uploaded object key=w91z5al6adjdyk1m6mxbhbfhr1n277al.ls error="server returned 404: 404 page not found\n"18932026/10/01 09:43:24 WARN Failed to register uploaded object key=9ab7cdp66b5wh1aazx5jj87z6xxzy6qj.ls error="server returned 404: 404 page not found\n"18942026/10/01 09:43:24 WARN Failed to register uploaded object key=1c4rvlkrg06ncnipp7bd49jd9qkianq3.ls error="server returned 404: 404 page not found\n"18952026/10/01 09:43:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18962026/10/01 09:43:24 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18972026/10/01 09:43:24 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18982026/10/01 09:43:24 INFO Signed narinfos id=1 count=318992026/10/01 09:43:24 INFO Uploading 3 narinfos19002026/10/01 09:43:24 OK 20241026095416_initial_model.sql (193.34ms)19012026/10/01 09:43:24 OK 20251210153512_drop_unused_gin_index.sql (11.86ms)19022026/10/01 09:43:24 WARN Failed to register uploaded object key=9ab7cdp66b5wh1aazx5jj87z6xxzy6qj.narinfo error="server returned 404: 404 page not found\n"19032026/10/01 09:43:24 WARN Failed to register uploaded object key=w91z5al6adjdyk1m6mxbhbfhr1n277al.narinfo error="server returned 404: 404 page not found\n"19042026/10/01 09:43:24 INFO Received complete push request method=POST path=/api/pushes/1/complete19052026/10/01 09:43:24 WARN Failed to register uploaded object key=1c4rvlkrg06ncnipp7bd49jd9qkianq3.narinfo error="server returned 404: 404 page not found\n"1906--- PASS: TestGCBugBareHashReferences (3.97s)1907=== CONT TestClientWithDependencies19082026/10/01 09:43:24 INFO Upload complete. (181ms)1909=== NAME TestClientMultipleUploads1910 client_integration_test.go:369: Uploaded 3 paths in 217.135125ms19112026/10/01 09:43:24 OK 20251218171726_add_pins.sql (58.4ms)19122026/10/01 09:43:24 OK 20260628120000_add_object_size_and_stats.sql (39.33ms)1913--- PASS: TestClientMultipleUploads (4.96s)1914=== CONT TestService_ReadScope_PublicByDefault19152026/10/01 09:43:24 OK 20260905000000_add_claims.sql (58.42ms)19162026/10/01 09:43:24 INFO lead: acquired remote=192.0.2.1:123419172026/10/01 09:43:24 OK 20260920000000_drop_claims.sql (41.19ms)19182026/10/01 09:43:24 OK 20260923120000_add_pushes.sql (10.73ms)19192026/10/01 09:43:24 goose: successfully migrated database to version: 2026092312000019202026/10/01 09:43:24 OK 1_commit_pending_closure.sql (1.63ms)19212026/10/01 09:43:24 OK 2_object_stats_trigger.sql (367.67µs)19222026/10/01 09:43:24 OK 3_commit_push.sql (309.67µs)19232026/10/01 09:43:24 goose: up to current file version: 31924=== NAME TestOrphanedObjectsGCStressTest1925 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains19262026/10/01 09:43:24 INFO lead: released remote=192.0.2.1:12341927 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19282026/10/01 09:43:24 INFO lead: acquired remote=192.0.2.1:123419292026/10/01 09:43:24 INFO lead: released remote=192.0.2.1:12341930--- PASS: TestLeadElectsOneAndHandsOver (3.97s)1931=== CONT TestClientIntegration19322026/10/01 09:43:24 INFO lead: acquired remote=192.0.2.1:123419332026/10/01 09:43:24 INFO lead: released remote=192.0.2.1:12341934--- PASS: TestLeadEndsOnShutdown (4.09s)1935=== CONT TestClientErrorHandling1936=== RUN TestClientErrorHandling/InvalidStorePath1937=== PAUSE TestClientErrorHandling/InvalidStorePath1938=== RUN TestClientErrorHandling/InvalidAuthToken1939=== PAUSE TestClientErrorHandling/InvalidAuthToken1940=== RUN TestClientErrorHandling/ServerNotAvailable1941=== PAUSE TestClientErrorHandling/ServerNotAvailable1942=== CONT TestClientCADerivations19432026-10-01 09:43:24.792 UTC [61603] ERROR: relation "goose_db_version" does not exist at character 3619442026-10-01 09:43:24.792 UTC [61603] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19452026-10-01 09:43:24.830 UTC [61606] ERROR: relation "goose_db_version" does not exist at character 3619462026-10-01 09:43:24.830 UTC [61606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19472026/10/01 09:43:24 OK 20241026095416_initial_model.sql (103.05ms)19482026/10/01 09:43:24 OK 20251210153512_drop_unused_gin_index.sql (14.95ms)19492026/10/01 09:43:24 OK 20241026095416_initial_model.sql (97.51ms)19502026/10/01 09:43:24 OK 20251218171726_add_pins.sql (22.4ms)19512026/10/01 09:43:24 OK 20251210153512_drop_unused_gin_index.sql (15.15ms)19522026/10/01 09:43:24 OK 20260628120000_add_object_size_and_stats.sql (19.41ms)19532026/10/01 09:43:24 OK 20251218171726_add_pins.sql (13.27ms)19542026/10/01 09:43:24 OK 20260905000000_add_claims.sql (5.5ms)19552026/10/01 09:43:24 OK 20260920000000_drop_claims.sql (2.41ms)19562026/10/01 09:43:25 OK 20260628120000_add_object_size_and_stats.sql (10.65ms)19572026/10/01 09:43:25 OK 20260923120000_add_pushes.sql (4.16ms)19582026/10/01 09:43:25 goose: successfully migrated database to version: 2026092312000019592026/10/01 09:43:25 OK 1_commit_pending_closure.sql (3.66ms)19602026/10/01 09:43:25 OK 2_object_stats_trigger.sql (478.92µs)19612026/10/01 09:43:25 OK 3_commit_push.sql (379.25µs)19622026/10/01 09:43:25 goose: up to current file version: 319632026/10/01 09:43:25 OK 20260905000000_add_claims.sql (6.2ms)19642026/10/01 09:43:25 OK 20260920000000_drop_claims.sql (2.14ms)19652026/10/01 09:43:25 OK 20260923120000_add_pushes.sql (9.39ms)19662026/10/01 09:43:25 goose: successfully migrated database to version: 2026092312000019672026/10/01 09:43:25 OK 1_commit_pending_closure.sql (2.94ms)19682026/10/01 09:43:25 OK 2_object_stats_trigger.sql (368.54µs)19692026/10/01 09:43:25 OK 3_commit_push.sql (273.38µs)19702026/10/01 09:43:25 goose: up to current file version: 319712026-10-01 09:43:25.045 UTC [61607] ERROR: relation "goose_db_version" does not exist at character 3619722026-10-01 09:43:25.045 UTC [61607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19732026/10/01 09:43:25 OK 20241026095416_initial_model.sql (89.33ms)19742026/10/01 09:43:25 OK 20251210153512_drop_unused_gin_index.sql (9.51ms)19752026/10/01 09:43:25 OK 20251218171726_add_pins.sql (29.45ms)19762026/10/01 09:43:25 OK 20260628120000_add_object_size_and_stats.sql (36.43ms)19772026-10-01 09:43:25.252 UTC [61608] ERROR: relation "goose_db_version" does not exist at character 3619782026-10-01 09:43:25.252 UTC [61608] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19792026/10/01 09:43:25 OK 20260905000000_add_claims.sql (39.16ms)19802026/10/01 09:43:25 OK 20260920000000_drop_claims.sql (26.58ms)19812026/10/01 09:43:25 OK 20260923120000_add_pushes.sql (2.06ms)19822026/10/01 09:43:25 goose: successfully migrated database to version: 2026092312000019832026/10/01 09:43:25 OK 1_commit_pending_closure.sql (1.51ms)19842026/10/01 09:43:25 OK 2_object_stats_trigger.sql (431.42µs)19852026/10/01 09:43:25 OK 3_commit_push.sql (194.38µs)19862026/10/01 09:43:25 goose: up to current file version: 319872026/10/01 09:43:25 OK 20241026095416_initial_model.sql (108.49ms)19882026/10/01 09:43:25 OK 20251210153512_drop_unused_gin_index.sql (10.21ms)19892026/10/01 09:43:25 OK 20251218171726_add_pins.sql (14.1ms)19902026/10/01 09:43:25 OK 20260628120000_add_object_size_and_stats.sql (51.18ms)19912026/10/01 09:43:25 OK 20260905000000_add_claims.sql (34.59ms)19922026/10/01 09:43:25 OK 20260920000000_drop_claims.sql (21.85ms)19932026/10/01 09:43:25 OK 20260923120000_add_pushes.sql (11.83ms)19942026/10/01 09:43:25 goose: successfully migrated database to version: 2026092312000019952026/10/01 09:43:25 OK 1_commit_pending_closure.sql (1.24ms)19962026/10/01 09:43:25 OK 2_object_stats_trigger.sql (260.67µs)19972026/10/01 09:43:25 OK 3_commit_push.sql (210.46µs)19982026/10/01 09:43:25 goose: up to current file version: 319992026-10-01 09:43:25.618 UTC [61623] ERROR: relation "goose_db_version" does not exist at character 3620002026-10-01 09:43:25.618 UTC [61623] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20012026-10-01 09:43:25.633 UTC [61626] ERROR: relation "goose_db_version" does not exist at character 3620022026-10-01 09:43:25.633 UTC [61626] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20032026/10/01 09:43:25 INFO Received uploads request method=POST path=/api/pending_closures20042026/10/01 09:43:25 INFO Received uploads request method=POST path=/api/pending_closures20052026/10/01 09:43:25 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20062026/10/01 09:43:25 INFO Uploading apfwcj8npxz95wkr9wqapwiayp2n3mqm-b (248B)20072026/10/01 09:43:25 INFO Uploading v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5-shared-dep (136B)20082026/10/01 09:43:25 WARN Failed to register uploaded object key=nar/1rshrq3f50d79ssv12cn3rlk4d3wlrr2wyvkxq1lr62x311p2x7q.nar.zst error="server returned 404: 404 page not found\n"20092026/10/01 09:43:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20102026/10/01 09:43:25 WARN Failed to register uploaded object key=v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5.ls error="server returned 404: 404 page not found\n"20112026/10/01 09:43:25 WARN Failed to register uploaded object key=apfwcj8npxz95wkr9wqapwiayp2n3mqm.ls error="server returned 404: 404 page not found\n"20122026/10/01 09:43:25 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20132026/10/01 09:43:25 WARN Failed to register uploaded object key=698wfvwkspr1y897sx8jjmqjvi9vih5r.ls error="server returned 404: 404 page not found\n"20142026/10/01 09:43:25 INFO Signed narinfos id=2 count=220152026/10/01 09:43:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20162026/10/01 09:43:25 INFO Signed narinfos id=1 count=220172026/10/01 09:43:25 INFO Uploading 4 narinfos20182026/10/01 09:43:25 WARN Failed to register uploaded object key=v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5.narinfo error="server returned 404: 404 page not found\n"20192026/10/01 09:43:25 WARN Failed to register uploaded object key=698wfvwkspr1y897sx8jjmqjvi9vih5r.narinfo error="server returned 404: 404 page not found\n"20202026/10/01 09:43:25 WARN Failed to register uploaded object key=apfwcj8npxz95wkr9wqapwiayp2n3mqm.narinfo error="server returned 404: 404 page not found\n"20212026/10/01 09:43:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20222026/10/01 09:43:25 WARN Failed to register uploaded object key=v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5.narinfo error="server returned 404: 404 page not found\n"20232026/10/01 09:43:25 INFO Completed upload id=120242026/10/01 09:43:25 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20252026/10/01 09:43:25 INFO Completed upload id=220262026/10/01 09:43:25 INFO Upload complete. (119ms)2027=== NAME TestClientFallsBackToClosures2028 client_pushes_test.go:112: Retrieved narinfo from S3:2029 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientFallsBackToClosures1292041578/001/store/v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5-shared-dep2030 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2031 Compression: zstd2032 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822033 NarSize: 1362034 References: 2035 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2036 client_pushes_test.go:112: Retrieved narinfo from S3:2037 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientFallsBackToClosures1292041578/001/store/698wfvwkspr1y897sx8jjmqjvi9vih5r-a2038 URL: nar/1rshrq3f50d79ssv12cn3rlk4d3wlrr2wyvkxq1lr62x311p2x7q.nar.zst2039 Compression: zstd2040 NarHash: sha256:1rshrq3f50d79ssv12cn3rlk4d3wlrr2wyvkxq1lr62x311p2x7q2041 NarSize: 2482042 References: /nix/var/nix/builds/nix-60884-3569518374/TestClientFallsBackToClosures1292041578/001/store/v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5-shared-dep2043 CA: text:sha256:0g1sn1mbdybba4ksz87z9c8lx37rjyj5ssq1lw06q70pa614j4df2044 client_pushes_test.go:112: Retrieved narinfo from S3:2045 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientFallsBackToClosures1292041578/001/store/apfwcj8npxz95wkr9wqapwiayp2n3mqm-b2046 URL: nar/1rshrq3f50d79ssv12cn3rlk4d3wlrr2wyvkxq1lr62x311p2x7q.nar.zst2047 Compression: zstd2048 NarHash: sha256:1rshrq3f50d79ssv12cn3rlk4d3wlrr2wyvkxq1lr62x311p2x7q2049 NarSize: 2482050 References: /nix/var/nix/builds/nix-60884-3569518374/TestClientFallsBackToClosures1292041578/001/store/v9zdw3lv8pjrgfrd1x1p2nh5fmy5q3k5-shared-dep2051 CA: text:sha256:0g1sn1mbdybba4ksz87z9c8lx37rjyj5ssq1lw06q70pa614j4df20522026/10/01 09:43:25 OK 20241026095416_initial_model.sql (95.65ms)20532026/10/01 09:43:25 OK 20251210153512_drop_unused_gin_index.sql (12.76ms)20542026/10/01 09:43:25 OK 20241026095416_initial_model.sql (105.95ms)2055--- PASS: TestClientFallsBackToClosures (3.37s)2056=== CONT TestCacheStatsHandler20572026/10/01 09:43:25 OK 20251218171726_add_pins.sql (26.79ms)20582026/10/01 09:43:25 OK 20251210153512_drop_unused_gin_index.sql (14.44ms)20592026/10/01 09:43:25 OK 20251218171726_add_pins.sql (3.6ms)2060--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (4.53s)2061=== CONT TestCacheConfigHandler2062=== RUN TestCacheConfigHandler/full_config,_no_issuer2063=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2064=== RUN TestCacheConfigHandler/no_cache_url_configured2065=== PAUSE TestCacheConfigHandler/no_cache_url_configured2066=== RUN TestCacheConfigHandler/no_signing_keys2067=== PAUSE TestCacheConfigHandler/no_signing_keys2068=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2069=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2070=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection20712026/10/01 09:43:25 OK 20260628120000_add_object_size_and_stats.sql (21.84ms)20722026/10/01 09:43:25 OK 20260628120000_add_object_size_and_stats.sql (32.39ms)20732026/10/01 09:43:25 INFO Received push request method=POST path=/api/pushes20742026/10/01 09:43:25 OK 20260905000000_add_claims.sql (33.8ms)20752026/10/01 09:43:25 OK 20260905000000_add_claims.sql (18.26ms)20762026/10/01 09:43:25 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20772026/10/01 09:43:25 INFO Uploading n41q1rv1cfy0ddqs18krxvraa32gq3v0-b (248B)20782026/10/01 09:43:25 INFO Uploading 3ng3app8r2xi80drmiss4zwzpb4zvbdb-shared-dep (136B)20792026/10/01 09:43:25 OK 20260920000000_drop_claims.sql (9.32ms)20802026/10/01 09:43:25 WARN Failed to register uploaded object key=3ng3app8r2xi80drmiss4zwzpb4zvbdb.ls error="server returned 404: 404 page not found\n"20812026/10/01 09:43:25 WARN Failed to register uploaded object key=grs7gr0gv68r1xl13csj90058s34ychs.ls error="server returned 404: 404 page not found\n"20822026/10/01 09:43:25 WARN Failed to register uploaded object key=n41q1rv1cfy0ddqs18krxvraa32gq3v0.ls error="server returned 404: 404 page not found\n"20832026/10/01 09:43:25 WARN Failed to register uploaded object key=nar/1k7hm3bkicrq6fdkhb1146c4a79mihrk36vg3ngv779n54m9y327.nar.zst error="server returned 404: 404 page not found\n"20842026/10/01 09:43:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20852026/10/01 09:43:25 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20862026/10/01 09:43:25 INFO Signed narinfos id=1 count=320872026/10/01 09:43:25 INFO Uploading 3 narinfos20882026/10/01 09:43:25 OK 20260923120000_add_pushes.sql (19.21ms)20892026/10/01 09:43:25 goose: successfully migrated database to version: 2026092312000020902026/10/01 09:43:25 OK 20260920000000_drop_claims.sql (25.27ms)20912026/10/01 09:43:25 OK 1_commit_pending_closure.sql (894.58µs)20922026/10/01 09:43:25 OK 2_object_stats_trigger.sql (208.71µs)20932026/10/01 09:43:25 OK 3_commit_push.sql (176.79µs)20942026/10/01 09:43:25 goose: up to current file version: 320952026/10/01 09:43:25 WARN Failed to register uploaded object key=grs7gr0gv68r1xl13csj90058s34ychs.narinfo error="server returned 404: 404 page not found\n"20962026/10/01 09:43:25 WARN Failed to register uploaded object key=3ng3app8r2xi80drmiss4zwzpb4zvbdb.narinfo error="server returned 404: 404 page not found\n"20972026/10/01 09:43:25 INFO Received complete push request method=POST path=/api/pushes/1/complete20982026/10/01 09:43:25 OK 20260923120000_add_pushes.sql (12.52ms)20992026/10/01 09:43:25 goose: successfully migrated database to version: 2026092312000021002026/10/01 09:43:25 WARN Failed to register uploaded object key=n41q1rv1cfy0ddqs18krxvraa32gq3v0.narinfo error="server returned 404: 404 page not found\n"21012026/10/01 09:43:25 OK 1_commit_pending_closure.sql (1.15ms)21022026/10/01 09:43:25 OK 2_object_stats_trigger.sql (242.17µs)21032026/10/01 09:43:25 OK 3_commit_push.sql (190.96µs)21042026/10/01 09:43:25 goose: up to current file version: 321052026/10/01 09:43:25 INFO Upload complete. (134ms)21062026-10-01 09:43:25.896 UTC [61641] ERROR: relation "goose_db_version" does not exist at character 3621072026-10-01 09:43:25.896 UTC [61641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2108=== NAME TestClientPushesUseOnePush2109 client_pushes_test.go:97: Retrieved narinfo from S3:2110 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientPushesUseOnePush1934828710/001/store/3ng3app8r2xi80drmiss4zwzpb4zvbdb-shared-dep2111 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2112 Compression: zstd2113 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822114 NarSize: 1362115 References: 2116 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2117 client_pushes_test.go:97: Retrieved narinfo from S3:2118 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientPushesUseOnePush1934828710/001/store/grs7gr0gv68r1xl13csj90058s34ychs-a2119 URL: nar/1k7hm3bkicrq6fdkhb1146c4a79mihrk36vg3ngv779n54m9y327.nar.zst2120 Compression: zstd2121 NarHash: sha256:1k7hm3bkicrq6fdkhb1146c4a79mihrk36vg3ngv779n54m9y3272122 NarSize: 2482123 References: /nix/var/nix/builds/nix-60884-3569518374/TestClientPushesUseOnePush1934828710/001/store/3ng3app8r2xi80drmiss4zwzpb4zvbdb-shared-dep2124 CA: text:sha256:0f8bbfp2q3qgd759psvnxwh6rspz49ha9alzv71k34zmkp93v80d2125 client_pushes_test.go:97: Retrieved narinfo from S3:2126 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientPushesUseOnePush1934828710/001/store/n41q1rv1cfy0ddqs18krxvraa32gq3v0-b2127 URL: nar/1k7hm3bkicrq6fdkhb1146c4a79mihrk36vg3ngv779n54m9y327.nar.zst2128 Compression: zstd2129 NarHash: sha256:1k7hm3bkicrq6fdkhb1146c4a79mihrk36vg3ngv779n54m9y3272130 NarSize: 2482131 References: /nix/var/nix/builds/nix-60884-3569518374/TestClientPushesUseOnePush1934828710/001/store/3ng3app8r2xi80drmiss4zwzpb4zvbdb-shared-dep2132 CA: text:sha256:0f8bbfp2q3qgd759psvnxwh6rspz49ha9alzv71k34zmkp93v80d2133=== NAME TestPinProtectsFromGC2134 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-60884-3569518374/TestPinProtectsFromGC3875815769/001/store/qv2d08s8xm5fz8lz0zk6yjq0rzysip4p-pinned-file.txt2135 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-60884-3569518374/TestPinProtectsFromGC3875815769/001/store/6af9rqs8x0ir0pgsh9csyby75msbisbb-unpinned-file.txt2136--- PASS: TestClientPushesUseOnePush (3.43s)2137=== CONT TestGetExistingObjectsLocksRows21382026/10/01 09:43:26 INFO Received push request method=POST path=/api/pushes21392026-10-01 09:43:26.029 UTC [61651] ERROR: relation "goose_db_version" does not exist at character 3621402026-10-01 09:43:26.029 UTC [61651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21412026/10/01 09:43:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21422026/10/01 09:43:26 INFO Uploading qv2d08s8xm5fz8lz0zk6yjq0rzysip4p-pinned-file.txt (128B)21432026/10/01 09:43:26 WARN Failed to register uploaded object key=qv2d08s8xm5fz8lz0zk6yjq0rzysip4p.ls error="server returned 404: 404 page not found\n"21442026/10/01 09:43:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21452026/10/01 09:43:26 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21462026/10/01 09:43:26 INFO Signed narinfos id=1 count=121472026/10/01 09:43:26 INFO Uploading 1 narinfos21482026/10/01 09:43:26 INFO Received complete push request method=POST path=/api/pushes/1/complete21492026/10/01 09:43:26 WARN Failed to register uploaded object key=qv2d08s8xm5fz8lz0zk6yjq0rzysip4p.narinfo error="server returned 404: 404 page not found\n"21502026/10/01 09:43:26 OK 20241026095416_initial_model.sql (146.89ms)21512026/10/01 09:43:26 INFO Upload complete. (132ms)21522026/10/01 09:43:26 OK 20251210153512_drop_unused_gin_index.sql (6.98ms)21532026/10/01 09:43:26 OK 20251218171726_add_pins.sql (24.95ms)21542026/10/01 09:43:26 OK 20260628120000_add_object_size_and_stats.sql (32.76ms)21552026/10/01 09:43:26 OK 20260905000000_add_claims.sql (14.49ms)21562026/10/01 09:43:26 INFO Received push request method=POST path=/api/pushes21572026/10/01 09:43:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21582026/10/01 09:43:26 INFO Uploading 6af9rqs8x0ir0pgsh9csyby75msbisbb-unpinned-file.txt (128B)21592026/10/01 09:43:26 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"21602026/10/01 09:43:26 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign21612026/10/01 09:43:26 WARN Failed to register uploaded object key=6af9rqs8x0ir0pgsh9csyby75msbisbb.ls error="server returned 404: 404 page not found\n"21622026/10/01 09:43:26 INFO Signed narinfos id=2 count=121632026/10/01 09:43:26 INFO Uploading 1 narinfos21642026/10/01 09:43:26 OK 20260920000000_drop_claims.sql (29.42ms)21652026/10/01 09:43:26 OK 20260923120000_add_pushes.sql (6.59ms)21662026/10/01 09:43:26 goose: successfully migrated database to version: 2026092312000021672026/10/01 09:43:26 INFO Received complete push request method=POST path=/api/pushes/2/complete21682026/10/01 09:43:26 OK 1_commit_pending_closure.sql (1.1ms)21692026/10/01 09:43:26 OK 2_object_stats_trigger.sql (285.54µs)21702026/10/01 09:43:26 INFO Upload complete. (82ms)21712026/10/01 09:43:26 WARN Failed to register uploaded object key=6af9rqs8x0ir0pgsh9csyby75msbisbb.narinfo error="server returned 404: 404 page not found\n"21722026/10/01 09:43:26 OK 3_commit_push.sql (714.17µs)21732026/10/01 09:43:26 goose: up to current file version: 321742026/10/01 09:43:26 OK 20241026095416_initial_model.sql (128.1ms)21752026/10/01 09:43:26 OK 20251210153512_drop_unused_gin_index.sql (7.89ms)21762026/10/01 09:43:26 INFO Received push request method=POST path=/api/pushes21772026/10/01 09:43:26 INFO Starting cleanup of old closures method=DELETE path=/api/closures21782026/10/01 09:43:26 INFO Garbage collection started21792026/10/01 09:43:26 OK 20251218171726_add_pins.sql (29.98ms)21802026/10/01 09:43:26 INFO Aborted multipart uploads count=0 kept=021812026/10/01 09:43:26 WARN Force mode enabled - objects will be deleted immediately without grace period21822026/10/01 09:43:26 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21832026/10/01 09:43:26 INFO Uploading 3hp794711yxbfvlc1mvvbl4hvfccn4zd-top (256B)21842026/10/01 09:43:26 INFO Uploading ms175ps4n4csibhbbbj2kh2q6qzvlicr-shared-dep (136B)21852026/10/01 09:43:26 OK 20260628120000_add_object_size_and_stats.sql (54.09ms)21862026/10/01 09:43:26 WARN Failed to register uploaded object key=3hp794711yxbfvlc1mvvbl4hvfccn4zd.ls error="server returned 404: 404 page not found\n"21872026/10/01 09:43:26 WARN Failed to register uploaded object key=ms175ps4n4csibhbbbj2kh2q6qzvlicr.ls error="server returned 404: 404 page not found\n"21882026/10/01 09:43:26 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21892026/10/01 09:43:26 WARN Failed to register uploaded object key=nar/1dhmhh0475xs9ghw6k3dll1wm3gs1p2pficsf99d590xlwbnn8fr.nar.zst error="server returned 404: 404 page not found\n"21902026/10/01 09:43:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21912026/10/01 09:43:26 INFO Signed narinfos id=1 count=221922026/10/01 09:43:26 INFO Uploading 2 narinfos21932026/10/01 09:43:26 WARN Failed to register uploaded object key=ms175ps4n4csibhbbbj2kh2q6qzvlicr.narinfo error="server returned 404: 404 page not found\n"21942026/10/01 09:43:26 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=021952026/10/01 09:43:26 INFO Received complete push request method=POST path=/api/pushes/1/complete21962026/10/01 09:43:26 WARN Failed to register uploaded object key=3hp794711yxbfvlc1mvvbl4hvfccn4zd.narinfo error="server returned 404: 404 page not found\n"21972026/10/01 09:43:26 OK 20260905000000_add_claims.sql (47.3ms)21982026/10/01 09:43:26 INFO Vacuumed table table=pending_closures21992026/10/01 09:43:26 INFO Upload complete. (173ms)2200=== NAME TestClientSharedPathCommittedMidPush2201 client_integration_test.go:680: Retrieved narinfo from S3:2202 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientSharedPathCommittedMidPush1468666706/001/store/ms175ps4n4csibhbbbj2kh2q6qzvlicr-shared-dep2203 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2204 Compression: zstd2205 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822206 NarSize: 1362207 References: 2208 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2209 client_integration_test.go:680: Retrieved narinfo from S3:2210 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientSharedPathCommittedMidPush1468666706/001/store/3hp794711yxbfvlc1mvvbl4hvfccn4zd-top2211 URL: nar/1dhmhh0475xs9ghw6k3dll1wm3gs1p2pficsf99d590xlwbnn8fr.nar.zst2212 Compression: zstd2213 NarHash: sha256:1dhmhh0475xs9ghw6k3dll1wm3gs1p2pficsf99d590xlwbnn8fr2214 NarSize: 2562215 References: /nix/var/nix/builds/nix-60884-3569518374/TestClientSharedPathCommittedMidPush1468666706/001/store/ms175ps4n4csibhbbbj2kh2q6qzvlicr-shared-dep2216 CA: text:sha256:0yq4j94925lvsl5nw3hp4d9ynksmrrjc8mrwvnvhf17pivxfgld322172026/10/01 09:43:26 OK 20260920000000_drop_claims.sql (26.96ms)22182026/10/01 09:43:26 INFO Vacuumed table table=pending_objects22192026/10/01 09:43:26 INFO Vacuumed table table=multipart_uploads22202026/10/01 09:43:26 OK 20260923120000_add_pushes.sql (7.71ms)22212026/10/01 09:43:26 goose: successfully migrated database to version: 2026092312000022222026/10/01 09:43:26 OK 1_commit_pending_closure.sql (1.17ms)22232026/10/01 09:43:26 OK 2_object_stats_trigger.sql (271.92µs)22242026/10/01 09:43:26 OK 3_commit_push.sql (205.96µs)22252026/10/01 09:43:26 goose: up to current file version: 322262026/10/01 09:43:26 INFO Vacuumed table table=closures22272026/10/01 09:43:26 INFO Vacuumed table table=objects2228--- PASS: TestService_ReadScope_PublicByDefault (1.94s)2229=== CONT TestRegisterCompletedObjectNeedsPendingRow2230--- PASS: TestClientSharedPathCommittedMidPush (2.82s)2231=== CONT TestSweepSkipsRowsLockedByPush2232=== NAME TestClientWithDependencies2233 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-60884-3569518374/TestClientWithDependencies1006817379/001/store/ikz7xw9pbhvvd3pis00nw3a2916n8skj-test-script2234 client_integration_test.go:615: Found 1 dependencies (including self)22352026/10/01 09:43:26 INFO Received push request method=POST path=/api/pushes2236=== NAME TestOrphanedObjectsGCStressTest2237 orphaned_objects_gc_test.go:509: Stress test completed successfully:2238 orphaned_objects_gc_test.go:510: - Active objects preserved: 202239 orphaned_objects_gc_test.go:511: - Objects deleted: 2102240 orphaned_objects_gc_test.go:512: - Total GC'd: 2102241--- PASS: TestOrphanedObjectsGCStressTest (13.43s)2242=== CONT TestFailedS3DeleteKeepsTombstone22432026/10/01 09:43:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22442026/10/01 09:43:26 INFO Uploading ikz7xw9pbhvvd3pis00nw3a2916n8skj-test-script (136B)22452026/10/01 09:43:26 WARN Failed to register uploaded object key=ikz7xw9pbhvvd3pis00nw3a2916n8skj.ls error="server returned 404: 404 page not found\n"22462026/10/01 09:43:26 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"22472026/10/01 09:43:26 WARN Failed to register uploaded object key=log/a1c4mxxrg2k5jd4yly0k01ap9fsi50a2-test-script.drv error="server returned 404: 404 page not found\n"22482026/10/01 09:43:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22492026/10/01 09:43:26 INFO Signed narinfos id=1 count=122502026/10/01 09:43:26 INFO Uploading 1 narinfos22512026/10/01 09:43:26 INFO Received complete push request method=POST path=/api/pushes/1/complete22522026/10/01 09:43:26 WARN Failed to register uploaded object key=ikz7xw9pbhvvd3pis00nw3a2916n8skj.narinfo error="server returned 404: 404 page not found\n"2253=== NAME TestClientIntegration2254 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-60884-3569518374/TestClientIntegration2423001343/002/store/qrxb3ywxqcbiw8hg1dwibmqc35fp5qnr-test-file.txt22552026/10/01 09:43:26 INFO Upload complete. (165ms)2256=== NAME TestClientWithDependencies2257 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-60884-3569518374/TestClientWithDependencies1006817379/001/store) requires matching store prefix2258--- PASS: TestClientWithDependencies (2.51s)2259=== CONT TestForceGCDuringPushOffersSweptObject2260=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows2261=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows2262=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check2263=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check2264=== CONT TestGCSweepSkipsPendingObjects22652026-10-01 09:43:26.934 UTC [61693] ERROR: relation "goose_db_version" does not exist at character 3622662026-10-01 09:43:26.934 UTC [61693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22672026/10/01 09:43:26 INFO Received push request method=POST path=/api/pushes22682026/10/01 09:43:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22692026/10/01 09:43:26 INFO Uploading qrxb3ywxqcbiw8hg1dwibmqc35fp5qnr-test-file.txt (152B)22702026/10/01 09:43:26 WARN Failed to register uploaded object key=qrxb3ywxqcbiw8hg1dwibmqc35fp5qnr.ls error="server returned 404: 404 page not found\n"22712026/10/01 09:43:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22722026/10/01 09:43:26 INFO Signed narinfos id=1 count=122732026/10/01 09:43:26 INFO Uploading 1 narinfos22742026/10/01 09:43:26 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"22752026/10/01 09:43:26 INFO Received complete push request method=POST path=/api/pushes/1/complete22762026/10/01 09:43:26 WARN Failed to register uploaded object key=qrxb3ywxqcbiw8hg1dwibmqc35fp5qnr.narinfo error="server returned 404: 404 page not found\n"22772026-10-01 09:43:26.964 UTC [61695] ERROR: relation "goose_db_version" does not exist at character 3622782026-10-01 09:43:26.964 UTC [61695] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22792026/10/01 09:43:26 INFO Upload complete. (94ms)22802026/10/01 09:43:27 OK 20241026095416_initial_model.sql (57.42ms)22812026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (6.44ms)22822026/10/01 09:43:27 OK 20251218171726_add_pins.sql (1.89ms)22832026/10/01 09:43:27 INFO All 1 paths already cached2284=== NAME TestClientIntegration2285 client_integration_test.go:312: Retrieved narinfo from S3:2286 StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientIntegration2423001343/002/store/qrxb3ywxqcbiw8hg1dwibmqc35fp5qnr-test-file.txt2287 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2288 Compression: zstd2289 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12290 NarSize: 1522291 References: 2292 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk122932026/10/01 09:43:27 OK 20241026095416_initial_model.sql (29.83ms)22942026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (1.42ms)22952026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (589.46µs)2296 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2297 client_integration_test.go:313: Decompressed .ls content (64 bytes):2298 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2299 client_integration_test.go:316: Testing garbage collection...23002026/10/01 09:43:27 OK 20251218171726_add_pins.sql (1.49ms)23012026/10/01 09:43:27 OK 20260905000000_add_claims.sql (2.01ms)23022026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (701.63µs)23032026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (650µs)23042026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000023052026/10/01 09:43:27 OK 1_commit_pending_closure.sql (876.67µs)23062026/10/01 09:43:27 OK 2_object_stats_trigger.sql (215.13µs)23072026/10/01 09:43:27 OK 3_commit_push.sql (177.13µs)23082026/10/01 09:43:27 goose: up to current file version: 323092026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (25.67ms)23102026/10/01 09:43:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures23112026/10/01 09:43:27 INFO Garbage collection started23122026/10/01 09:43:27 INFO Aborted multipart uploads count=0 kept=023132026/10/01 09:43:27 WARN Force mode enabled - objects will be deleted immediately without grace period23142026/10/01 09:43:27 OK 20260905000000_add_claims.sql (19.54ms)23152026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (1.24ms)23162026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (3.02ms)23172026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000023182026/10/01 09:43:27 OK 1_commit_pending_closure.sql (894.33µs)23192026/10/01 09:43:27 OK 2_object_stats_trigger.sql (209.79µs)23202026/10/01 09:43:27 OK 3_commit_push.sql (165.79µs)23212026/10/01 09:43:27 goose: up to current file version: 323222026-10-01 09:43:27.088 UTC [61703] ERROR: relation "goose_db_version" does not exist at character 3623232026-10-01 09:43:27.088 UTC [61703] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23242026/10/01 09:43:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=023252026/10/01 09:43:27 INFO Vacuumed table table=pending_closures23262026/10/01 09:43:27 INFO Vacuumed table table=pending_objects23272026/10/01 09:43:27 INFO Vacuumed table table=multipart_uploads2328=== NAME TestClientCADerivations2329 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-60884-3569518374/TestClientCADerivations4044913850/001/store/hqhidrg6hy89hg80604b5sf7qifcraqy-ca-test23302026/10/01 09:43:27 INFO Vacuumed table table=closures23312026/10/01 09:43:27 INFO Vacuumed table table=objects23322026/10/01 09:43:27 OK 20241026095416_initial_model.sql (93.14ms)23332026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (1.21ms)23342026/10/01 09:43:27 INFO Received uploads request method=POST path=/api/pending_closures2335 client_ca_test.go:139: Found 1 dependencies (including self)23362026/10/01 09:43:27 OK 20251218171726_add_pins.sql (32.62ms)23372026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (18.91ms)23382026/10/01 09:43:27 OK 20260905000000_add_claims.sql (13.4ms)23392026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (10.92ms)23402026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (1.29ms)23412026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000023422026/10/01 09:43:27 OK 1_commit_pending_closure.sql (1.2ms)23432026/10/01 09:43:27 OK 2_object_stats_trigger.sql (348.25µs)23442026/10/01 09:43:27 OK 3_commit_push.sql (196µs)23452026/10/01 09:43:27 goose: up to current file version: 323462026/10/01 09:43:27 INFO Received push request method=POST path=/api/pushes23472026/10/01 09:43:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23482026/10/01 09:43:27 INFO Uploading hqhidrg6hy89hg80604b5sf7qifcraqy-ca-test (144B)23492026/10/01 09:43:27 WARN Failed to register uploaded object key=hqhidrg6hy89hg80604b5sf7qifcraqy.ls error="server returned 404: 404 page not found\n"23502026/10/01 09:43:27 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"23512026/10/01 09:43:27 WARN Failed to register uploaded object key=log/1p8279nx58hailv3n0z7lsx41vqvgynv-ca-test.drv error="server returned 404: 404 page not found\n"23522026/10/01 09:43:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23532026/10/01 09:43:27 INFO Signed narinfos id=1 count=123542026/10/01 09:43:27 INFO Uploading 1 narinfos23552026/10/01 09:43:27 INFO Received complete push request method=POST path=/api/pushes/1/complete23562026/10/01 09:43:27 WARN Failed to register uploaded object key=hqhidrg6hy89hg80604b5sf7qifcraqy.narinfo error="server returned 404: 404 page not found\n"23572026/10/01 09:43:27 INFO Upload complete. (151ms)2358 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-60884-3569518374/TestClientCADerivations4044913850/001/store/hqhidrg6hy89hg80604b5sf7qifcraqy-ca-test2359 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2360 Compression: zstd2361 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2362 NarSize: 1442363 References: 2364 Deriver: /nix/var/nix/builds/nix-60884-3569518374/TestClientCADerivations4044913850/001/store/1p8279nx58hailv3n0z7lsx41vqvgynv-ca-test.drv2365 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2366 client_ca_test.go:185: Checking for realisation files in S3...2367 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2368 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2369--- PASS: TestCacheStatsHandler (1.67s)2370=== CONT TestGCSweepDeliversEachKeyOnce2371--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.66s)2372=== CONT TestTombstonedObjectOfferedWithoutWaiting23732026-10-01 09:43:27.490 UTC [61718] ERROR: relation "goose_db_version" does not exist at character 3623742026-10-01 09:43:27.490 UTC [61718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23752026-10-01 09:43:27.490 UTC [61719] ERROR: relation "goose_db_version" does not exist at character 3623762026-10-01 09:43:27.490 UTC [61719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2377=== NAME TestClientCADerivations2378 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket62?endpoint=http://localhost:51054®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-60884-3569518374/TestClientCADerivations4044913850/001/store'2379 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12380--- PASS: TestClientCADerivations (2.77s)2381=== CONT TestService_ReadAuthMiddleware2382--- PASS: TestGetExistingObjectsLocksRows (1.66s)2383=== CONT TestService_RequireScope_OIDC23842026/10/01 09:43:27 OK 20241026095416_initial_model.sql (89.74ms)23852026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (3.18ms)23862026/10/01 09:43:27 OK 20241026095416_initial_model.sql (100.41ms)23872026/10/01 09:43:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51700/oidc23882026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (8.19ms)23892026/10/01 09:43:27 OK 20251218171726_add_pins.sql (16.17ms)23902026/10/01 09:43:27 OK 20251218171726_add_pins.sql (2.51ms)23912026-10-01 09:43:27.637 UTC [61725] ERROR: relation "goose_db_version" does not exist at character 3623922026-10-01 09:43:27.637 UTC [61725] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23932026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (9.22ms)23942026/10/01 09:43:27 OK 20260905000000_add_claims.sql (1.36ms)23952026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (940.38µs)23962026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (429.63µs)23972026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000023982026/10/01 09:43:27 OK 1_commit_pending_closure.sql (880.17µs)23992026-10-01 09:43:27.644 UTC [61726] ERROR: relation "goose_db_version" does not exist at character 3624002026-10-01 09:43:27.644 UTC [61726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24012026/10/01 09:43:27 OK 2_object_stats_trigger.sql (192.42µs)24022026/10/01 09:43:27 OK 3_commit_push.sql (185.38µs)24032026/10/01 09:43:27 goose: up to current file version: 324042026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (32.81ms)24052026/10/01 09:43:27 OK 20260905000000_add_claims.sql (15.82ms)24062026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (17.06ms)24072026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (6.58ms)24082026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000024092026/10/01 09:43:27 OK 1_commit_pending_closure.sql (2.4ms)24102026/10/01 09:43:27 OK 2_object_stats_trigger.sql (227.42µs)24112026/10/01 09:43:27 OK 3_commit_push.sql (167.83µs)24122026/10/01 09:43:27 goose: up to current file version: 324132026/10/01 09:43:27 OK 20241026095416_initial_model.sql (64.08ms)24142026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (6.25ms)24152026/10/01 09:43:27 OK 20251218171726_add_pins.sql (3.18ms)24162026/10/01 09:43:27 OK 20241026095416_initial_model.sql (58.94ms)24172026/10/01 09:43:27 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)24182026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (17.52ms)24192026/10/01 09:43:27 OK 20251218171726_add_pins.sql (7.34ms)24202026/10/01 09:43:27 OK 20260905000000_add_claims.sql (15.57ms)24212026/10/01 09:43:27 OK 20260628120000_add_object_size_and_stats.sql (15.63ms)24222026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (18.25ms)24232026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (13.45ms)24242026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000024252026/10/01 09:43:27 OK 20260905000000_add_claims.sql (32.66ms)24262026/10/01 09:43:27 OK 1_commit_pending_closure.sql (1.33ms)24272026/10/01 09:43:27 OK 2_object_stats_trigger.sql (252.33µs)24282026/10/01 09:43:27 OK 3_commit_push.sql (196.79µs)24292026/10/01 09:43:27 goose: up to current file version: 324302026/10/01 09:43:27 OK 20260920000000_drop_claims.sql (30.07ms)24312026/10/01 09:43:27 OK 20260923120000_add_pushes.sql (7.18ms)24322026/10/01 09:43:27 goose: successfully migrated database to version: 2026092312000024332026/10/01 09:43:27 OK 1_commit_pending_closure.sql (1.64ms)24342026/10/01 09:43:27 OK 2_object_stats_trigger.sql (334.25µs)24352026/10/01 09:43:27 OK 3_commit_push.sql (252.38µs)24362026/10/01 09:43:27 goose: up to current file version: 324372026/10/01 09:43:27 INFO Aborted multipart uploads count=0 kept=024382026/10/01 09:43:27 WARN Force mode enabled - objects will be deleted immediately without grace period24392026/10/01 09:43:27 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=024402026/10/01 09:43:27 INFO Vacuumed table table=pending_closures24412026/10/01 09:43:27 INFO Vacuumed table table=pending_objects24422026/10/01 09:43:27 INFO Vacuumed table table=multipart_uploads24432026/10/01 09:43:27 INFO Vacuumed table table=closures24442026/10/01 09:43:27 INFO Vacuumed table table=objects24452026/10/01 09:43:27 INFO Aborted multipart uploads count=0 kept=024462026/10/01 09:43:27 WARN Force mode enabled - objects will be deleted immediately without grace period24472026/10/01 09:43:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=024482026/10/01 09:43:27 INFO Vacuumed table table=pending_closures24492026/10/01 09:43:27 INFO Vacuumed table table=pending_objects24502026/10/01 09:43:27 INFO Vacuumed table table=multipart_uploads24512026/10/01 09:43:27 INFO Vacuumed table table=closures24522026/10/01 09:43:27 INFO Vacuumed table table=objects2453--- PASS: TestSweepSkipsRowsLockedByPush (1.53s)2454=== CONT TestService_AuthMiddleware_OIDC24552026/10/01 09:43:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51706/oidc2456--- PASS: TestRegisterCompletedObjectNeedsPendingRow (1.63s)2457=== CONT TestDeduplicatedObjectsRecordedAsPending24582026/10/01 09:43:28 INFO Received uploads request method=POST path=/api/pending_closures24592026/10/01 09:43:28 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=024602026/10/01 09:43:28 INFO Received create pin request method=POST path=/api/pins/myapp24612026/10/01 09:43:28 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-60884-3569518374/TestPinProtectsFromGC3875815769/001/store/qv2d08s8xm5fz8lz0zk6yjq0rzysip4p-pinned-file.txt narinfo_key=qv2d08s8xm5fz8lz0zk6yjq0rzysip4p.narinfo24622026/10/01 09:43:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures24632026/10/01 09:43:28 INFO Garbage collection started24642026/10/01 09:43:28 INFO Aborted multipart uploads count=0 kept=024652026/10/01 09:43:28 WARN Force mode enabled - objects will be deleted immediately without grace period24662026/10/01 09:43:28 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=024672026/10/01 09:43:28 INFO Vacuumed table table=pending_closures24682026/10/01 09:43:28 INFO Vacuumed table table=pending_objects24692026/10/01 09:43:28 INFO Vacuumed table table=multipart_uploads24702026/10/01 09:43:28 INFO Vacuumed table table=closures24712026/10/01 09:43:28 INFO Vacuumed table table=objects24722026/10/01 09:43:28 INFO Aborted multipart uploads count=0 kept=024732026/10/01 09:43:28 WARN Force mode enabled - objects will be deleted immediately without grace period24742026/10/01 09:43:28 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."24752026/10/01 09:43:28 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2476--- PASS: TestFailedS3DeleteKeepsTombstone (1.64s)2477=== CONT TestPushDedupSurvivesConcurrentGC24782026/10/01 09:43:28 INFO Received uploads request method=POST path=/api/pending_closures24792026/10/01 09:43:28 INFO Aborted multipart uploads count=0 kept=024802026/10/01 09:43:28 WARN Force mode enabled - objects will be deleted immediately without grace period24812026/10/01 09:43:28 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=024822026/10/01 09:43:28 INFO Vacuumed table table=pending_closures24832026/10/01 09:43:28 INFO Vacuumed table table=pending_objects24842026/10/01 09:43:28 INFO Vacuumed table table=multipart_uploads24852026/10/01 09:43:28 INFO Vacuumed table table=closures24862026-10-01 09:43:28.590 UTC [61738] ERROR: relation "goose_db_version" does not exist at character 3624872026-10-01 09:43:28.590 UTC [61738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24882026-10-01 09:43:28.591 UTC [61737] ERROR: relation "goose_db_version" does not exist at character 3624892026-10-01 09:43:28.591 UTC [61737] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24902026/10/01 09:43:28 INFO Vacuumed table table=objects24912026-10-01 09:43:28.596 UTC [61739] ERROR: relation "goose_db_version" does not exist at character 3624922026-10-01 09:43:28.596 UTC [61739] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2493--- PASS: TestGCSweepSkipsPendingObjects (1.71s)2494=== CONT TestService_AuthMiddleware_MTLSBoundSubjects24952026/10/01 09:43:28 OK 20241026095416_initial_model.sql (12.95ms)24962026/10/01 09:43:28 OK 20251210153512_drop_unused_gin_index.sql (610.13µs)24972026/10/01 09:43:28 OK 20251218171726_add_pins.sql (1.05ms)24982026/10/01 09:43:28 OK 20260628120000_add_object_size_and_stats.sql (7.35ms)24992026/10/01 09:43:28 OK 20241026095416_initial_model.sql (43.43ms)25002026/10/01 09:43:28 OK 20241026095416_initial_model.sql (44.17ms)25012026/10/01 09:43:28 OK 20251210153512_drop_unused_gin_index.sql (824.79µs)25022026/10/01 09:43:28 OK 20260905000000_add_claims.sql (26.3ms)25032026/10/01 09:43:28 OK 20251210153512_drop_unused_gin_index.sql (719.29µs)25042026/10/01 09:43:28 OK 20251218171726_add_pins.sql (1.06ms)25052026/10/01 09:43:28 OK 20260920000000_drop_claims.sql (1.14ms)25062026/10/01 09:43:28 OK 20251218171726_add_pins.sql (1.19ms)25072026/10/01 09:43:28 OK 20260923120000_add_pushes.sql (2.86ms)25082026/10/01 09:43:28 goose: successfully migrated database to version: 2026092312000025092026/10/01 09:43:28 OK 1_commit_pending_closure.sql (1.43ms)25102026/10/01 09:43:28 OK 2_object_stats_trigger.sql (242.92µs)25112026/10/01 09:43:28 OK 3_commit_push.sql (214.79µs)25122026/10/01 09:43:28 goose: up to current file version: 325132026-10-01 09:43:28.655 UTC [61742] ERROR: relation "goose_db_version" does not exist at character 3625142026-10-01 09:43:28.655 UTC [61742] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25152026/10/01 09:43:28 OK 20260628120000_add_object_size_and_stats.sql (6.6ms)25162026/10/01 09:43:28 OK 20260628120000_add_object_size_and_stats.sql (13.07ms)25172026/10/01 09:43:28 OK 20260905000000_add_claims.sql (6.45ms)25182026/10/01 09:43:28 OK 20260905000000_add_claims.sql (45.66ms)25192026/10/01 09:43:28 OK 20260920000000_drop_claims.sql (53.71ms)25202026/10/01 09:43:28 OK 20260920000000_drop_claims.sql (9.25ms)25212026/10/01 09:43:28 OK 20260923120000_add_pushes.sql (1.67ms)25222026/10/01 09:43:28 goose: successfully migrated database to version: 2026092312000025232026/10/01 09:43:28 OK 20260923120000_add_pushes.sql (1.57ms)25242026/10/01 09:43:28 goose: successfully migrated database to version: 2026092312000025252026/10/01 09:43:28 OK 1_commit_pending_closure.sql (2.04ms)25262026/10/01 09:43:28 OK 1_commit_pending_closure.sql (1.29ms)25272026/10/01 09:43:28 OK 2_object_stats_trigger.sql (252.33µs)25282026/10/01 09:43:28 OK 2_object_stats_trigger.sql (235.67µs)25292026/10/01 09:43:28 OK 3_commit_push.sql (191.71µs)25302026/10/01 09:43:28 goose: up to current file version: 325312026/10/01 09:43:28 OK 3_commit_push.sql (191.67µs)25322026/10/01 09:43:28 goose: up to current file version: 325332026/10/01 09:43:28 OK 20241026095416_initial_model.sql (59.76ms)25342026/10/01 09:43:28 OK 20251210153512_drop_unused_gin_index.sql (9.09ms)25352026/10/01 09:43:28 OK 20251218171726_add_pins.sql (9.49ms)25362026/10/01 09:43:28 OK 20260628120000_add_object_size_and_stats.sql (24.58ms)25372026/10/01 09:43:28 OK 20260905000000_add_claims.sql (40.62ms)25382026/10/01 09:43:28 OK 20260920000000_drop_claims.sql (24.86ms)25392026/10/01 09:43:28 OK 20260923120000_add_pushes.sql (3.36ms)25402026/10/01 09:43:28 goose: successfully migrated database to version: 2026092312000025412026/10/01 09:43:28 OK 1_commit_pending_closure.sql (2.83ms)25422026/10/01 09:43:28 OK 2_object_stats_trigger.sql (1.18ms)25432026/10/01 09:43:28 INFO Received uploads request method=POST path=/api/pending_closures25442026/10/01 09:43:28 OK 3_commit_push.sql (498.5µs)25452026/10/01 09:43:28 goose: up to current file version: 32546--- PASS: TestTombstonedObjectOfferedWithoutWaiting (1.45s)2547=== CONT TestService_AuthMiddleware_MTLSProxyHeader25482026/10/01 09:43:29 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02549=== NAME TestClientIntegration2550 client_integration_test.go:323: Objects in database after GC:2551 client_integration_test.go:323: Successfully deleted all objects with GC --force2552--- PASS: TestClientIntegration (4.43s)2553=== CONT TestGCMetrics25542026/10/01 09:43:29 INFO Aborted multipart uploads count=0 kept=025552026/10/01 09:43:29 WARN Force mode enabled - objects will be deleted immediately without grace period25562026/10/01 09:43:29 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=025572026/10/01 09:43:29 INFO Vacuumed table table=pending_closures25582026/10/01 09:43:29 INFO Vacuumed table table=pending_objects25592026/10/01 09:43:29 INFO Vacuumed table table=multipart_uploads25602026/10/01 09:43:29 INFO Vacuumed table table=closures25612026/10/01 09:43:29 INFO Vacuumed table table=objects2562--- PASS: TestGCSweepDeliversEachKeyOnce (1.85s)2563=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info25642026/10/01 09:43:29 INFO Received uploads request method=POST path=/2565=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key25662026/10/01 09:43:29 INFO Received request for more parts method=POST path=/2567=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key25682026/10/01 09:43:29 INFO Received complete multipart upload request method=POST path=/2569=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal25702026/10/01 09:43:29 INFO Received uploads request method=POST path=/2571--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2572 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2573 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2574 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2575 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2576=== CONT TestProxyWriteTimeout/narinfo2577=== CONT TestProxyWriteTimeout/unknown_size2578=== CONT TestProxyWriteTimeout/10_GiB_nar2579=== CONT TestProxyWriteTimeout/1_GiB_nar2580--- PASS: TestProxyWriteTimeout (0.02s)2581 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2582 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2583 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2584 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2585=== CONT TestIsValidUploadKey/narinfo2586=== CONT TestIsValidUploadKey/realisation_plus_in_output2587=== CONT TestIsValidUploadKey/unknown_type2588=== CONT TestIsValidUploadKey/empty_key2589=== CONT TestIsValidUploadKey/absolute2590=== CONT TestIsValidUploadKey/build_log_home-manager_file2591=== CONT TestIsValidUploadKey/traversal_nar2592=== CONT TestIsValidUploadKey/realisation2593=== CONT TestIsValidUploadKey/traversal2594=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2595=== CONT TestIsValidUploadKey/build_log_equals2596=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2597=== CONT TestIsValidUploadKey/build_log_question_mark2598=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2599=== CONT TestIsValidUploadKey/build_log_plus_in_name2600=== CONT TestIsValidUploadKey/index.html2601=== CONT TestIsValidUploadKey/nix-cache-info2602=== CONT TestIsValidUploadKey/nar_plain2603=== CONT TestIsValidUploadKey/build_log2604=== CONT TestIsValidUploadKey/listing2605=== CONT TestIsValidUploadKey/nar_xz2606=== CONT TestIsValidUploadKey/nar_zst2607--- PASS: TestIsValidUploadKey (0.02s)2608 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2609 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2610 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2611 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2612 --- PASS: TestIsValidUploadKey/absolute (0.00s)2613 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2614 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2615 --- PASS: TestIsValidUploadKey/realisation (0.00s)2616 --- PASS: TestIsValidUploadKey/traversal (0.00s)2617 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2618 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2619 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2620 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2621 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2622 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2623 --- PASS: TestIsValidUploadKey/index.html (0.00s)2624 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2625 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2626 --- PASS: TestIsValidUploadKey/build_log (0.00s)2627 --- PASS: TestIsValidUploadKey/listing (0.00s)2628 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2629 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2630=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26312026/10/01 09:43:29 INFO Received uploads request method=POST path=/26322026-10-01 09:43:29.373 UTC [61748] ERROR: relation "goose_db_version" does not exist at character 3626332026-10-01 09:43:29.373 UTC [61748] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26342026-10-01 09:43:29.379 UTC [61749] ERROR: relation "goose_db_version" does not exist at character 3626352026-10-01 09:43:29.379 UTC [61749] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2636--- PASS: TestService_ReadAuthMiddleware (1.85s)2637=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts26382026/10/01 09:43:29 INFO Received request for more parts method=POST path=/2639=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart26402026/10/01 09:43:29 INFO Received complete multipart upload request method=POST path=/2641=== CONT TestPush_RejectsBadRequests/no_roots26422026/10/01 09:43:29 INFO Received push request method=POST path=/api/pushes2643=== CONT TestPush_RejectsBadRequests/bad_root26442026/10/01 09:43:29 INFO Received push request method=POST path=/api/pushes2645=== CONT TestPush_RejectsBadRequests/root_not_in_objects26462026/10/01 09:43:29 INFO Received push request method=POST path=/api/pushes2647=== CONT TestPush_RejectsBadRequests/no_objects26482026/10/01 09:43:29 INFO Received push request method=POST path=/api/pushes2649=== CONT TestIsValidCachePath/narinfo2650=== CONT TestIsValidCachePath/index.html2651=== CONT TestIsValidCachePath/short_hash2652--- PASS: TestPush_RejectsBadRequests (5.52s)2653 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2654 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2655 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2656 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2657=== CONT TestIsValidCachePath/wrong_extension2658=== CONT TestIsValidCachePath/leading_slash2659=== CONT TestIsValidCachePath/empty2660=== CONT TestIsValidCachePath/random_path2661=== CONT TestIsValidCachePath/invalid_char_u2662=== CONT TestIsValidCachePath/invalid_char_e2663=== CONT TestIsValidCachePath/traversal_in_middle2664=== CONT TestIsValidCachePath/traversal_parent2665=== CONT TestIsValidCachePath/nar_xz2666=== CONT TestIsValidCachePath/nar_bz22667=== CONT TestIsValidCachePath/nar_zst2668=== CONT TestIsValidCachePath/realisation2669=== CONT TestIsValidCachePath/nix-cache-info2670=== CONT TestIsValidCachePath/nar_uncompressed2671=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2672=== CONT TestIsValidCachePath/log2673=== CONT TestIsValidCachePath/ls2674--- PASS: TestIsValidCachePath (0.00s)2675 --- PASS: TestIsValidCachePath/narinfo (0.00s)2676 --- PASS: TestIsValidCachePath/index.html (0.00s)2677 --- PASS: TestIsValidCachePath/short_hash (0.00s)2678 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2679 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2680 --- PASS: TestIsValidCachePath/empty (0.00s)2681 --- PASS: TestIsValidCachePath/random_path (0.00s)2682 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2683 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2684 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2685 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2686 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2687 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2688 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2689 --- PASS: TestIsValidCachePath/realisation (0.00s)2690 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2691 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2692 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2693 --- PASS: TestIsValidCachePath/log (0.00s)2694 --- PASS: TestIsValidCachePath/ls (0.00s)2695=== CONT TestParseSingleRange/none2696=== CONT TestParseSingleRange/open-ended2697=== CONT TestParseSingleRange/start_far_past_EOF2698=== CONT TestParseSingleRange/start_past_EOF2699=== CONT TestParseSingleRange/single_byte2700=== CONT TestParseSingleRange/end_clamped_to_size2701=== CONT TestParseSingleRange/malformed_both_empty2702=== CONT TestParseSingleRange/closed2703=== CONT TestParseSingleRange/malformed_end_before_start2704=== CONT TestParseSingleRange/suffix2705=== CONT TestParseSingleRange/multi-range_ignored2706=== CONT TestParseSingleRange/suffix_exceeds_size2707=== CONT TestParseSingleRange/malformed_no_dash2708=== CONT TestParseSingleRange/unknown_unit2709--- PASS: TestParseSingleRange (0.00s)2710 --- PASS: TestParseSingleRange/none (0.00s)2711 --- PASS: TestParseSingleRange/open-ended (0.00s)2712 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2713 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2714 --- PASS: TestParseSingleRange/single_byte (0.00s)2715 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2716 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2717 --- PASS: TestParseSingleRange/closed (0.00s)2718 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2719 --- PASS: TestParseSingleRange/suffix (0.00s)2720 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2721 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2722 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2723 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2724=== CONT TestServerTLSConfig/no_client_CA2725=== CONT TestServerTLSConfig/not_a_PEM_file2726=== CONT TestServerTLSConfig/missing_CA_file2727--- PASS: TestServerTLSConfig (0.00s)2728 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2729 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)2730 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2731=== CONT TestResolveDBConnectionString/flag_wins2732=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2733=== CONT TestResolveDBConnectionString/nothing_configured2734=== CONT TestResolveDBConnectionString/missing_file_is_an_error2735=== CONT TestResolveDBConnectionString/file_when_flag_empty2736=== CONT TestClientErrorHandling/InvalidStorePath2737--- PASS: TestResolveDBConnectionString (0.02s)2738 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2739 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2740 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2741 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2742 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)27432026/10/01 09:43:29 OK 20241026095416_initial_model.sql (73.57ms)27442026/10/01 09:43:29 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)27452026/10/01 09:43:29 OK 20241026095416_initial_model.sql (50.03ms)27462026-10-01 09:43:29.494 UTC [61752] ERROR: relation "goose_db_version" does not exist at character 3627472026-10-01 09:43:29.494 UTC [61752] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27482026/10/01 09:43:29 OK 20251218171726_add_pins.sql (39.55ms)27492026/10/01 09:43:29 OK 20251210153512_drop_unused_gin_index.sql (33.73ms)27502026/10/01 09:43:29 OK 20260628120000_add_object_size_and_stats.sql (11.93ms)27512026/10/01 09:43:29 OK 20251218171726_add_pins.sql (12.36ms)27522026/10/01 09:43:29 OK 20260628120000_add_object_size_and_stats.sql (16.36ms)27532026/10/01 09:43:29 OK 20260905000000_add_claims.sql (32.24ms)2754--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)2755 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2756 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2757 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)2758=== CONT TestClientErrorHandling/ServerNotAvailable27592026/10/01 09:43:29 OK 20260905000000_add_claims.sql (33.57ms)27602026/10/01 09:43:29 OK 20260920000000_drop_claims.sql (23.14ms)27612026/10/01 09:43:29 OK 20260923120000_add_pushes.sql (10.32ms)27622026/10/01 09:43:29 goose: successfully migrated database to version: 2026092312000027632026/10/01 09:43:29 OK 1_commit_pending_closure.sql (960.13µs)27642026/10/01 09:43:29 OK 2_object_stats_trigger.sql (259.54µs)27652026/10/01 09:43:29 OK 3_commit_push.sql (187.75µs)27662026/10/01 09:43:29 goose: up to current file version: 327672026/10/01 09:43:29 OK 20260920000000_drop_claims.sql (21.13ms)27682026/10/01 09:43:29 OK 20260923120000_add_pushes.sql (1.78ms)27692026/10/01 09:43:29 goose: successfully migrated database to version: 2026092312000027702026/10/01 09:43:29 OK 1_commit_pending_closure.sql (2.28ms)27712026/10/01 09:43:29 OK 2_object_stats_trigger.sql (307.42µs)27722026/10/01 09:43:29 OK 3_commit_push.sql (965.79µs)27732026/10/01 09:43:29 goose: up to current file version: 32774=== RUN TestService_RequireScope_OIDC/builder_may_write2775=== PAUSE TestService_RequireScope_OIDC/builder_may_write2776=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2777=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2778=== RUN TestService_RequireScope_OIDC/ops_may_admin2779=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2780=== RUN TestService_RequireScope_OIDC/ops_may_not_write2781=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2782=== RUN TestService_RequireScope_OIDC/reader_may_not_write2783=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2784=== RUN TestService_RequireScope_OIDC/static_token_may_admin2785=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2786=== RUN TestService_RequireScope_OIDC/static_token_may_write2787=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2788=== RUN TestService_RequireScope_OIDC/reader_may_read2789=== PAUSE TestService_RequireScope_OIDC/reader_may_read2790=== RUN TestService_RequireScope_OIDC/writer_implies_read2791=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2792=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2793=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2794=== CONT TestClientErrorHandling/InvalidAuthToken27952026/10/01 09:43:29 OK 20241026095416_initial_model.sql (139.11ms)27962026/10/01 09:43:29 OK 20251210153512_drop_unused_gin_index.sql (8.34ms)27972026/10/01 09:43:29 OK 20251218171726_add_pins.sql (13.29ms)27982026/10/01 09:43:29 OK 20260628120000_add_object_size_and_stats.sql (22.02ms)27992026-10-01 09:43:29.729 UTC [61757] ERROR: relation "goose_db_version" does not exist at character 3628002026-10-01 09:43:29.729 UTC [61757] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28012026/10/01 09:43:29 OK 20260905000000_add_claims.sql (17.16ms)28022026/10/01 09:43:29 OK 20260920000000_drop_claims.sql (9.51ms)28032026/10/01 09:43:29 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28042026/10/01 09:43:29 OK 20260923120000_add_pushes.sql (15.49ms)28052026/10/01 09:43:29 goose: successfully migrated database to version: 2026092312000028062026/10/01 09:43:29 OK 1_commit_pending_closure.sql (933.29µs)28072026/10/01 09:43:29 OK 2_object_stats_trigger.sql (433.08µs)28082026/10/01 09:43:29 OK 3_commit_push.sql (333.58µs)28092026/10/01 09:43:29 goose: up to current file version: 32810=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2811=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2812=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2813=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2814=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2815=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2816=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2817=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2818=== CONT TestCacheConfigHandler/full_config,_no_issuer2819=== CONT TestCacheConfigHandler/no_signing_keys2820=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2821=== CONT TestCacheConfigHandler/no_cache_url_configured2822--- PASS: TestCacheConfigHandler (0.00s)2823 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2824 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2825 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2826 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2827=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows28282026/10/01 09:43:29 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.069166ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28292026/10/01 09:43:29 OK 20241026095416_initial_model.sql (111.29ms)28302026/10/01 09:43:29 OK 20251210153512_drop_unused_gin_index.sql (9.6ms)28312026/10/01 09:43:29 OK 20251218171726_add_pins.sql (1.86ms)28322026/10/01 09:43:29 OK 20260628120000_add_object_size_and_stats.sql (17.33ms)28332026/10/01 09:43:29 OK 20260905000000_add_claims.sql (17.12ms)28342026/10/01 09:43:29 OK 20260920000000_drop_claims.sql (10.51ms)28352026/10/01 09:43:29 OK 20260923120000_add_pushes.sql (5.98ms)28362026/10/01 09:43:29 goose: successfully migrated database to version: 2026092312000028372026/10/01 09:43:29 OK 1_commit_pending_closure.sql (1.61ms)28382026/10/01 09:43:29 OK 2_object_stats_trigger.sql (313.96µs)28392026/10/01 09:43:29 OK 3_commit_push.sql (264.58µs)28402026/10/01 09:43:29 goose: up to current file version: 328412026-10-01 09:43:29.995 UTC [61762] ERROR: relation "goose_db_version" does not exist at character 3628422026-10-01 09:43:29.995 UTC [61762] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28432026/10/01 09:43:30 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=396.614114ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28442026/10/01 09:43:30 INFO Received uploads request method=POST path=/api/pending_closures2845--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.02s)2846=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check28472026/10/01 09:43:30 OK 20241026095416_initial_model.sql (94.06ms)28482026/10/01 09:43:30 OK 20251210153512_drop_unused_gin_index.sql (7.72ms)28492026/10/01 09:43:30 OK 20251218171726_add_pins.sql (12.34ms)28502026/10/01 09:43:30 OK 20260628120000_add_object_size_and_stats.sql (24.57ms)28512026/10/01 09:43:30 OK 20260905000000_add_claims.sql (33.22ms)28522026/10/01 09:43:30 OK 20260920000000_drop_claims.sql (30.74ms)28532026/10/01 09:43:30 OK 20260923120000_add_pushes.sql (7.89ms)28542026/10/01 09:43:30 goose: successfully migrated database to version: 2026092312000028552026/10/01 09:43:30 OK 1_commit_pending_closure.sql (3.39ms)28562026/10/01 09:43:30 OK 2_object_stats_trigger.sql (703.96µs)28572026/10/01 09:43:30 OK 3_commit_push.sql (403.46µs)28582026/10/01 09:43:30 goose: up to current file version: 32859=== NAME TestPinProtectsFromGC2860 client_integration_test.go:840: Pin successfully protected closure from garbage collection2861--- PASS: TestPinProtectsFromGC (7.03s)2862=== CONT TestService_RequireScope_OIDC/builder_may_write2863=== CONT TestService_RequireScope_OIDC/static_token_may_admin2864=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2865=== CONT TestService_RequireScope_OIDC/writer_implies_read2866=== CONT TestService_RequireScope_OIDC/reader_may_read2867=== CONT TestService_RequireScope_OIDC/static_token_may_write2868=== CONT TestService_RequireScope_OIDC/ops_may_not_write2869=== CONT TestService_RequireScope_OIDC/reader_may_not_write2870=== CONT TestService_RequireScope_OIDC/ops_may_admin2871=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2872=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2873=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28742026/10/01 09:43:30 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]2875=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2876=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected28772026/10/01 09:43:30 WARN Authentication failed token_preview=eyJhbGciOi...FS2JlKrFSg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2878--- PASS: TestService_RequireScope_OIDC (2.01s)2879 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2880 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2881 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2882 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2883 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2884 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2885 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2886 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2887 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2888 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2889--- PASS: TestService_AuthMiddleware_OIDC (1.89s)2890 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2891 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2892 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2893 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)28942026/10/01 09:43:30 INFO Received uploads request method=POST path=/api/pending_closures28952026/10/01 09:43:30 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=748.226724ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28962026/10/01 09:43:30 INFO Aborted multipart uploads count=0 kept=028972026-10-01 09:43:30.543 UTC [61765] ERROR: relation "goose_db_version" does not exist at character 3628982026-10-01 09:43:30.543 UTC [61765] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28992026/10/01 09:43:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=029002026/10/01 09:43:30 INFO Vacuumed table table=pending_closures29012026/10/01 09:43:30 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"29022026/10/01 09:43:30 WARN mTLS auth: bound subjects configured but subject DN unavailable29032026/10/01 09:43:30 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2904--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.00s)29052026/10/01 09:43:30 INFO Vacuumed table table=pending_objects29062026/10/01 09:43:30 INFO Vacuumed table table=multipart_uploads29072026/10/01 09:43:30 INFO Vacuumed table table=closures29082026/10/01 09:43:30 INFO Vacuumed table table=objects29092026/10/01 09:43:30 INFO Aborted multipart uploads count=0 kept=029102026/10/01 09:43:30 WARN Force mode enabled - objects will be deleted immediately without grace period29112026/10/01 09:43:30 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=029122026/10/01 09:43:30 INFO Vacuumed table table=pending_closures29132026/10/01 09:43:30 INFO Vacuumed table table=pending_objects29142026/10/01 09:43:30 INFO Vacuumed table table=multipart_uploads29152026/10/01 09:43:30 INFO Vacuumed table table=closures29162026/10/01 09:43:30 INFO Vacuumed table table=objects2917--- PASS: TestPushDedupSurvivesConcurrentGC (2.35s)29182026/10/01 09:43:30 OK 20241026095416_initial_model.sql (130.57ms)29192026/10/01 09:43:30 OK 20251210153512_drop_unused_gin_index.sql (12.85ms)29202026/10/01 09:43:30 OK 20251218171726_add_pins.sql (14.01ms)29212026/10/01 09:43:30 OK 20260628120000_add_object_size_and_stats.sql (36.21ms)29222026/10/01 09:43:30 OK 20260905000000_add_claims.sql (42.66ms)2923--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.99s)29242026/10/01 09:43:30 OK 20260920000000_drop_claims.sql (47.32ms)29252026-10-01 09:43:30.900 UTC [61767] ERROR: relation "goose_db_version" does not exist at character 3629262026-10-01 09:43:30.900 UTC [61767] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29272026/10/01 09:43:30 OK 20260923120000_add_pushes.sql (9.29ms)29282026/10/01 09:43:30 goose: successfully migrated database to version: 2026092312000029292026/10/01 09:43:30 OK 1_commit_pending_closure.sql (3.95ms)29302026/10/01 09:43:30 OK 2_object_stats_trigger.sql (734.83µs)29312026/10/01 09:43:30 OK 3_commit_push.sql (493.5µs)29322026/10/01 09:43:30 goose: up to current file version: 329332026-10-01 09:43:31.016 UTC [61768] ERROR: relation "goose_db_version" does not exist at character 3629342026-10-01 09:43:31.016 UTC [61768] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29352026/10/01 09:43:31 OK 20241026095416_initial_model.sql (90.2ms)29362026/10/01 09:43:31 OK 20251210153512_drop_unused_gin_index.sql (3.28ms)29372026/10/01 09:43:31 OK 20251218171726_add_pins.sql (21.12ms)29382026/10/01 09:43:31 OK 20260628120000_add_object_size_and_stats.sql (26.35ms)29392026/10/01 09:43:31 OK 20260905000000_add_claims.sql (43.56ms)29402026/10/01 09:43:31 OK 20260920000000_drop_claims.sql (26.13ms)29412026/10/01 09:43:31 OK 20241026095416_initial_model.sql (128.24ms)29422026/10/01 09:43:31 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.619296966s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29432026/10/01 09:43:31 INFO Aborted multipart uploads count=0 kept=029442026/10/01 09:43:31 WARN Force mode enabled - objects will be deleted immediately without grace period29452026/10/01 09:43:31 OK 20251210153512_drop_unused_gin_index.sql (12.23ms)29462026/10/01 09:43:31 OK 20260923120000_add_pushes.sql (15.2ms)29472026/10/01 09:43:31 goose: successfully migrated database to version: 2026092312000029482026/10/01 09:43:31 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=029492026/10/01 09:43:31 INFO Vacuumed table table=pending_closures29502026/10/01 09:43:31 INFO Vacuumed table table=pending_objects29512026/10/01 09:43:31 INFO Vacuumed table table=multipart_uploads29522026/10/01 09:43:31 INFO Vacuumed table table=closures29532026/10/01 09:43:31 OK 1_commit_pending_closure.sql (3.43ms)29542026/10/01 09:43:31 INFO Vacuumed table table=objects29552026/10/01 09:43:31 OK 2_object_stats_trigger.sql (668.58µs)2956--- PASS: TestGCMetrics (2.05s)29572026/10/01 09:43:31 OK 3_commit_push.sql (410.17µs)29582026/10/01 09:43:31 goose: up to current file version: 329592026/10/01 09:43:31 OK 20251218171726_add_pins.sql (22.13ms)29602026/10/01 09:43:31 OK 20260628120000_add_object_size_and_stats.sql (20.61ms)29612026/10/01 09:43:31 OK 20260905000000_add_claims.sql (18.86ms)29622026/10/01 09:43:31 OK 20260920000000_drop_claims.sql (22.25ms)29632026/10/01 09:43:31 OK 20260923120000_add_pushes.sql (2.71ms)29642026/10/01 09:43:31 goose: successfully migrated database to version: 2026092312000029652026/10/01 09:43:31 OK 1_commit_pending_closure.sql (3.71ms)29662026/10/01 09:43:31 OK 2_object_stats_trigger.sql (581.08µs)29672026/10/01 09:43:31 OK 3_commit_push.sql (352.96µs)29682026/10/01 09:43:31 goose: up to current file version: 329692026-10-01 09:43:31.295 UTC [61770] ERROR: relation "goose_db_version" does not exist at character 3629702026-10-01 09:43:31.295 UTC [61770] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29712026/10/01 09:43:31 OK 20241026095416_initial_model.sql (108.57ms)29722026-10-01 09:43:31.435 UTC [61771] ERROR: relation "goose_db_version" does not exist at character 3629732026-10-01 09:43:31.435 UTC [61771] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29742026/10/01 09:43:31 OK 20251210153512_drop_unused_gin_index.sql (15.55ms)29752026/10/01 09:43:31 OK 20251218171726_add_pins.sql (31.43ms)29762026/10/01 09:43:31 OK 20260628120000_add_object_size_and_stats.sql (8.5ms)29772026/10/01 09:43:31 OK 20260905000000_add_claims.sql (3.5ms)29782026/10/01 09:43:31 OK 20260920000000_drop_claims.sql (11.48ms)29792026/10/01 09:43:31 OK 20260923120000_add_pushes.sql (786.33µs)29802026/10/01 09:43:31 goose: successfully migrated database to version: 2026092312000029812026/10/01 09:43:31 OK 1_commit_pending_closure.sql (1.01ms)29822026/10/01 09:43:31 OK 20241026095416_initial_model.sql (25.37ms)29832026/10/01 09:43:31 OK 2_object_stats_trigger.sql (263.71µs)29842026/10/01 09:43:31 OK 3_commit_push.sql (184.25µs)29852026/10/01 09:43:31 goose: up to current file version: 329862026/10/01 09:43:31 OK 20251210153512_drop_unused_gin_index.sql (9.31ms)29872026/10/01 09:43:31 OK 20251218171726_add_pins.sql (5.44ms)29882026/10/01 09:43:31 OK 20260628120000_add_object_size_and_stats.sql (10.6ms)29892026/10/01 09:43:31 OK 20260905000000_add_claims.sql (10.14ms)29902026/10/01 09:43:31 OK 20260920000000_drop_claims.sql (6.75ms)29912026/10/01 09:43:31 OK 20260923120000_add_pushes.sql (4.81ms)29922026/10/01 09:43:31 goose: successfully migrated database to version: 2026092312000029932026/10/01 09:43:31 OK 1_commit_pending_closure.sql (1.04ms)29942026/10/01 09:43:31 OK 2_object_stats_trigger.sql (246.83µs)29952026/10/01 09:43:31 OK 3_commit_push.sql (208.71µs)29962026/10/01 09:43:31 goose: up to current file version: 329972026/10/01 09:43:31 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29982026/10/01 09:43:31 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29992026/10/01 09:43:31 INFO Received uploads request method=POST path=/api/pending_closures30002026/10/01 09:43:31 INFO Aborted multipart uploads count=0 kept=030012026/10/01 09:43:31 WARN Force mode enabled - objects will be deleted immediately without grace period30022026/10/01 09:43:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=030032026/10/01 09:43:31 INFO Vacuumed table table=pending_closures30042026/10/01 09:43:31 INFO Vacuumed table table=pending_objects30052026/10/01 09:43:31 INFO Vacuumed table table=multipart_uploads30062026/10/01 09:43:31 INFO Vacuumed table table=closures30072026/10/01 09:43:31 INFO Vacuumed table table=objects30082026/10/01 09:43:32 INFO Received uploads request method=POST path=/api/pending_closures30092026/10/01 09:43:32 INFO Aborted multipart uploads count=0 kept=030102026/10/01 09:43:32 WARN Force mode enabled - objects will be deleted immediately without grace period30112026/10/01 09:43:32 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=030122026/10/01 09:43:32 INFO Vacuumed table table=pending_closures30132026/10/01 09:43:32 INFO Vacuumed table table=pending_objects30142026/10/01 09:43:32 INFO Vacuumed table table=multipart_uploads30152026/10/01 09:43:32 INFO Vacuumed table table=closures30162026/10/01 09:43:32 INFO Vacuumed table table=objects3017--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3018 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.06s)3019 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.00s)30202026/10/01 09:43:32 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30212026/10/01 09:43:32 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.126435ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30222026/10/01 09:43:33 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=360.658139ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30232026/10/01 09:43:33 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=737.56823ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30242026/10/01 09:43:34 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.480190398s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30252026/10/01 09:43:35 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 [::1]:19999: connect: connection refused"30262026/10/01 09:43:35 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30272026/10/01 09:43:35 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=207.440455ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30282026/10/01 09:43:36 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.568688ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30292026/10/01 09:43:36 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=850.967516ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30302026/10/01 09:43:37 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.736690603s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30312026/10/01 09:43:39 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30322026/10/01 09:43:39 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.976283ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30332026/10/01 09:43:39 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=381.980006ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30342026/10/01 09:43:39 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=754.496552ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30352026/10/01 09:43:40 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.468413132s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3036--- PASS: TestClientErrorHandling (0.00s)3037 --- PASS: TestClientErrorHandling/InvalidStorePath (2.07s)3038 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.21s)3039 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.39s)3040PASS3041{"timestamp":"2026-10-01T09:43:41.971539Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51215","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}30422026-10-01 09:43:42.199 UTC [61049] LOG: received smart shutdown request30432026-10-01 09:43:42.200 UTC [61049] LOG: background worker "logical replication launcher" (PID 61059) exited with exit code 130442026-10-01 09:43:42.206 UTC [61054] LOG: shutting down30452026-10-01 09:43:42.206 UTC [61054] LOG: checkpoint starting: shutdown immediate30462026-10-01 09:43:43.403 UTC [61054] LOG: checkpoint complete: wrote 12737 buffers (77.7%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.680 s, sync=0.478 s, total=1.197 s; sync files=27975, longest=0.001 s, average=0.001 s; distance=393932 kB, estimate=393932 kB; lsn=0/1983FF80, redo lsn=0/1983FF8030472026-10-01 09:43:43.409 UTC [61049] LOG: database system is shut down3048Running OIDC tests...3049=== RUN TestAudienceForIssuer3050=== PAUSE TestAudienceForIssuer3051=== RUN TestGlobMatch3052=== PAUSE TestGlobMatch3053=== RUN TestValidateToken_ValidToken3054=== PAUSE TestValidateToken_ValidToken3055=== RUN TestValidateToken_WrongAudience3056=== PAUSE TestValidateToken_WrongAudience3057=== RUN TestValidateToken_Expired3058=== PAUSE TestValidateToken_Expired3059=== RUN TestValidateToken_BoundClaimsMismatch3060=== PAUSE TestValidateToken_BoundClaimsMismatch3061=== RUN TestValidateToken_BoundSubjectMismatch3062=== PAUSE TestValidateToken_BoundSubjectMismatch3063=== RUN TestValidateToken_MultipleProviders3064=== PAUSE TestValidateToken_MultipleProviders3065=== RUN TestValidateToken_NoMatchingProvider3066=== PAUSE TestValidateToken_NoMatchingProvider3067=== RUN TestValidateToken_KubernetesServiceAccount3068=== PAUSE TestValidateToken_KubernetesServiceAccount3069=== RUN TestNewValidator_KubernetesRequiresCA3070=== PAUSE TestNewValidator_KubernetesRequiresCA3071=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3072=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3073=== RUN TestPins_ReservedForMatchingRule3074=== PAUSE TestPins_ReservedForMatchingRule3075=== RUN TestPins_TopLevelShorthand3076=== PAUSE TestPins_TopLevelShorthand3077=== RUN TestPins_ConfigValidation3078=== PAUSE TestPins_ConfigValidation3079=== RUN TestScopes_LegacyProviderDefaultsToWrite3080=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3081=== RUN TestScopes_Rules3082=== PAUSE TestScopes_Rules3083=== RUN TestScopes_ConfigValidation3084=== PAUSE TestScopes_ConfigValidation3085=== CONT TestAudienceForIssuer3086--- PASS: TestAudienceForIssuer (0.00s)3087=== CONT TestValidateToken_NoMatchingProvider3088=== CONT TestPins_ConfigValidation3089=== CONT TestNewValidator_KubernetesRequiresCA3090=== CONT TestPins_ReservedForMatchingRule3091=== CONT TestScopes_Rules3092=== CONT TestScopes_LegacyProviderDefaultsToWrite3093=== CONT TestPins_TopLevelShorthand3094=== CONT TestScopes_ConfigValidation3095=== CONT TestValidateToken_KubernetesServiceAccount3096=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3097--- PASS: TestPins_ConfigValidation (0.01s)3098=== CONT TestValidateToken_MultipleProviders3099--- PASS: TestScopes_ConfigValidation (0.00s)3100=== CONT TestValidateToken_Expired31012026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51829/oidc3102--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.02s)3103=== CONT TestValidateToken_BoundSubjectMismatch31042026/10/01 09:43:44 http: TLS handshake error from 127.0.0.1:51832: read tcp 127.0.0.1:51831->127.0.0.1:51832: use of closed network connection3105--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)3106=== CONT TestValidateToken_BoundClaimsMismatch31072026/10/01 09:43:44 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5183431082026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51836/oidc3109--- PASS: TestPins_ReservedForMatchingRule (0.06s)3110=== CONT TestValidateToken_ValidToken3111=== CONT TestValidateToken_WrongAudience3112--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)31132026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51838/oidc31142026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51840/oidc3115--- PASS: TestPins_TopLevelShorthand (0.06s)3116=== CONT TestGlobMatch3117=== RUN TestGlobMatch/foo_foo3118=== PAUSE TestGlobMatch/foo_foo3119=== RUN TestGlobMatch/foo_bar3120=== PAUSE TestGlobMatch/foo_bar3121=== RUN TestGlobMatch/*_3122=== PAUSE TestGlobMatch/*_3123=== RUN TestGlobMatch/*_anything3124=== PAUSE TestGlobMatch/*_anything3125=== RUN TestGlobMatch/foo*_foo3126=== PAUSE TestGlobMatch/foo*_foo3127=== RUN TestGlobMatch/foo*_foobar3128=== PAUSE TestGlobMatch/foo*_foobar3129=== RUN TestGlobMatch/foo*_bar3130=== PAUSE TestGlobMatch/foo*_bar3131=== RUN TestGlobMatch/*bar_bar3132=== PAUSE TestGlobMatch/*bar_bar3133=== RUN TestGlobMatch/*bar_foobar3134=== PAUSE TestGlobMatch/*bar_foobar3135=== RUN TestGlobMatch/*bar_foo3136=== PAUSE TestGlobMatch/*bar_foo3137=== RUN TestGlobMatch/foo*bar_foobar3138=== PAUSE TestGlobMatch/foo*bar_foobar3139=== RUN TestGlobMatch/foo*bar_foo123bar3140=== PAUSE TestGlobMatch/foo*bar_foo123bar3141=== RUN TestGlobMatch/foo*bar_foobarbaz3142=== PAUSE TestGlobMatch/foo*bar_foobarbaz3143=== RUN TestGlobMatch/*/*_foo/bar3144=== PAUSE TestGlobMatch/*/*_foo/bar3145=== RUN TestGlobMatch/*/*_foo3146=== PAUSE TestGlobMatch/*/*_foo3147=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3148=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3149=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03150=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03151=== RUN TestGlobMatch/refs/*/main_refs/heads/main3152=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3153=== RUN TestGlobMatch/fo?_foo3154=== PAUSE TestGlobMatch/fo?_foo3155=== RUN TestGlobMatch/fo?_fo3156=== PAUSE TestGlobMatch/fo?_fo3157=== RUN TestGlobMatch/fo?_fooo3158=== PAUSE TestGlobMatch/fo?_fooo3159=== RUN TestGlobMatch/?oo_foo3160=== PAUSE TestGlobMatch/?oo_foo3161=== RUN TestGlobMatch/?oo_boo3162=== PAUSE TestGlobMatch/?oo_boo3163=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3164=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3165=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3166=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3167=== CONT TestGlobMatch/foo_foo3168=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3169=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3170=== CONT TestGlobMatch/?oo_boo3171=== CONT TestGlobMatch/?oo_foo3172=== CONT TestGlobMatch/fo?_fooo3173=== CONT TestGlobMatch/fo?_fo3174=== CONT TestGlobMatch/fo?_foo3175=== CONT TestGlobMatch/refs/*/main_refs/heads/main3176=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03177=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3178=== CONT TestGlobMatch/*/*_foo3179=== CONT TestGlobMatch/*/*_foo/bar3180=== CONT TestGlobMatch/foo*bar_foobarbaz3181=== CONT TestGlobMatch/foo*bar_foo123bar3182=== CONT TestGlobMatch/foo*bar_foobar3183=== CONT TestGlobMatch/*bar_foo3184=== CONT TestGlobMatch/*bar_foobar3185=== CONT TestGlobMatch/*bar_bar3186=== CONT TestGlobMatch/foo*_bar3187=== CONT TestGlobMatch/foo*_foobar3188=== CONT TestGlobMatch/foo*_foo3189=== CONT TestGlobMatch/*_anything3190=== CONT TestGlobMatch/*_3191=== CONT TestGlobMatch/foo_bar3192--- PASS: TestGlobMatch (0.00s)3193 --- PASS: TestGlobMatch/foo_foo (0.00s)3194 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3195 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3196 --- PASS: TestGlobMatch/?oo_boo (0.00s)3197 --- PASS: TestGlobMatch/?oo_foo (0.00s)3198 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3199 --- PASS: TestGlobMatch/fo?_fo (0.00s)3200 --- PASS: TestGlobMatch/fo?_foo (0.00s)3201 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3202 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3203 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3204 --- PASS: TestGlobMatch/*/*_foo (0.00s)3205 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3206 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3207 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3208 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3209 --- PASS: TestGlobMatch/*bar_foo (0.00s)3210 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3211 --- PASS: TestGlobMatch/*bar_bar (0.00s)3212 --- PASS: TestGlobMatch/foo*_bar (0.00s)3213 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3214 --- PASS: TestGlobMatch/foo*_foo (0.00s)3215 --- PASS: TestGlobMatch/*_anything (0.00s)3216 --- PASS: TestGlobMatch/*_ (0.00s)3217 --- PASS: TestGlobMatch/foo_bar (0.00s)3218--- PASS: TestValidateToken_BoundClaimsMismatch (0.02s)32192026/10/01 09:43:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233220--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)32212026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51845/oidc32222026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51847/oidc3223--- PASS: TestScopes_Rules (0.09s)3224--- PASS: TestValidateToken_ValidToken (0.04s)32252026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51849/oidc3226--- PASS: TestValidateToken_WrongAudience (0.04s)32272026/10/01 09:43:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51844/oidc32282026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51853/oidc3229--- PASS: TestValidateToken_NoMatchingProvider (0.11s)3230--- PASS: TestValidateToken_Expired (0.10s)32312026/10/01 09:43:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51855/oidc3232--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)32332026/10/01 09:43:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51833/oidc32342026/10/01 09:43:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:51857/oidc3235--- PASS: TestValidateToken_MultipleProviders (0.13s)3236PASS3237Running hook tests...3238=== RUN TestSendPathsEmpty3239=== PAUSE TestSendPathsEmpty3240=== RUN TestQueueEnqueueAndFetch3241=== PAUSE TestQueueEnqueueAndFetch3242=== RUN TestQueueDeduplication3243=== PAUSE TestQueueDeduplication3244=== RUN TestQueueRemove3245=== PAUSE TestQueueRemove3246=== RUN TestQueueFetchBatchLimit3247=== PAUSE TestQueueFetchBatchLimit3248=== RUN TestQueueRetryMovesToBack3249=== PAUSE TestQueueRetryMovesToBack3250=== RUN TestQueueFetchRemoveLifecycle3251=== PAUSE TestQueueFetchRemoveLifecycle3252=== RUN TestQueueConcurrentWriters3253=== PAUSE TestQueueConcurrentWriters3254=== RUN TestQueueRemoveLargeClosure3255=== PAUSE TestQueueRemoveLargeClosure3256=== RUN TestServerClientIntegration3257=== PAUSE TestServerClientIntegration3258=== RUN TestServerQueueError3259=== PAUSE TestServerQueueError3260=== RUN TestGetListenerSocketActivation3261 server_test.go:210: === RUN TestGetListenerSocketActivation3262 --- PASS: TestGetListenerSocketActivation (0.00s)3263 PASS3264 3265--- PASS: TestGetListenerSocketActivation (0.01s)3266=== RUN TestDrainIsolatesPoisonPath3267=== PAUSE TestDrainIsolatesPoisonPath3268=== RUN TestRunNotBlockedByPoisonHead3269=== PAUSE TestRunNotBlockedByPoisonHead3270=== RUN TestDrainGivesUpWhenServerDown3271=== PAUSE TestDrainGivesUpWhenServerDown3272=== RUN TestFailedPathPrunedByLaterClosure3273=== PAUSE TestFailedPathPrunedByLaterClosure3274=== RUN TestWorkerUploadsAndRemoves3275=== PAUSE TestWorkerUploadsAndRemoves3276=== RUN TestWorkerSkipsGCdPaths3277=== PAUSE TestWorkerSkipsGCdPaths3278=== RUN TestWorkerPrunesClosureDeps3279=== PAUSE TestWorkerPrunesClosureDeps3280=== RUN TestDrainTimeout3281=== PAUSE TestDrainTimeout3282=== CONT TestSendPathsEmpty3283=== CONT TestServerQueueError3284--- PASS: TestSendPathsEmpty (0.00s)3285=== CONT TestServerClientIntegration3286=== CONT TestWorkerUploadsAndRemoves3287=== CONT TestWorkerPrunesClosureDeps3288=== CONT TestDrainTimeout3289=== CONT TestQueueRetryMovesToBack3290=== CONT TestQueueRemoveLargeClosure3291=== CONT TestQueueConcurrentWriters3292=== CONT TestQueueFetchRemoveLifecycle3293=== CONT TestDrainGivesUpWhenServerDown32942026/10/01 09:43:45 ERROR Failed to queue paths error="permission denied" count=13295--- PASS: TestServerQueueError (0.00s)3296=== CONT TestFailedPathPrunedByLaterClosure3297--- PASS: TestServerClientIntegration (0.00s)3298=== CONT TestWorkerSkipsGCdPaths32992026/10/01 09:43:45 INFO Upload queue status pending=233002026/10/01 09:43:45 INFO Uploading batch count=233012026/10/01 09:43:45 INFO Uploading batch count=133022026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=133032026/10/01 09:43:45 INFO Uploading batch count=233042026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=233052026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainGivesUpWhenServerDown3806611926/002/a33062026/10/01 09:43:45 INFO Upload queue status pending=233072026/10/01 09:43:45 INFO Uploading batch count=233082026/10/01 09:43:45 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-60884-3569518374/TestWorkerSkipsGCdPaths200579043/002/nonexistent3309--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3310=== CONT TestRunNotBlockedByPoisonHead33112026/10/01 09:43:45 INFO Upload queue status pending=233122026/10/01 09:43:45 INFO Uploading batch count=13313--- PASS: TestQueueRetryMovesToBack (0.01s)3314=== CONT TestQueueRemove33152026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainGivesUpWhenServerDown3806611926/002/b33162026/10/01 09:43:45 INFO Uploading batch count=133172026/10/01 09:43:45 INFO Uploading batch count=133182026/10/01 09:43:45 INFO Uploading batch count=233192026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=233202026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainGivesUpWhenServerDown3806611926/002/c33212026/10/01 09:43:45 INFO Uploading batch count=133222026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainGivesUpWhenServerDown3806611926/002/d33232026/10/01 09:43:45 INFO Uploading batch count=233242026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=233252026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainGivesUpWhenServerDown3806611926/002/e33262026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainGivesUpWhenServerDown3806611926/002/f33272026/10/01 09:43:45 ERROR Drain finished with paths left in queue remaining=103328--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3329=== CONT TestDrainIsolatesPoisonPath33302026/10/01 09:43:45 INFO Upload queue status pending=333312026/10/01 09:43:45 INFO Uploading batch count=133322026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=13333--- PASS: TestQueueRemove (0.00s)3334=== CONT TestQueueFetchBatchLimit33352026/10/01 09:43:45 INFO Uploading batch count=433362026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=43337--- PASS: TestDrainGivesUpWhenServerDown (0.01s)3338=== CONT TestQueueDeduplication33392026/10/01 09:43:45 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60884-3569518374/TestDrainIsolatesPoisonPath1992903658/002/bbb33402026/10/01 09:43:45 INFO Uploading batch count=133412026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=133422026/10/01 09:43:45 INFO Uploading batch count=133432026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=133442026/10/01 09:43:45 INFO Uploading batch count=133452026/10/01 09:43:45 ERROR Upload failed error="upload failed" count=133462026/10/01 09:43:45 ERROR Drain finished with paths left in queue remaining=13347--- PASS: TestQueueFetchBatchLimit (0.00s)3348=== CONT TestQueueEnqueueAndFetch3349--- PASS: TestDrainIsolatesPoisonPath (0.00s)3350--- PASS: TestQueueDeduplication (0.00s)3351--- PASS: TestQueueEnqueueAndFetch (0.00s)3352--- PASS: TestWorkerSkipsGCdPaths (0.03s)3353--- PASS: TestWorkerUploadsAndRemoves (0.03s)3354--- PASS: TestWorkerPrunesClosureDeps (0.03s)3355--- PASS: TestQueueRemoveLargeClosure (0.05s)3356--- PASS: TestQueueConcurrentWriters (0.15s)33572026/10/01 09:43:45 ERROR Upload failed error="context deadline exceeded" count=233582026/10/01 09:43:45 ERROR Drain finished with paths left in queue remaining=43359--- PASS: TestDrainTimeout (0.21s)33602026/10/01 09:43:46 INFO Uploading batch count=133612026/10/01 09:43:46 INFO Uploading batch count=133622026/10/01 09:43:46 INFO Uploading batch count=133632026/10/01 09:43:46 ERROR Upload failed error="upload failed" count=133642026/10/01 09:43:46 INFO Uploading batch count=133652026/10/01 09:43:46 ERROR Upload failed error="upload failed" count=133662026/10/01 09:43:46 INFO Uploading batch count=133672026/10/01 09:43:46 ERROR Upload failed error="upload failed" count=133682026/10/01 09:43:46 INFO Uploading batch count=133692026/10/01 09:43:46 ERROR Upload failed error="upload failed" count=133702026/10/01 09:43:46 ERROR Drain finished with paths left in queue remaining=13371--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3372PASS