niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #318
· 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.20s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.03s)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=== CONT TestScriptTokenCachesUntilRefresh98--- PASS: TestShellSplit (0.00s)99=== CONT TestSetClientTLSDoesNotMutateDefaultTransport100=== CONT TestSetClientTLS101=== CONT TestClientSignaturesByStorePath102--- PASS: TestClientSignaturesByStorePath (0.00s)103=== CONT TestStreamPushBatchesUnderLoad104=== CONT TestStreamPushReportsSignatures105=== CONT TestStreamPushRequestLine106=== CONT TestStreamPushGivesUpOnDeadServer107=== CONT TestStreamPushIsolatesFailures1082026/10/01 09:47:35 ERROR Upload failed error="connection refused" count=201092026/10/01 09:47:35 ERROR Server seems unavailable, giving up on batch untried=171102026/10/01 09:47:35 ERROR Upload failed error="bad path" count=3111--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)112=== CONT TestStreamPushReportsEveryPath1132026/10/01 09:47:35 ERROR Upload failed error=boom count=1114--- PASS: TestStreamPushIsolatesFailures (0.00s)115=== CONT TestShellSplitErrors1162026/10/01 09:47:35 ERROR Upload failed error=boom count=1117--- PASS: TestShellSplitErrors (0.00s)118=== CONT TestFileTokenMissing119--- PASS: TestStreamPushReportsSignatures (0.00s)120=== CONT TestScriptTokenNoExpiryRerunsEveryCall121--- PASS: TestStreamPushReportsEveryPath (0.00s)122=== CONT TestFileTokenEmpty123--- PASS: TestDoServerRequestAttachesToken (0.00s)124=== CONT TestEncodeNixBase32WithRealHash125--- PASS: TestEncodeNixBase32WithRealHash (0.00s)126=== CONT TestDoWithRetry_BodyReplayedViaGetBody1272026/10/01 09:47:35 WARN Rate limiter enabled after throttle name=server-test rate=51282026/10/01 09:47:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:521401292026/10/01 09:47:35 WARN Rate limiter backed off name=server-test rate=51302026/10/01 09:47:35 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52140131--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)132=== CONT TestResolveStorePath133--- PASS: TestStreamPushRequestLine (0.01s)134=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1352026/10/01 09:47:35 WARN Rate limiter enabled after throttle name=server-test rate=5136--- PASS: TestFileTokenMissing (0.02s)137=== CONT TestRateLimiterFeedback138=== RUN TestRateLimiterFeedback/429_enables_limiter139=== PAUSE TestRateLimiterFeedback/429_enables_limiter140=== RUN TestRateLimiterFeedback/503_enables_limiter141=== PAUSE TestRateLimiterFeedback/503_enables_limiter142=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter143=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter144=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter145=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter146=== CONT TestPathInfoCACompatibility147=== RUN TestPathInfoCACompatibility/null_ca_field148=== PAUSE TestPathInfoCACompatibility/null_ca_field149=== RUN TestPathInfoCACompatibility/old_string_format_-_text150=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text151=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive152=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive153=== RUN TestPathInfoCACompatibility/new_structured_format_-_text154=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text155=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method156=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method157=== CONT TestParsePathInfoJSONMultiplePaths158=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths160=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths161=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths162=== CONT TestParsePathInfoJSON163=== RUN TestParsePathInfoJSON/Nix_format164=== PAUSE TestParsePathInfoJSON/Nix_format165=== RUN TestParsePathInfoJSON/Lix_format166=== PAUSE TestParsePathInfoJSON/Lix_format167=== RUN TestParsePathInfoJSON/empty_input168=== PAUSE TestParsePathInfoJSON/empty_input169=== RUN TestParsePathInfoJSON/whitespace_only170=== PAUSE TestParsePathInfoJSON/whitespace_only171=== RUN TestParsePathInfoJSON/invalid_JSON172=== PAUSE TestParsePathInfoJSON/invalid_JSON173=== CONT TestPathInfoHashCompatibility174=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)175=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)176=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon177=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon178=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI179=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI180=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512181=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512182=== CONT TestGetStorePathHash183=== RUN TestGetStorePathHash/valid_store_path184=== PAUSE TestGetStorePathHash/valid_store_path185=== RUN TestGetStorePathHash/basename_without_hyphen_should_error186=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error187=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error188=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error189=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error190=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error191=== CONT TestConvertHashToNix32192=== RUN TestConvertHashToNix32/SRI_format_to_Nix32193=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32194=== RUN TestConvertHashToNix32/already_Nix32_format195=== PAUSE TestConvertHashToNix32/already_Nix32_format196=== RUN TestConvertHashToNix32/invalid_format197=== PAUSE TestConvertHashToNix32/invalid_format198=== CONT TestUploadMultipart_SupersededByPeer199=== RUN TestUploadMultipart_SupersededByPeer/exists200=== PAUSE TestUploadMultipart_SupersededByPeer/exists201=== RUN TestUploadMultipart_SupersededByPeer/missing202=== PAUSE TestUploadMultipart_SupersededByPeer/missing203=== CONT TestEncodeNixBase32204=== RUN TestEncodeNixBase32/test_string_hash205=== PAUSE TestEncodeNixBase32/test_string_hash206=== RUN TestEncodeNixBase32/empty_input207=== PAUSE TestEncodeNixBase32/empty_input208=== CONT TestDumpPathWriterError209=== RUN TestSetClientTLSErrors/missing_cert_file210=== PAUSE TestSetClientTLSErrors/missing_cert_file211=== RUN TestSetClientTLSErrors/missing_key_file212=== PAUSE TestSetClientTLSErrors/missing_key_file213=== RUN TestSetClientTLSErrors/missing_ca_file214=== PAUSE TestSetClientTLSErrors/missing_ca_file215=== RUN TestSetClientTLSErrors/invalid_ca_file216=== PAUSE TestSetClientTLSErrors/invalid_ca_file217=== CONT TestDumpPathSingleFile218--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)219=== CONT TestDumpPathMatchesNix220--- PASS: TestResolveStorePath (0.03s)221=== CONT TestPartSizeForNAR222=== RUN TestPartSizeForNAR/zero_stays_at_minimum223=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum224--- PASS: TestFileTokenEmpty (0.03s)225=== CONT TestFilterOversizedClosures226=== RUN TestPartSizeForNAR/small_stays_at_minimum227=== PAUSE TestPartSizeForNAR/small_stays_at_minimum228=== RUN TestFilterOversizedClosures/no_limit_keeps_everything229=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything230=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped231=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped232=== RUN TestFilterOversizedClosures/all_closures_skipped233=== PAUSE TestFilterOversizedClosures/all_closures_skipped234=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum235=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum236=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts237=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts238=== RUN TestPartSizeForNAR/1_TiB239=== PAUSE TestPartSizeForNAR/1_TiB240=== RUN TestPartSizeForNAR/5_TiB_S3_max_object241=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object242=== RUN TestPartSizeForNAR/capped_at_5_GiB243=== PAUSE TestPartSizeForNAR/capped_at_5_GiB244=== CONT TestUploadMultipart_PartsInParallel245=== RUN TestSetClientTLS/rejects_connection_without_client_cert246=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert247=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA248=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA249=== RUN TestSetClientTLS/preserves_debug_logging_transport250=== PAUSE TestSetClientTLS/preserves_debug_logging_transport251=== CONT TestScriptTokenEmptyCommand252--- PASS: TestScriptTokenEmptyCommand (0.00s)253=== CONT TestFileTokenReadsAndCaches254=== CONT TestScriptTokenScriptFails255--- PASS: TestScriptTokenScriptFails (0.01s)256=== CONT TestScriptTokenBadJSON257--- PASS: TestFileTokenReadsAndCaches (0.02s)258=== CONT TestScriptTokenEmptyToken259--- PASS: TestScriptTokenBadJSON (0.05s)260=== CONT TestStaticToken261--- PASS: TestStaticToken (0.00s)262=== CONT TestCaseHackSuffix263--- PASS: TestScriptTokenEmptyToken (0.04s)264=== CONT TestRegisterUploadedObjectReusesConnections265--- PASS: TestStreamPushBatchesUnderLoad (0.10s)266=== CONT TestRateLimiterFeedback/429_enables_limiter267--- PASS: TestScriptTokenCachesUntilRefresh (0.10s)268=== CONT TestRateLimiterFeedback/503_enables_limiter2692026/10/01 09:47:36 WARN Rate limiter enabled after throttle name=server-test rate=52702026/10/01 09:47:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:522182712026/10/01 09:47:36 WARN Rate limiter backed off name=server-test rate=5272=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2732026/10/01 09:47:36 WARN Rate limiter enabled after throttle name=server-test rate=52742026/10/01 09:47:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:522202752026/10/01 09:47:36 WARN Rate limiter backed off name=server-test rate=5276=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter277=== CONT TestPathInfoCACompatibility/null_ca_field278=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths279=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method280=== CONT TestPathInfoCACompatibility/new_structured_format_-_text281=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive282=== CONT TestPathInfoCACompatibility/old_string_format_-_text283--- PASS: TestPathInfoCACompatibility (0.00s)284 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)285 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)286 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)287 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)288 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)289=== CONT TestParsePathInfoJSON/Nix_format290=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths291--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)292 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)293 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)294=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)295=== CONT TestParsePathInfoJSON/invalid_JSON296=== CONT TestParsePathInfoJSON/whitespace_only297=== CONT TestParsePathInfoJSON/empty_input298=== CONT TestParsePathInfoJSON/Lix_format299--- PASS: TestParsePathInfoJSON (0.00s)300 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)301 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)302 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)303 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)304 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)305=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI306=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512307=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon308--- PASS: TestPathInfoHashCompatibility (0.00s)309 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)310 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)311 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)312 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)313=== CONT TestGetStorePathHash/valid_store_path314=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error315=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error316=== CONT TestGetStorePathHash/basename_without_hyphen_should_error317--- PASS: TestGetStorePathHash (0.00s)318 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)319 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)320 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)321 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)322=== CONT TestConvertHashToNix32/SRI_format_to_Nix32323=== CONT TestConvertHashToNix32/invalid_format324=== CONT TestConvertHashToNix32/already_Nix32_format325--- PASS: TestConvertHashToNix32 (0.00s)326 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)327 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)328 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)329=== CONT TestUploadMultipart_SupersededByPeer/exists330--- PASS: TestRateLimiterFeedback (0.00s)331 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)332 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)333 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)334 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)335=== CONT TestUploadMultipart_SupersededByPeer/missing336=== CONT TestEncodeNixBase32/test_string_hash337=== CONT TestEncodeNixBase32/empty_input338--- PASS: TestEncodeNixBase32 (0.00s)339 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)340 --- PASS: TestEncodeNixBase32/empty_input (0.00s)341=== CONT TestSetClientTLSErrors/missing_cert_file342=== CONT TestSetClientTLSErrors/missing_ca_file343=== CONT TestSetClientTLSErrors/invalid_ca_file344--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)345 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)346 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)347=== CONT TestFilterOversizedClosures/no_limit_keeps_everything348=== CONT TestPartSizeForNAR/zero_stays_at_minimum349=== CONT TestPartSizeForNAR/5_TiB_S3_max_object350=== CONT TestFilterOversizedClosures/all_closures_skipped3512026/10/01 09:47:36 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=50352=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3532026/10/01 09:47:36 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=2000354--- PASS: TestFilterOversizedClosures (0.00s)355 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)356 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)357 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)358=== CONT TestPartSizeForNAR/capped_at_5_GiB359=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts360=== CONT TestPartSizeForNAR/1_TiB361=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum362=== CONT TestPartSizeForNAR/small_stays_at_minimum363--- PASS: TestPartSizeForNAR (0.00s)364 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)365 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)366 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)367 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)368 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)369 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)371=== CONT TestSetClientTLSErrors/missing_key_file372=== CONT TestSetClientTLS/rejects_connection_without_client_cert373=== CONT TestSetClientTLS/preserves_debug_logging_transport374=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA375--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)3762026/10/01 09:47:36 http: TLS handshake error from 127.0.0.1:52230: remote error: tls: bad certificate377--- PASS: TestSetClientTLSErrors (0.05s)378 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)380 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)381 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)382--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.14s)383--- PASS: TestSetClientTLS (0.06s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)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.26s)388--- PASS: TestCaseHackSuffix (0.36s)389--- PASS: TestDumpPathWriterError (0.62s)390--- PASS: TestUploadMultipart_PartsInParallel (0.62s)391--- PASS: TestDumpPathMatchesNix (0.92s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld11".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-77474-458540005/postgres1825500717/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-77474-458540005/postgres1825500717/data -l logfile start421422/nix/var/nix/builds/nix-77474-458540005/postgres1825500717:5432 - no response4232026-10-01 09:47:43.757 UTC [78141] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:47:43.768 UTC [78141] LOG: listening on Unix socket "/nix/var/nix/builds/nix-77474-458540005/postgres1825500717/.s.PGSQL.5432"4252026-10-01 09:47:43.785 UTC [78153] LOG: database system was shut down at 2026-10-01 09:47:43 UTC4262026-10-01 09:47:43.799 UTC [78141] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-77474-458540005/postgres1825500717:5432 - accepting connections428{"timestamp":"2026-10-01T09:47:44.062001Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"76ee1c18-3924-49f2-826a-e26a74f53aa5","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)"}429{"timestamp":"2026-10-01T09:47:44.164079Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9fda953c-b320-465e-bea4-56d823d7f8d0","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(9)"}430{"timestamp":"2026-10-01T09:47:44.267612Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3d0818c7-8a96-40fa-8b61-7ce51116e29c","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(10)"}431{"timestamp":"2026-10-01T09:47:44.368552Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0ea433a5-636e-42d7-89f5-7ba19d47e606","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(7)"}432{"timestamp":"2026-10-01T09:47:44.470745Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3060ba59-ed0d-4bd3-bc88-09173d95cb4b","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)"}433=== RUN TestService_AuthMiddleware434=== PAUSE TestService_AuthMiddleware435=== RUN TestService_AuthMiddleware_MTLSProxyHeader436=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader437=== RUN TestService_AuthMiddleware_MTLSBoundSubjects438=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects439=== RUN TestService_ReadAuthMiddleware440=== PAUSE TestService_ReadAuthMiddleware441=== RUN TestService_AuthMiddleware_OIDC442=== PAUSE TestService_AuthMiddleware_OIDC443=== RUN TestService_RequireScope_OIDC444=== PAUSE TestService_RequireScope_OIDC445=== RUN TestService_ReadScope_PublicByDefault446=== PAUSE TestService_ReadScope_PublicByDefault447=== RUN TestCacheConfigHandler448=== PAUSE TestCacheConfigHandler449=== RUN TestCacheStatsHandler450=== PAUSE TestCacheStatsHandler451=== RUN TestClientCADerivations452=== PAUSE TestClientCADerivations453=== RUN TestClientErrorHandling454=== PAUSE TestClientErrorHandling455=== RUN TestClientIntegration456=== PAUSE TestClientIntegration457=== RUN TestClientMultipleUploads458=== PAUSE TestClientMultipleUploads459=== RUN TestClientWithDependencies460=== PAUSE TestClientWithDependencies461=== RUN TestClientSharedPathCommittedMidPush462=== PAUSE TestClientSharedPathCommittedMidPush463=== RUN TestPinProtectsFromGC464=== PAUSE TestPinProtectsFromGC465=== RUN TestClientPushesUseOnePush466=== PAUSE TestClientPushesUseOnePush467=== RUN TestClientFallsBackToClosures468=== PAUSE TestClientFallsBackToClosures469=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock470=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock471=== RUN TestResolveDBConnectionString472=== PAUSE TestResolveDBConnectionString473=== RUN TestLeadElectsOneAndHandsOver474=== PAUSE TestLeadElectsOneAndHandsOver475=== RUN TestLeadIncumbentWinsAfterRestart4762026-10-01 09:47:47.394 UTC [78373] ERROR: relation "goose_db_version" does not exist at character 364772026-10-01 09:47:47.394 UTC [78373] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4782026/10/01 09:47:47 OK 20241026095416_initial_model.sql (151.06ms)4792026/10/01 09:47:47 OK 20251210153512_drop_unused_gin_index.sql (22.6ms)4802026/10/01 09:47:47 OK 20251218171726_add_pins.sql (21.45ms)4812026/10/01 09:47:47 OK 20260628120000_add_object_size_and_stats.sql (13.8ms)4822026/10/01 09:47:47 OK 20260905000000_add_claims.sql (6.4ms)4832026/10/01 09:47:47 OK 20260920000000_drop_claims.sql (32.26ms)4842026/10/01 09:47:47 OK 20260923120000_add_pushes.sql (16.11ms)4852026/10/01 09:47:47 goose: successfully migrated database to version: 202609231200004862026/10/01 09:47:47 OK 1_commit_pending_closure.sql (1.94ms)4872026/10/01 09:47:47 OK 2_object_stats_trigger.sql (535.08µs)4882026/10/01 09:47:47 OK 3_commit_push.sql (424.17µs)4892026/10/01 09:47:47 goose: up to current file version: 34902026/10/01 09:47:48 INFO lead: acquired remote=192.0.2.1:12344912026/10/01 09:47:48 INFO lead: released remote=192.0.2.1:12344922026/10/01 09:47:48 INFO lead: acquired remote=192.0.2.1:12344932026/10/01 09:47:48 INFO lead: released remote=192.0.2.1:1234494--- PASS: TestLeadIncumbentWinsAfterRestart (4.12s)495=== RUN TestLeadEndsOnShutdown496=== PAUSE TestLeadEndsOnShutdown497=== RUN TestGCAdvisoryLockBlocksConcurrentRun4982026-10-01 09:47:50.025 UTC [78446] ERROR: relation "goose_db_version" does not exist at character 364992026-10-01 09:47:50.025 UTC [78446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5002026/10/01 09:47:50 OK 20241026095416_initial_model.sql (82.65ms)5012026/10/01 09:47:50 OK 20251210153512_drop_unused_gin_index.sql (20.16ms)5022026/10/01 09:47:50 OK 20251218171726_add_pins.sql (38.04ms)5032026/10/01 09:47:50 OK 20260628120000_add_object_size_and_stats.sql (14.16ms)5042026/10/01 09:47:50 OK 20260905000000_add_claims.sql (49.37ms)5052026/10/01 09:47:50 OK 20260920000000_drop_claims.sql (43.2ms)5062026/10/01 09:47:50 OK 20260923120000_add_pushes.sql (12.85ms)5072026/10/01 09:47:50 goose: successfully migrated database to version: 202609231200005082026/10/01 09:47:50 OK 1_commit_pending_closure.sql (1.54ms)5092026/10/01 09:47:50 OK 2_object_stats_trigger.sql (270.33µs)5102026/10/01 09:47:50 OK 3_commit_push.sql (211.5µs)5112026/10/01 09:47:50 goose: up to current file version: 3512--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.97s)513=== RUN TestGCBugBareHashReferences514=== PAUSE TestGCBugBareHashReferences515=== RUN TestGCMetrics516=== PAUSE TestGCMetrics517=== RUN TestPushDedupSurvivesConcurrentGC518=== PAUSE TestPushDedupSurvivesConcurrentGC519=== RUN TestDeduplicatedObjectsRecordedAsPending520=== PAUSE TestDeduplicatedObjectsRecordedAsPending521=== RUN TestGCSweepSkipsPendingObjects522=== PAUSE TestGCSweepSkipsPendingObjects523=== RUN TestTombstonedObjectOfferedWithoutWaiting524=== PAUSE TestTombstonedObjectOfferedWithoutWaiting525=== RUN TestGCSweepDeliversEachKeyOnce526=== PAUSE TestGCSweepDeliversEachKeyOnce527=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection528=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection529=== RUN TestForceGCDuringPushOffersSweptObject530=== PAUSE TestForceGCDuringPushOffersSweptObject531=== RUN TestFailedS3DeleteKeepsTombstone532=== PAUSE TestFailedS3DeleteKeepsTombstone533=== RUN TestSweepSkipsRowsLockedByPush534=== PAUSE TestSweepSkipsRowsLockedByPush535=== RUN TestRegisterCompletedObjectNeedsPendingRow536=== PAUSE TestRegisterCompletedObjectNeedsPendingRow537=== RUN TestGetExistingObjectsLocksRows538=== PAUSE TestGetExistingObjectsLocksRows539=== RUN TestSweepRechecksPendingAfterLocking540=== PAUSE TestSweepRechecksPendingAfterLocking541=== RUN TestPushWaitsForSweepHoldingRow542=== PAUSE TestPushWaitsForSweepHoldingRow543=== RUN TestCommitRacingPendingCleanupKeepsObjects544=== PAUSE TestCommitRacingPendingCleanupKeepsObjects545=== RUN TestGCEndsOnShutdown546=== PAUSE TestGCEndsOnShutdown547=== RUN TestGCTaskStore_StartNew548=== PAUSE TestGCTaskStore_StartNew549=== RUN TestGCTaskStore_DeduplicateSameParams550=== PAUSE TestGCTaskStore_DeduplicateSameParams551=== RUN TestGCTaskStore_ConflictDifferentParams552=== PAUSE TestGCTaskStore_ConflictDifferentParams553=== RUN TestGCTaskStore_GetEmpty554=== PAUSE TestGCTaskStore_GetEmpty555=== RUN TestGCTaskStore_GetReturnsLatest556=== PAUSE TestGCTaskStore_GetReturnsLatest557=== RUN TestGCTaskStore_CompletedAllowsNewTask558=== PAUSE TestGCTaskStore_CompletedAllowsNewTask559=== RUN TestGCTaskStore_PhaseUpdates560=== PAUSE TestGCTaskStore_PhaseUpdates561=== RUN TestGCTaskStore_Fail562=== PAUSE TestGCTaskStore_Fail563=== RUN TestGracefulShutdownDrainsInflight564=== PAUSE TestGracefulShutdownDrainsInflight565=== RUN TestService_healthCheckHandler566=== PAUSE TestService_healthCheckHandler567=== RUN TestService_readinessHandler568=== PAUSE TestService_readinessHandler569=== RUN TestGenerateLandingPage570=== PAUSE TestGenerateLandingPage571=== RUN TestCacheConfigHandlerMaxNarSize572=== PAUSE TestCacheConfigHandlerMaxNarSize573=== RUN TestCreatePendingClosureRejectsOversizedNAR574=== PAUSE TestCreatePendingClosureRejectsOversizedNAR575=== RUN TestNARDeduplicationMetadataUploadBug576=== PAUSE TestNARDeduplicationMetadataUploadBug577=== RUN TestMetricsInventory578=== PAUSE TestMetricsInventory579=== RUN TestService_NativeMTLS580=== PAUSE TestService_NativeMTLS581=== RUN TestServerTLSConfig582=== PAUSE TestServerTLSConfig583=== RUN TestMultipartCleanup584=== PAUSE TestMultipartCleanup585=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded586=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded587=== RUN TestPendingCleanupUsesOneCutoff588=== PAUSE TestPendingCleanupUsesOneCutoff589=== RUN TestObjectStatsTrigger590=== PAUSE TestObjectStatsTrigger591=== RUN TestOrphanedObjectsGC592=== PAUSE TestOrphanedObjectsGC593=== RUN TestOrphanedObjectsGCStressTest594=== PAUSE TestOrphanedObjectsGCStressTest595=== RUN TestCreatePin_ReservedPins596=== PAUSE TestCreatePin_ReservedPins597=== RUN TestPresentReportsOnlyClosureRoots598=== PAUSE TestPresentReportsOnlyClosureRoots599=== RUN TestPresentNotReportedWhileGCDeletesClosure600=== PAUSE TestPresentNotReportedWhileGCDeletesClosure601=== RUN TestParseSingleRange602=== PAUSE TestParseSingleRange603=== RUN TestProxyHeadersOnlyTrustedOnSocket604=== PAUSE TestProxyHeadersOnlyTrustedOnSocket605=== RUN TestIsValidCachePath606=== PAUSE TestIsValidCachePath607=== RUN TestReadProxyNarinfo608=== PAUSE TestReadProxyNarinfo609=== RUN TestReadProxyNarinfoAlreadyDecompressed610=== PAUSE TestReadProxyNarinfoAlreadyDecompressed611=== RUN TestReadProxyNarStreaming612=== PAUSE TestReadProxyNarStreaming613=== RUN TestReadProxy404614=== PAUSE TestReadProxy404615=== RUN TestReadProxyInvalidPath616=== PAUSE TestReadProxyInvalidPath617=== RUN TestReadProxyHead618=== PAUSE TestReadProxyHead619=== RUN TestReadProxyConditionalGet620=== PAUSE TestReadProxyConditionalGet621=== RUN TestReadProxyRootRedirectsToIndexHTML622=== PAUSE TestReadProxyRootRedirectsToIndexHTML623=== RUN TestReadProxyDisabled624=== PAUSE TestReadProxyDisabled625=== RUN TestReadRedirectNar626=== PAUSE TestReadRedirectNar627=== RUN TestReadRedirectKeepsNarinfoProxied628=== PAUSE TestReadRedirectKeepsNarinfoProxied629=== RUN TestReadProxyRangeRequest630=== PAUSE TestReadProxyRangeRequest631=== RUN TestReadRedirectUsesPublicS3URL632=== PAUSE TestReadRedirectUsesPublicS3URL633=== RUN TestPush_OverlappingRootsStoreOneRowPerKey634=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey635=== RUN TestPush_CompleteCommitsEveryRoot636=== PAUSE TestPush_CompleteCommitsEveryRoot637=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit638=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit639=== RUN TestPush_RejectsBadRequests640=== PAUSE TestPush_RejectsBadRequests641=== RUN TestPush_SignsNarinfosOfItsPendingObjects642=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects643=== RUN TestRedundantMultipartUpload644=== PAUSE TestRedundantMultipartUpload645=== RUN TestCompleteMultipartUpload_ErrorButObjectExists646=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists647=== RUN TestCompletedNarNotReofferedAcrossClosures648=== PAUSE TestCompletedNarNotReofferedAcrossClosures649=== RUN TestPresignedUploadRegisteredBeforeCommit650=== PAUSE TestPresignedUploadRegisteredBeforeCommit651=== RUN TestService_Rustfstest652=== PAUSE TestService_Rustfstest653=== RUN TestParseSize654=== PAUSE TestParseSize655=== RUN TestSkippedUploadsHandler656=== PAUSE TestSkippedUploadsHandler657=== RUN TestSystemdListenerNotActivated658--- PASS: TestSystemdListenerNotActivated (0.00s)659=== RUN TestWatchdogBeatsWhenHealthy660--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)661=== RUN TestWatchdogSkipsWhenUnhealthy6622026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6692026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6702026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6712026/10/01 09:47:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"672--- PASS: TestWatchdogSkipsWhenUnhealthy (0.24s)673=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle674=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle675=== RUN TestProxyWriteTimeout676=== PAUSE TestProxyWriteTimeout677=== RUN TestIsValidUploadKey678=== PAUSE TestIsValidUploadKey679=== RUN TestUploadHandlersRejectInvalidKeys680=== PAUSE TestUploadHandlersRejectInvalidKeys681=== RUN TestUploadHandlersRejectOversizedBody682=== PAUSE TestUploadHandlersRejectOversizedBody683=== RUN TestService_cleanupPendingClosuresHandler684=== PAUSE TestService_cleanupPendingClosuresHandler685=== RUN TestService_createPendingClosureHandler686=== PAUSE TestService_createPendingClosureHandler687=== RUN TestService_verifyS3Integrity688=== PAUSE TestService_verifyS3Integrity689=== RUN TestCompleteMultipartUnregistered690=== PAUSE TestCompleteMultipartUnregistered691=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT692=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT693=== CONT TestCompleteMultipartUnregistered694=== CONT TestService_verifyS3Integrity695=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT696=== CONT TestCacheConfigHandlerMaxNarSize697=== CONT TestReadProxyRootRedirectsToIndexHTML698=== CONT TestClientMultipleUploads699=== CONT TestPresentReportsOnlyClosureRoots700=== CONT TestService_AuthMiddleware701=== CONT TestClientWithDependencies702=== CONT TestDeduplicatedObjectsRecordedAsPending703--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)704=== CONT TestPushDedupSurvivesConcurrentGC7052026-10-01 09:47:53.565 UTC [78571] ERROR: relation "goose_db_version" does not exist at character 367062026-10-01 09:47:53.565 UTC [78571] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7072026-10-01 09:47:53.633 UTC [78575] ERROR: relation "goose_db_version" does not exist at character 367082026-10-01 09:47:53.633 UTC [78575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7092026-10-01 09:47:53.634 UTC [78577] ERROR: relation "goose_db_version" does not exist at character 367102026-10-01 09:47:53.634 UTC [78577] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7112026-10-01 09:47:53.634 UTC [78576] ERROR: relation "goose_db_version" does not exist at character 367122026-10-01 09:47:53.634 UTC [78576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7132026-10-01 09:47:53.657 UTC [78578] ERROR: relation "goose_db_version" does not exist at character 367142026-10-01 09:47:53.657 UTC [78578] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7152026-10-01 09:47:53.669 UTC [78579] ERROR: relation "goose_db_version" does not exist at character 367162026-10-01 09:47:53.669 UTC [78579] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7172026-10-01 09:47:53.689 UTC [78581] ERROR: relation "goose_db_version" does not exist at character 367182026-10-01 09:47:53.689 UTC [78581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026-10-01 09:47:53.736 UTC [78584] ERROR: relation "goose_db_version" does not exist at character 367202026-10-01 09:47:53.736 UTC [78584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026-10-01 09:47:53.740 UTC [78585] ERROR: relation "goose_db_version" does not exist at character 367222026-10-01 09:47:53.740 UTC [78585] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7232026-10-01 09:47:53.740 UTC [78580] ERROR: relation "goose_db_version" does not exist at character 367242026-10-01 09:47:53.740 UTC [78580] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026/10/01 09:47:53 OK 20241026095416_initial_model.sql (147.57ms)7262026/10/01 09:47:53 OK 20251210153512_drop_unused_gin_index.sql (11.16ms)7272026/10/01 09:47:53 OK 20251218171726_add_pins.sql (37.58ms)7282026/10/01 09:47:53 OK 20241026095416_initial_model.sql (168.07ms)7292026/10/01 09:47:53 OK 20251210153512_drop_unused_gin_index.sql (17.81ms)7302026/10/01 09:47:53 OK 20260628120000_add_object_size_and_stats.sql (31.46ms)7312026/10/01 09:47:53 OK 20260905000000_add_claims.sql (39.17ms)7322026/10/01 09:47:53 OK 20251218171726_add_pins.sql (46.17ms)7332026/10/01 09:47:53 OK 20241026095416_initial_model.sql (191.14ms)7342026/10/01 09:47:53 OK 20241026095416_initial_model.sql (147.63ms)7352026/10/01 09:47:53 OK 20260920000000_drop_claims.sql (16.47ms)7362026/10/01 09:47:53 OK 20241026095416_initial_model.sql (171.59ms)7372026/10/01 09:47:53 OK 20251210153512_drop_unused_gin_index.sql (17.1ms)7382026/10/01 09:47:53 OK 20251210153512_drop_unused_gin_index.sql (15.45ms)7392026/10/01 09:47:53 OK 20251210153512_drop_unused_gin_index.sql (28.17ms)7402026/10/01 09:47:53 OK 20260628120000_add_object_size_and_stats.sql (29.85ms)7412026/10/01 09:47:53 OK 20260923120000_add_pushes.sql (41.47ms)7422026/10/01 09:47:53 goose: successfully migrated database to version: 202609231200007432026/10/01 09:47:53 OK 20251218171726_add_pins.sql (25.16ms)7442026/10/01 09:47:53 OK 20251218171726_add_pins.sql (41.45ms)7452026/10/01 09:47:53 OK 20241026095416_initial_model.sql (140.43ms)7462026/10/01 09:47:53 OK 1_commit_pending_closure.sql (10.66ms)7472026/10/01 09:47:53 OK 20251218171726_add_pins.sql (35.34ms)7482026/10/01 09:47:53 OK 20241026095416_initial_model.sql (141.45ms)7492026/10/01 09:47:53 OK 20241026095416_initial_model.sql (249.97ms)7502026/10/01 09:47:53 OK 20260905000000_add_claims.sql (34.19ms)7512026/10/01 09:47:53 OK 20241026095416_initial_model.sql (141.67ms)7522026/10/01 09:47:53 OK 20241026095416_initial_model.sql (250.74ms)7532026/10/01 09:47:53 OK 2_object_stats_trigger.sql (4.99ms)7542026/10/01 09:47:53 OK 3_commit_push.sql (6.79ms)7552026/10/01 09:47:53 goose: up to current file version: 37562026/10/01 09:47:54 OK 20251210153512_drop_unused_gin_index.sql (15.44ms)7572026/10/01 09:47:54 OK 20251210153512_drop_unused_gin_index.sql (16.23ms)7582026/10/01 09:47:54 OK 20251210153512_drop_unused_gin_index.sql (16.96ms)7592026/10/01 09:47:54 OK 20251210153512_drop_unused_gin_index.sql (30.19ms)7602026/10/01 09:47:54 OK 20251210153512_drop_unused_gin_index.sql (30.39ms)7612026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (40.33ms)7622026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (60.69ms)7632026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (69.68ms)7642026/10/01 09:47:54 OK 20251218171726_add_pins.sql (47.29ms)7652026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (74.65ms)7662026/10/01 09:47:54 OK 20251218171726_add_pins.sql (60.09ms)7672026/10/01 09:47:54 OK 20251218171726_add_pins.sql (60.23ms)7682026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (9.87ms)7692026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200007702026/10/01 09:47:54 OK 1_commit_pending_closure.sql (2.08ms)7712026/10/01 09:47:54 OK 2_object_stats_trigger.sql (568.58µs)7722026/10/01 09:47:54 OK 3_commit_push.sql (397.08µs)7732026/10/01 09:47:54 goose: up to current file version: 37742026/10/01 09:47:54 OK 20251218171726_add_pins.sql (62.8ms)7752026/10/01 09:47:54 OK 20251218171726_add_pins.sql (63.09ms)7762026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (44.2ms)7772026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (32.43ms)7782026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (33.89ms)7792026/10/01 09:47:54 OK 20260905000000_add_claims.sql (60.02ms)7802026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (57.59ms)7812026/10/01 09:47:54 OK 20260905000000_add_claims.sql (111.06ms)7822026/10/01 09:47:54 OK 20260628120000_add_object_size_and_stats.sql (65.67ms)7832026/10/01 09:47:54 OK 20260905000000_add_claims.sql (100.78ms)7842026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (63.49ms)7852026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (22.65ms)7862026/10/01 09:47:54 OK 20260905000000_add_claims.sql (65.47ms)7872026/10/01 09:47:54 OK 20260905000000_add_claims.sql (84.18ms)7882026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (20.86ms)7892026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200007902026/10/01 09:47:54 OK 1_commit_pending_closure.sql (1.96ms)7912026/10/01 09:47:54 OK 2_object_stats_trigger.sql (664.79µs)7922026/10/01 09:47:54 OK 3_commit_push.sql (423.79µs)7932026/10/01 09:47:54 goose: up to current file version: 37942026/10/01 09:47:54 OK 20260905000000_add_claims.sql (92.88ms)7952026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (29.22ms)7962026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200007972026/10/01 09:47:54 OK 1_commit_pending_closure.sql (1.98ms)7982026/10/01 09:47:54 OK 2_object_stats_trigger.sql (586.96µs)7992026/10/01 09:47:54 OK 3_commit_push.sql (410.75µs)8002026/10/01 09:47:54 goose: up to current file version: 38012026/10/01 09:47:54 OK 20260905000000_add_claims.sql (76.35ms)8022026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (71.98ms)8032026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (64.05ms)8042026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (27.31ms)8052026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (61.52ms)8062026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (51.58ms)8072026/10/01 09:47:54 OK 20260905000000_add_claims.sql (102.29ms)8082026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (22.68ms)8092026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200008102026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (23.97ms)8112026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200008122026/10/01 09:47:54 OK 1_commit_pending_closure.sql (2.5ms)8132026/10/01 09:47:54 OK 1_commit_pending_closure.sql (3.11ms)8142026/10/01 09:47:54 OK 2_object_stats_trigger.sql (591.88µs)8152026/10/01 09:47:54 OK 3_commit_push.sql (388.25µs)8162026/10/01 09:47:54 goose: up to current file version: 38172026/10/01 09:47:54 OK 2_object_stats_trigger.sql (492.92µs)8182026/10/01 09:47:54 OK 3_commit_push.sql (390.42µs)8192026/10/01 09:47:54 goose: up to current file version: 38202026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (13.94ms)8212026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200008222026/10/01 09:47:54 OK 1_commit_pending_closure.sql (1.93ms)8232026/10/01 09:47:54 OK 2_object_stats_trigger.sql (535.04µs)8242026/10/01 09:47:54 OK 3_commit_push.sql (421.79µs)8252026/10/01 09:47:54 goose: up to current file version: 38262026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (21.28ms)8272026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200008282026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (21.31ms)8292026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200008302026/10/01 09:47:54 OK 1_commit_pending_closure.sql (2.45ms)8312026/10/01 09:47:54 OK 1_commit_pending_closure.sql (2.45ms)8322026/10/01 09:47:54 OK 2_object_stats_trigger.sql (559.88µs)8332026/10/01 09:47:54 OK 2_object_stats_trigger.sql (574.92µs)8342026/10/01 09:47:54 OK 3_commit_push.sql (418.29µs)8352026/10/01 09:47:54 goose: up to current file version: 38362026/10/01 09:47:54 OK 3_commit_push.sql (452.71µs)8372026/10/01 09:47:54 goose: up to current file version: 38382026/10/01 09:47:54 OK 20260920000000_drop_claims.sql (46.3ms)8392026/10/01 09:47:54 INFO Received uploads request method=POST path=/api/pending_closures8402026/10/01 09:47:54 OK 20260923120000_add_pushes.sql (23.22ms)8412026/10/01 09:47:54 goose: successfully migrated database to version: 202609231200008422026/10/01 09:47:54 OK 1_commit_pending_closure.sql (2.69ms)8432026/10/01 09:47:54 OK 2_object_stats_trigger.sql (706.17µs)8442026/10/01 09:47:54 OK 3_commit_push.sql (450.79µs)8452026/10/01 09:47:54 goose: up to current file version: 38462026/10/01 09:47:54 INFO Received uploads request method=POST path=/api/pending_closures847--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.96s)848=== CONT TestGCMetrics849--- PASS: TestReadProxyRootRedirectsToIndexHTML (4.27s)850=== CONT TestGCBugBareHashReferences8512026/10/01 09:47:55 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"852--- PASS: TestService_AuthMiddleware (4.99s)853=== CONT TestLeadEndsOnShutdown854=== NAME TestClientWithDependencies855 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-77474-458540005/TestClientWithDependencies1513622276/001/store/ys08vlab2ffrk18nfknlph271cihx6nk-test-script8562026/10/01 09:47:56 INFO Received uploads request method=POST path=/api/pending_closures857 client_integration_test.go:615: Found 1 dependencies (including self)8582026/10/01 09:47:56 INFO Aborted multipart uploads count=08592026/10/01 09:47:56 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=08602026/10/01 09:47:56 INFO Received push request method=POST path=/api/pushes8612026/10/01 09:47:56 INFO Vacuumed table table=pending_closures8622026/10/01 09:47:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8632026/10/01 09:47:56 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst864--- PASS: TestCompleteMultipartUnregistered (5.75s)865=== CONT TestLeadElectsOneAndHandsOver8662026/10/01 09:47:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8672026/10/01 09:47:56 INFO Uploading ys08vlab2ffrk18nfknlph271cihx6nk-test-script (136B)8682026/10/01 09:47:56 INFO Vacuumed table table=pending_objects8692026/10/01 09:47:56 INFO Vacuumed table table=multipart_uploads8702026/10/01 09:47:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8712026/10/01 09:47:56 INFO Vacuumed table table=closures8722026/10/01 09:47:56 WARN Failed to register uploaded object key=ys08vlab2ffrk18nfknlph271cihx6nk.ls error="server returned 404: 404 page not found\n"8732026/10/01 09:47:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8742026/10/01 09:47:56 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"8752026/10/01 09:47:56 WARN Failed to register uploaded object key=log/j0mq3yax8wa9x3mglczy5km3vwjzglmq-test-script.drv error="server returned 404: 404 page not found\n"8762026/10/01 09:47:56 INFO Signed narinfos id=1 count=18772026/10/01 09:47:56 INFO Uploading 1 narinfos8782026/10/01 09:47:56 INFO Vacuumed table table=objects8792026/10/01 09:47:56 INFO Aborted multipart uploads count=08802026/10/01 09:47:56 WARN Force mode enabled - objects will be deleted immediately without grace period8812026/10/01 09:47:56 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=08822026/10/01 09:47:56 INFO Vacuumed table table=pending_closures8832026/10/01 09:47:56 INFO Received complete push request method=POST path=/api/pushes/1/complete8842026/10/01 09:47:56 WARN Failed to register uploaded object key=ys08vlab2ffrk18nfknlph271cihx6nk.narinfo error="server returned 404: 404 page not found\n"8852026/10/01 09:47:56 INFO Vacuumed table table=pending_objects8862026/10/01 09:47:56 INFO Vacuumed table table=multipart_uploads8872026/10/01 09:47:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTIxMTFiYmYtNmIxNi00OGU2LWJhZTUtNjliOTNmY2JiZDg0LjcyZTZhNWFkLTIwYjQtNDVhYi04NDIzLWYyOGI1NmE3ZjRjNXgxNzkwODQ4MDc0MzYwNDU3MDAw parts=108882026/10/01 09:47:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8892026/10/01 09:47:56 INFO Vacuumed table table=closures8902026/10/01 09:47:56 INFO Vacuumed table table=objects8912026/10/01 09:47:56 INFO Completed upload id=18922026/10/01 09:47:56 INFO Upload complete. (404ms)893--- PASS: TestPushDedupSurvivesConcurrentGC (6.01s)894=== CONT TestResolveDBConnectionString895=== NAME TestClientWithDependencies896 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-77474-458540005/TestClientWithDependencies1513622276/001/store) requires matching store prefix8972026/10/01 09:47:56 INFO Received uploads request method=POST path=/api/pending_closures8982026/10/01 09:47:56 INFO Received uploads request method=POST path=/api/pending_closures8992026/10/01 09:47:56 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9002026/10/01 09:47:56 WARN Found objects in DB but missing from S3, will re-upload count=1901--- PASS: TestService_verifyS3Integrity (6.03s)902=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock903=== RUN TestResolveDBConnectionString/flag_wins904=== PAUSE TestResolveDBConnectionString/flag_wins905=== RUN TestResolveDBConnectionString/file_when_flag_empty906=== PAUSE TestResolveDBConnectionString/file_when_flag_empty907=== RUN TestResolveDBConnectionString/missing_file_is_an_error908=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error909=== RUN TestResolveDBConnectionString/PGHOST_allows_empty910=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty911=== RUN TestResolveDBConnectionString/nothing_configured912=== PAUSE TestResolveDBConnectionString/nothing_configured913=== CONT TestClientFallsBackToClosures914--- PASS: TestClientWithDependencies (6.05s)915=== CONT TestClientPushesUseOnePush9162026/10/01 09:47:57 INFO Received uploads request method=POST path=/api/pending_closures917--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.69s)918=== CONT TestPinProtectsFromGC9192026-10-01 09:47:57.647 UTC [78773] ERROR: relation "goose_db_version" does not exist at character 369202026-10-01 09:47:57.647 UTC [78773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC921=== NAME TestClientMultipleUploads922 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-77474-458540005/TestClientMultipleUploads607035755/001/store/ii0qc5sd4h9yw4rxv6ybi10fp4gahnyh-test-file-0.txt9232026-10-01 09:47:57.761 UTC [78783] ERROR: relation "goose_db_version" does not exist at character 369242026-10-01 09:47:57.761 UTC [78783] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC925 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-77474-458540005/TestClientMultipleUploads607035755/001/store/xsa3kkm2kb668krdmxa620dw5lr256ax-test-file-1.txt926--- PASS: TestPresentReportsOnlyClosureRoots (7.02s)927=== CONT TestClientSharedPathCommittedMidPush928=== NAME TestClientMultipleUploads929 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-77474-458540005/TestClientMultipleUploads607035755/001/store/il75p7c0ha2zdwn3cjx771y19rz4jj68-test-file-2.txt9302026/10/01 09:47:58 OK 20241026095416_initial_model.sql (328.73ms)9312026/10/01 09:47:58 OK 20251210153512_drop_unused_gin_index.sql (14.48ms)9322026/10/01 09:47:58 OK 20241026095416_initial_model.sql (325.69ms)9332026/10/01 09:47:58 OK 20251210153512_drop_unused_gin_index.sql (23.31ms)9342026/10/01 09:47:58 OK 20251218171726_add_pins.sql (43.13ms)9352026/10/01 09:47:58 OK 20251218171726_add_pins.sql (46.58ms)9362026/10/01 09:47:58 INFO Received push request method=POST path=/api/pushes9372026/10/01 09:47:58 OK 20260628120000_add_object_size_and_stats.sql (61.54ms)9382026/10/01 09:47:58 OK 20260628120000_add_object_size_and_stats.sql (43.72ms)9392026/10/01 09:47:58 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9402026/10/01 09:47:58 INFO Uploading il75p7c0ha2zdwn3cjx771y19rz4jj68-test-file-2.txt (160B)9412026/10/01 09:47:58 INFO Uploading xsa3kkm2kb668krdmxa620dw5lr256ax-test-file-1.txt (160B)9422026/10/01 09:47:58 INFO Uploading ii0qc5sd4h9yw4rxv6ybi10fp4gahnyh-test-file-0.txt (160B)9432026/10/01 09:47:58 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"9442026/10/01 09:47:58 WARN Failed to register uploaded object key=ii0qc5sd4h9yw4rxv6ybi10fp4gahnyh.ls error="server returned 404: 404 page not found\n"9452026/10/01 09:47:58 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"9462026/10/01 09:47:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9472026/10/01 09:47:58 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9482026/10/01 09:47:58 WARN Failed to register uploaded object key=il75p7c0ha2zdwn3cjx771y19rz4jj68.ls error="server returned 404: 404 page not found\n"9492026/10/01 09:47:58 WARN Failed to register uploaded object key=xsa3kkm2kb668krdmxa620dw5lr256ax.ls error="server returned 404: 404 page not found\n"9502026/10/01 09:47:58 INFO Signed narinfos id=1 count=39512026/10/01 09:47:58 INFO Uploading 3 narinfos9522026/10/01 09:47:58 OK 20260905000000_add_claims.sql (79.43ms)9532026/10/01 09:47:58 INFO Received complete push request method=POST path=/api/pushes/1/complete9542026/10/01 09:47:58 WARN Failed to register uploaded object key=ii0qc5sd4h9yw4rxv6ybi10fp4gahnyh.narinfo error="server returned 404: 404 page not found\n"9552026/10/01 09:47:58 WARN Failed to register uploaded object key=xsa3kkm2kb668krdmxa620dw5lr256ax.narinfo error="server returned 404: 404 page not found\n"9562026/10/01 09:47:58 WARN Failed to register uploaded object key=il75p7c0ha2zdwn3cjx771y19rz4jj68.narinfo error="server returned 404: 404 page not found\n"9572026/10/01 09:47:58 OK 20260905000000_add_claims.sql (109.47ms)9582026/10/01 09:47:58 INFO Upload complete. (282ms)959 client_integration_test.go:369: Uploaded 3 paths in 357.327333ms9602026/10/01 09:47:58 OK 20260920000000_drop_claims.sql (93.95ms)9612026/10/01 09:47:58 OK 20260920000000_drop_claims.sql (67.75ms)9622026/10/01 09:47:58 OK 20260923120000_add_pushes.sql (40.56ms)9632026/10/01 09:47:58 goose: successfully migrated database to version: 202609231200009642026/10/01 09:47:58 OK 1_commit_pending_closure.sql (1.76ms)9652026/10/01 09:47:58 OK 2_object_stats_trigger.sql (474.96µs)9662026/10/01 09:47:58 OK 3_commit_push.sql (318.92µs)9672026/10/01 09:47:58 goose: up to current file version: 39682026/10/01 09:47:58 OK 20260923120000_add_pushes.sql (36.06ms)9692026/10/01 09:47:58 goose: successfully migrated database to version: 202609231200009702026/10/01 09:47:58 OK 1_commit_pending_closure.sql (2.69ms)9712026/10/01 09:47:58 OK 2_object_stats_trigger.sql (1.86ms)9722026/10/01 09:47:58 OK 3_commit_push.sql (1.14ms)9732026/10/01 09:47:58 goose: up to current file version: 3974--- PASS: TestClientMultipleUploads (7.69s)975=== CONT TestCompletedNarNotReofferedAcrossClosures9762026/10/01 09:47:58 INFO Aborted multipart uploads count=09772026/10/01 09:47:58 WARN Force mode enabled - objects will be deleted immediately without grace period9782026/10/01 09:47:58 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=09792026/10/01 09:47:58 INFO Vacuumed table table=pending_closures9802026/10/01 09:47:58 INFO Vacuumed table table=pending_objects9812026/10/01 09:47:58 INFO Vacuumed table table=multipart_uploads9822026/10/01 09:47:58 INFO Vacuumed table table=closures9832026/10/01 09:47:58 INFO Vacuumed table table=objects984--- PASS: TestGCMetrics (4.04s)985=== CONT TestService_createPendingClosureHandler9862026-10-01 09:47:59.282 UTC [78855] ERROR: relation "goose_db_version" does not exist at character 369872026-10-01 09:47:59.282 UTC [78855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9882026-10-01 09:47:59.282 UTC [78856] ERROR: relation "goose_db_version" does not exist at character 369892026-10-01 09:47:59.282 UTC [78856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9902026/10/01 09:47:59 OK 20241026095416_initial_model.sql (163.96ms)9912026/10/01 09:47:59 OK 20241026095416_initial_model.sql (156.38ms)9922026/10/01 09:47:59 OK 20251210153512_drop_unused_gin_index.sql (13.34ms)9932026/10/01 09:47:59 OK 20251210153512_drop_unused_gin_index.sql (15.39ms)9942026/10/01 09:47:59 OK 20251218171726_add_pins.sql (19.29ms)9952026/10/01 09:47:59 OK 20251218171726_add_pins.sql (19.82ms)996--- PASS: TestGCBugBareHashReferences (4.42s)997=== CONT TestService_cleanupPendingClosuresHandler9982026/10/01 09:47:59 OK 20260628120000_add_object_size_and_stats.sql (84.74ms)9992026/10/01 09:47:59 OK 20260628120000_add_object_size_and_stats.sql (86.68ms)10002026/10/01 09:47:59 OK 20260905000000_add_claims.sql (22.49ms)10012026/10/01 09:47:59 OK 20260905000000_add_claims.sql (25.5ms)10022026/10/01 09:47:59 OK 20260920000000_drop_claims.sql (20.39ms)10032026/10/01 09:47:59 OK 20260920000000_drop_claims.sql (21.2ms)10042026-10-01 09:47:59.737 UTC [78864] ERROR: relation "goose_db_version" does not exist at character 3610052026-10-01 09:47:59.737 UTC [78864] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10062026/10/01 09:47:59 OK 20260923120000_add_pushes.sql (6.09ms)10072026/10/01 09:47:59 goose: successfully migrated database to version: 2026092312000010082026/10/01 09:47:59 OK 20260923120000_add_pushes.sql (6.63ms)10092026/10/01 09:47:59 goose: successfully migrated database to version: 2026092312000010102026/10/01 09:47:59 OK 1_commit_pending_closure.sql (5.2ms)10112026/10/01 09:47:59 OK 1_commit_pending_closure.sql (7.07ms)10122026/10/01 09:47:59 OK 2_object_stats_trigger.sql (1.15ms)10132026/10/01 09:47:59 OK 3_commit_push.sql (308.46µs)10142026/10/01 09:47:59 goose: up to current file version: 310152026/10/01 09:47:59 OK 2_object_stats_trigger.sql (630.42µs)10162026/10/01 09:47:59 OK 3_commit_push.sql (281.46µs)10172026/10/01 09:47:59 goose: up to current file version: 310182026-10-01 09:47:59.878 UTC [78869] ERROR: relation "goose_db_version" does not exist at character 3610192026-10-01 09:47:59.878 UTC [78869] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10202026-10-01 09:47:59.993 UTC [78870] ERROR: relation "goose_db_version" does not exist at character 3610212026-10-01 09:47:59.993 UTC [78870] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10222026-10-01 09:48:00.066 UTC [78871] ERROR: relation "goose_db_version" does not exist at character 3610232026-10-01 09:48:00.066 UTC [78871] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10242026/10/01 09:48:00 OK 20241026095416_initial_model.sql (203.51ms)10252026/10/01 09:48:00 OK 20241026095416_initial_model.sql (157.92ms)10262026/10/01 09:48:00 OK 20251210153512_drop_unused_gin_index.sql (47.07ms)10272026/10/01 09:48:00 OK 20251210153512_drop_unused_gin_index.sql (32.41ms)10282026/10/01 09:48:00 INFO lead: acquired remote=192.0.2.1:123410292026/10/01 09:48:00 INFO lead: released remote=192.0.2.1:12341030--- PASS: TestLeadEndsOnShutdown (4.25s)1031=== CONT TestUploadHandlersRejectOversizedBody10322026/10/01 09:48:00 OK 20251218171726_add_pins.sql (54.51ms)10332026/10/01 09:48:00 OK 20251218171726_add_pins.sql (39.27ms)1034=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1035=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1036=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1037=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1038=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1039=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1040=== CONT TestUploadHandlersRejectInvalidKeys1041=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1042=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1043=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1044=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1045=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1046=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1047=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1048=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1049=== CONT TestIsValidUploadKey1050=== RUN TestIsValidUploadKey/narinfo1051=== PAUSE TestIsValidUploadKey/narinfo1052=== RUN TestIsValidUploadKey/nar_zst1053=== PAUSE TestIsValidUploadKey/nar_zst1054=== RUN TestIsValidUploadKey/nar_xz1055=== PAUSE TestIsValidUploadKey/nar_xz1056=== RUN TestIsValidUploadKey/nar_plain1057=== PAUSE TestIsValidUploadKey/nar_plain1058=== RUN TestIsValidUploadKey/listing1059=== PAUSE TestIsValidUploadKey/listing1060=== RUN TestIsValidUploadKey/build_log1061=== PAUSE TestIsValidUploadKey/build_log1062=== RUN TestIsValidUploadKey/build_log_home-manager_file1063=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1064=== RUN TestIsValidUploadKey/build_log_plus_in_name1065=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1066=== RUN TestIsValidUploadKey/build_log_question_mark1067=== PAUSE TestIsValidUploadKey/build_log_question_mark1068=== RUN TestIsValidUploadKey/build_log_equals1069=== PAUSE TestIsValidUploadKey/build_log_equals1070=== RUN TestIsValidUploadKey/realisation1071=== PAUSE TestIsValidUploadKey/realisation1072=== RUN TestIsValidUploadKey/realisation_plus_in_output1073=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1074=== RUN TestIsValidUploadKey/nix-cache-info1075=== PAUSE TestIsValidUploadKey/nix-cache-info1076=== RUN TestIsValidUploadKey/index.html1077=== PAUSE TestIsValidUploadKey/index.html1078=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1079=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1080=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1081=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1082=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1083=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1084=== RUN TestIsValidUploadKey/traversal1085=== PAUSE TestIsValidUploadKey/traversal1086=== RUN TestIsValidUploadKey/traversal_nar1087=== PAUSE TestIsValidUploadKey/traversal_nar1088=== RUN TestIsValidUploadKey/absolute1089=== PAUSE TestIsValidUploadKey/absolute1090=== RUN TestIsValidUploadKey/empty_key1091=== PAUSE TestIsValidUploadKey/empty_key1092=== RUN TestIsValidUploadKey/unknown_type1093=== PAUSE TestIsValidUploadKey/unknown_type1094=== CONT TestProxyWriteTimeout1095=== RUN TestProxyWriteTimeout/narinfo1096=== PAUSE TestProxyWriteTimeout/narinfo1097=== RUN TestProxyWriteTimeout/1_GiB_nar1098=== PAUSE TestProxyWriteTimeout/1_GiB_nar1099=== RUN TestProxyWriteTimeout/10_GiB_nar1100=== PAUSE TestProxyWriteTimeout/10_GiB_nar1101=== RUN TestProxyWriteTimeout/unknown_size1102=== PAUSE TestProxyWriteTimeout/unknown_size1103=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11042026/10/01 09:48:00 OK 20260628120000_add_object_size_and_stats.sql (67.09ms)11052026/10/01 09:48:00 OK 20260628120000_add_object_size_and_stats.sql (78.59ms)11062026/10/01 09:48:00 OK 20260905000000_add_claims.sql (63.38ms)11072026/10/01 09:48:00 OK 20260905000000_add_claims.sql (103.45ms)11082026/10/01 09:48:00 OK 20241026095416_initial_model.sql (312.7ms)11092026/10/01 09:48:00 OK 20251210153512_drop_unused_gin_index.sql (10.95ms)11102026/10/01 09:48:00 OK 20260920000000_drop_claims.sql (78.85ms)11112026/10/01 09:48:00 OK 20260920000000_drop_claims.sql (61.31ms)11122026/10/01 09:48:00 OK 20260923120000_add_pushes.sql (43.49ms)11132026/10/01 09:48:00 goose: successfully migrated database to version: 2026092312000011142026/10/01 09:48:00 OK 1_commit_pending_closure.sql (2.16ms)11152026/10/01 09:48:00 OK 2_object_stats_trigger.sql (616.29µs)11162026/10/01 09:48:00 OK 3_commit_push.sql (404.67µs)11172026/10/01 09:48:00 goose: up to current file version: 311182026/10/01 09:48:00 OK 20251218171726_add_pins.sql (57.46ms)11192026/10/01 09:48:00 OK 20260923120000_add_pushes.sql (43.35ms)11202026/10/01 09:48:00 goose: successfully migrated database to version: 2026092312000011212026/10/01 09:48:00 OK 1_commit_pending_closure.sql (2.12ms)11222026/10/01 09:48:00 OK 2_object_stats_trigger.sql (541.83µs)11232026/10/01 09:48:00 OK 3_commit_push.sql (398.71µs)11242026/10/01 09:48:00 goose: up to current file version: 311252026/10/01 09:48:00 OK 20260628120000_add_object_size_and_stats.sql (60.4ms)11262026-10-01 09:48:00.530 UTC [78877] ERROR: relation "goose_db_version" does not exist at character 3611272026-10-01 09:48:00.530 UTC [78877] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11282026/10/01 09:48:00 OK 20241026095416_initial_model.sql (383.33ms)11292026/10/01 09:48:00 OK 20251210153512_drop_unused_gin_index.sql (8.13ms)11302026/10/01 09:48:00 INFO lead: acquired remote=192.0.2.1:123411312026/10/01 09:48:00 OK 20260905000000_add_claims.sql (109.05ms)11322026/10/01 09:48:00 OK 20251218171726_add_pins.sql (77.74ms)11332026/10/01 09:48:00 OK 20260920000000_drop_claims.sql (40.47ms)11342026/10/01 09:48:00 OK 20260923120000_add_pushes.sql (22.43ms)11352026/10/01 09:48:00 goose: successfully migrated database to version: 2026092312000011362026/10/01 09:48:00 OK 20260628120000_add_object_size_and_stats.sql (65.75ms)11372026/10/01 09:48:00 OK 1_commit_pending_closure.sql (5.83ms)11382026/10/01 09:48:00 OK 2_object_stats_trigger.sql (314.46µs)11392026/10/01 09:48:00 OK 3_commit_push.sql (201.21µs)11402026/10/01 09:48:00 goose: up to current file version: 311412026/10/01 09:48:00 INFO lead: released remote=192.0.2.1:123411422026/10/01 09:48:00 INFO lead: acquired remote=192.0.2.1:123411432026/10/01 09:48:00 INFO lead: released remote=192.0.2.1:12341144--- PASS: TestLeadElectsOneAndHandsOver (4.08s)1145=== CONT TestSkippedUploadsHandler11462026/10/01 09:48:00 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001147--- PASS: TestSkippedUploadsHandler (0.00s)1148=== CONT TestParseSize1149--- PASS: TestParseSize (0.00s)1150=== CONT TestService_Rustfstest11512026/10/01 09:48:00 OK 20241026095416_initial_model.sql (142.8ms)11522026/10/01 09:48:00 OK 20251210153512_drop_unused_gin_index.sql (12.91ms)11532026/10/01 09:48:00 OK 20260905000000_add_claims.sql (115.85ms)11542026/10/01 09:48:00 OK 20251218171726_add_pins.sql (44.62ms)11552026/10/01 09:48:00 OK 20260920000000_drop_claims.sql (82.46ms)11562026/10/01 09:48:00 OK 20260628120000_add_object_size_and_stats.sql (49.99ms)11572026/10/01 09:48:00 OK 20260923120000_add_pushes.sql (23.21ms)11582026/10/01 09:48:00 goose: successfully migrated database to version: 2026092312000011592026/10/01 09:48:00 OK 1_commit_pending_closure.sql (2.31ms)11602026/10/01 09:48:00 OK 2_object_stats_trigger.sql (643.63µs)11612026/10/01 09:48:00 OK 3_commit_push.sql (438.29µs)11622026/10/01 09:48:00 goose: up to current file version: 311632026/10/01 09:48:00 OK 20260905000000_add_claims.sql (88.65ms)11642026/10/01 09:48:01 OK 20260920000000_drop_claims.sql (78.51ms)11652026/10/01 09:48:01 OK 20260923120000_add_pushes.sql (33.73ms)11662026/10/01 09:48:01 goose: successfully migrated database to version: 2026092312000011672026/10/01 09:48:01 OK 1_commit_pending_closure.sql (1.26ms)11682026/10/01 09:48:01 OK 2_object_stats_trigger.sql (286.38µs)11692026/10/01 09:48:01 OK 3_commit_push.sql (237.92µs)11702026/10/01 09:48:01 goose: up to current file version: 311712026/10/01 09:48:01 INFO Received push request method=POST path=/api/pushes11722026/10/01 09:48:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11732026/10/01 09:48:02 INFO Uploading v9j40lar6g90s7wddc4ir2va8jzyswx5-a (248B)11742026/10/01 09:48:02 INFO Uploading 8604hvyzqvp6svndha2zyw5jgkrd1vjk-shared-dep (136B)11752026/10/01 09:48:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11762026/10/01 09:48:02 WARN Failed to register uploaded object key=nar/0b56x9dda98gdfahy2dz4xzn217qmh3477fmwvs3gd6x81dd26bx.nar.zst error="server returned 404: 404 page not found\n"11772026/10/01 09:48:02 WARN Failed to register uploaded object key=8604hvyzqvp6svndha2zyw5jgkrd1vjk.ls error="server returned 404: 404 page not found\n"11782026/10/01 09:48:02 WARN Failed to register uploaded object key=8qb24ykrf8py9rirdmmivgsk57gindni.ls error="server returned 404: 404 page not found\n"11792026/10/01 09:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11802026/10/01 09:48:02 WARN Failed to register uploaded object key=v9j40lar6g90s7wddc4ir2va8jzyswx5.ls error="server returned 404: 404 page not found\n"11812026/10/01 09:48:02 INFO Signed narinfos id=1 count=311822026/10/01 09:48:02 INFO Uploading 3 narinfos11832026-10-01 09:48:02.118 UTC [78902] ERROR: relation "goose_db_version" does not exist at character 3611842026-10-01 09:48:02.118 UTC [78902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11852026/10/01 09:48:02 WARN Failed to register uploaded object key=8604hvyzqvp6svndha2zyw5jgkrd1vjk.narinfo error="server returned 404: 404 page not found\n"11862026/10/01 09:48:02 WARN Failed to register uploaded object key=8qb24ykrf8py9rirdmmivgsk57gindni.narinfo error="server returned 404: 404 page not found\n"11872026/10/01 09:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete11882026/10/01 09:48:02 WARN Failed to register uploaded object key=v9j40lar6g90s7wddc4ir2va8jzyswx5.narinfo error="server returned 404: 404 page not found\n"11892026/10/01 09:48:02 INFO Upload complete. (253ms)1190=== NAME TestClientPushesUseOnePush1191 client_pushes_test.go:97: Retrieved narinfo from S3:1192 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientPushesUseOnePush328316627/001/store/8604hvyzqvp6svndha2zyw5jgkrd1vjk-shared-dep1193 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1194 Compression: zstd1195 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821196 NarSize: 1361197 References: 1198 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1199 client_pushes_test.go:97: Retrieved narinfo from S3:1200 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientPushesUseOnePush328316627/001/store/v9j40lar6g90s7wddc4ir2va8jzyswx5-a1201 URL: nar/0b56x9dda98gdfahy2dz4xzn217qmh3477fmwvs3gd6x81dd26bx.nar.zst1202 Compression: zstd1203 NarHash: sha256:0b56x9dda98gdfahy2dz4xzn217qmh3477fmwvs3gd6x81dd26bx1204 NarSize: 2481205 References: /nix/var/nix/builds/nix-77474-458540005/TestClientPushesUseOnePush328316627/001/store/8604hvyzqvp6svndha2zyw5jgkrd1vjk-shared-dep1206 CA: text:sha256:1gsiv2246hxqbj0v5qa5vii3zfdv7cxvg6xn7vs7n1rz12isjr1f1207 client_pushes_test.go:97: Retrieved narinfo from S3:1208 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientPushesUseOnePush328316627/001/store/8qb24ykrf8py9rirdmmivgsk57gindni-b1209 URL: nar/0b56x9dda98gdfahy2dz4xzn217qmh3477fmwvs3gd6x81dd26bx.nar.zst1210 Compression: zstd1211 NarHash: sha256:0b56x9dda98gdfahy2dz4xzn217qmh3477fmwvs3gd6x81dd26bx1212 NarSize: 2481213 References: /nix/var/nix/builds/nix-77474-458540005/TestClientPushesUseOnePush328316627/001/store/8604hvyzqvp6svndha2zyw5jgkrd1vjk-shared-dep1214 CA: text:sha256:1gsiv2246hxqbj0v5qa5vii3zfdv7cxvg6xn7vs7n1rz12isjr1f1215--- PASS: TestClientPushesUseOnePush (5.31s)1216=== CONT TestPresignedUploadRegisteredBeforeCommit12172026/10/01 09:48:02 OK 20241026095416_initial_model.sql (289.84ms)12182026-10-01 09:48:02.490 UTC [78918] ERROR: relation "goose_db_version" does not exist at character 3612192026-10-01 09:48:02.490 UTC [78918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12202026/10/01 09:48:02 OK 20251210153512_drop_unused_gin_index.sql (11.27ms)12212026/10/01 09:48:02 OK 20251218171726_add_pins.sql (29.86ms)12222026/10/01 09:48:02 OK 20260628120000_add_object_size_and_stats.sql (83.38ms)12232026/10/01 09:48:02 INFO Received uploads request method=POST path=/api/pending_closures12242026/10/01 09:48:02 OK 20260905000000_add_claims.sql (85.41ms)12252026/10/01 09:48:02 INFO Received uploads request method=POST path=/api/pending_closures12262026/10/01 09:48:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12272026/10/01 09:48:02 INFO Uploading nifwllhgn3vrq1xf8j4r6q7xkm46k8yv-a (248B)12282026/10/01 09:48:02 INFO Uploading byv4x6dvj5kka363pa5h17sgvqx459k5-shared-dep (136B)12292026/10/01 09:48:02 INFO Received push request method=POST path=/api/pushes12302026/10/01 09:48:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12312026/10/01 09:48:02 WARN Failed to register uploaded object key=9kbzvghf7v6c3pi9pdhvbhp09csxwg72.ls error="server returned 404: 404 page not found\n"12322026/10/01 09:48:02 WARN Failed to register uploaded object key=byv4x6dvj5kka363pa5h17sgvqx459k5.ls error="server returned 404: 404 page not found\n"12332026/10/01 09:48:02 WARN Failed to register uploaded object key=nar/1ij5m6cvjfiljc9f76npwqi19gs2nf6kdqhp9nac315zg58c7g10.nar.zst error="server returned 404: 404 page not found\n"12342026/10/01 09:48:02 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12352026/10/01 09:48:02 INFO Uploading 49k6h5y5iw1qj230l7wrfljvvgmlf3b2-shared-dep (136B)12362026/10/01 09:48:02 INFO Uploading 4jcabrmcqb33cn64lbg454kf03kb72jk-top (256B)12372026/10/01 09:48:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12382026/10/01 09:48:02 WARN Failed to register uploaded object key=nifwllhgn3vrq1xf8j4r6q7xkm46k8yv.ls error="server returned 404: 404 page not found\n"12392026/10/01 09:48:02 INFO Signed narinfos id=1 count=212402026/10/01 09:48:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12412026/10/01 09:48:02 INFO Signed narinfos id=2 count=212422026/10/01 09:48:02 INFO Uploading 4 narinfos12432026/10/01 09:48:02 OK 20260920000000_drop_claims.sql (42.05ms)12442026/10/01 09:48:02 WARN Failed to register uploaded object key=4jcabrmcqb33cn64lbg454kf03kb72jk.ls error="server returned 404: 404 page not found\n"12452026/10/01 09:48:02 OK 20260923120000_add_pushes.sql (19.52ms)12462026/10/01 09:48:02 goose: successfully migrated database to version: 2026092312000012472026/10/01 09:48:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12482026/10/01 09:48:02 WARN Failed to register uploaded object key=49k6h5y5iw1qj230l7wrfljvvgmlf3b2.ls error="server returned 404: 404 page not found\n"12492026/10/01 09:48:02 OK 1_commit_pending_closure.sql (1.02ms)12502026/10/01 09:48:02 OK 2_object_stats_trigger.sql (530.63µs)12512026/10/01 09:48:02 OK 3_commit_push.sql (198.04µs)12522026/10/01 09:48:02 goose: up to current file version: 312532026/10/01 09:48:02 WARN Failed to register uploaded object key=nifwllhgn3vrq1xf8j4r6q7xkm46k8yv.narinfo error="server returned 404: 404 page not found\n"12542026/10/01 09:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12552026/10/01 09:48:02 WARN Failed to register uploaded object key=nar/1j8w30bvsxjy4blylmv21m79kgq9f8p5n444vdxayg0q503pm2ih.nar.zst error="server returned 404: 404 page not found\n"12562026/10/01 09:48:02 INFO Signed narinfos id=1 count=212572026/10/01 09:48:02 INFO Uploading 2 narinfos12582026/10/01 09:48:02 WARN Failed to register uploaded object key=9kbzvghf7v6c3pi9pdhvbhp09csxwg72.narinfo error="server returned 404: 404 page not found\n"12592026/10/01 09:48:02 WARN Failed to register uploaded object key=byv4x6dvj5kka363pa5h17sgvqx459k5.narinfo error="server returned 404: 404 page not found\n"12602026/10/01 09:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete12612026/10/01 09:48:02 WARN Failed to register uploaded object key=49k6h5y5iw1qj230l7wrfljvvgmlf3b2.narinfo error="server returned 404: 404 page not found\n"12622026/10/01 09:48:02 WARN Failed to register uploaded object key=4jcabrmcqb33cn64lbg454kf03kb72jk.narinfo error="server returned 404: 404 page not found\n"12632026/10/01 09:48:02 INFO Upload complete. (211ms)1264=== NAME TestClientSharedPathCommittedMidPush1265 client_integration_test.go:680: Retrieved narinfo from S3:1266 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientSharedPathCommittedMidPush1500434068/001/store/49k6h5y5iw1qj230l7wrfljvvgmlf3b2-shared-dep1267 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1268 Compression: zstd1269 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821270 NarSize: 1361271 References: 1272 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1273 client_integration_test.go:680: Retrieved narinfo from S3:1274 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientSharedPathCommittedMidPush1500434068/001/store/4jcabrmcqb33cn64lbg454kf03kb72jk-top1275 URL: nar/1j8w30bvsxjy4blylmv21m79kgq9f8p5n444vdxayg0q503pm2ih.nar.zst1276 Compression: zstd1277 NarHash: sha256:1j8w30bvsxjy4blylmv21m79kgq9f8p5n444vdxayg0q503pm2ih1278 NarSize: 2561279 References: /nix/var/nix/builds/nix-77474-458540005/TestClientSharedPathCommittedMidPush1500434068/001/store/49k6h5y5iw1qj230l7wrfljvvgmlf3b2-shared-dep1280 CA: text:sha256:1y4yjsajcxsflh2j72v5x9q0qf6458cp1is15n41hwcax9y6iwzl12812026/10/01 09:48:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12822026/10/01 09:48:02 WARN Failed to register uploaded object key=byv4x6dvj5kka363pa5h17sgvqx459k5.narinfo error="server returned 404: 404 page not found\n"12832026/10/01 09:48:02 OK 20241026095416_initial_model.sql (269.99ms)1284=== NAME TestPinProtectsFromGC1285 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-77474-458540005/TestPinProtectsFromGC2593343253/001/store/c85cmzah6629wdj99bgwsmzhly7mhx9d-pinned-file.txt1286 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-77474-458540005/TestPinProtectsFromGC2593343253/001/store/jrmmzjjnjsgaicdlzszmfh5fk9p12n4s-unpinned-file.txt12872026/10/01 09:48:02 OK 20251210153512_drop_unused_gin_index.sql (15.74ms)12882026/10/01 09:48:02 INFO Completed upload id=112892026/10/01 09:48:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12902026/10/01 09:48:02 INFO Completed upload id=212912026/10/01 09:48:02 INFO Upload complete. (344ms)1292=== NAME TestClientFallsBackToClosures1293 client_pushes_test.go:112: Retrieved narinfo from S3:1294 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientFallsBackToClosures2026762168/001/store/byv4x6dvj5kka363pa5h17sgvqx459k5-shared-dep1295 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1296 Compression: zstd1297 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821298 NarSize: 1361299 References: 1300 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1301 client_pushes_test.go:112: Retrieved narinfo from S3:1302 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientFallsBackToClosures2026762168/001/store/nifwllhgn3vrq1xf8j4r6q7xkm46k8yv-a1303 URL: nar/1ij5m6cvjfiljc9f76npwqi19gs2nf6kdqhp9nac315zg58c7g10.nar.zst1304 Compression: zstd1305 NarHash: sha256:1ij5m6cvjfiljc9f76npwqi19gs2nf6kdqhp9nac315zg58c7g101306 NarSize: 2481307 References: /nix/var/nix/builds/nix-77474-458540005/TestClientFallsBackToClosures2026762168/001/store/byv4x6dvj5kka363pa5h17sgvqx459k5-shared-dep1308 CA: text:sha256:1v6mz4xj4y3bcgxvyjchma304wfqk74gdkbffar8q4c1ghh7133w1309 client_pushes_test.go:112: Retrieved narinfo from S3:1310 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientFallsBackToClosures2026762168/001/store/9kbzvghf7v6c3pi9pdhvbhp09csxwg72-b1311 URL: nar/1ij5m6cvjfiljc9f76npwqi19gs2nf6kdqhp9nac315zg58c7g10.nar.zst1312 Compression: zstd1313 NarHash: sha256:1ij5m6cvjfiljc9f76npwqi19gs2nf6kdqhp9nac315zg58c7g101314 NarSize: 2481315 References: /nix/var/nix/builds/nix-77474-458540005/TestClientFallsBackToClosures2026762168/001/store/byv4x6dvj5kka363pa5h17sgvqx459k5-shared-dep1316 CA: text:sha256:1v6mz4xj4y3bcgxvyjchma304wfqk74gdkbffar8q4c1ghh7133w13172026/10/01 09:48:02 OK 20251218171726_add_pins.sql (34.05ms)1318--- PASS: TestClientSharedPathCommittedMidPush (4.99s)1319=== CONT TestGCTaskStore_StartNew1320--- PASS: TestGCTaskStore_StartNew (0.00s)1321=== CONT TestGenerateLandingPage1322--- PASS: TestGenerateLandingPage (0.00s)1323=== CONT TestService_readinessHandler13242026/10/01 09:48:02 OK 20260628120000_add_object_size_and_stats.sql (38.68ms)13252026/10/01 09:48:02 INFO Received push request method=POST path=/api/pushes1326--- PASS: TestClientFallsBackToClosures (6.02s)1327=== CONT TestService_healthCheckHandler13282026/10/01 09:48:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13292026/10/01 09:48:03 INFO Uploading c85cmzah6629wdj99bgwsmzhly7mhx9d-pinned-file.txt (128B)13302026/10/01 09:48:03 WARN Failed to register uploaded object key=c85cmzah6629wdj99bgwsmzhly7mhx9d.ls error="server returned 404: 404 page not found\n"13312026/10/01 09:48:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13322026/10/01 09:48:03 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13332026/10/01 09:48:03 INFO Signed narinfos id=1 count=113342026/10/01 09:48:03 INFO Uploading 1 narinfos13352026/10/01 09:48:03 OK 20260905000000_add_claims.sql (77.5ms)13362026/10/01 09:48:03 INFO Received complete push request method=POST path=/api/pushes/1/complete13372026/10/01 09:48:03 WARN Failed to register uploaded object key=c85cmzah6629wdj99bgwsmzhly7mhx9d.narinfo error="server returned 404: 404 page not found\n"13382026-10-01 09:48:03.076 UTC [78965] ERROR: relation "goose_db_version" does not exist at character 3613392026-10-01 09:48:03.076 UTC [78965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13402026/10/01 09:48:03 INFO Upload complete. (176ms)13412026/10/01 09:48:03 OK 20260920000000_drop_claims.sql (79.8ms)1342--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (6.17s)1343=== CONT TestGracefulShutdownDrainsInflight13442026/10/01 09:48:03 INFO Starting HTTP server address=127.0.0.1:5267113452026/10/01 09:48:03 INFO Shutdown signal received, draining in-flight requests timeout=10s13462026/10/01 09:48:03 INFO Received uploads request method=POST path=/api/pending_closures13472026/10/01 09:48:03 OK 20260923120000_add_pushes.sql (16.47ms)13482026/10/01 09:48:03 goose: successfully migrated database to version: 2026092312000013492026/10/01 09:48:03 OK 1_commit_pending_closure.sql (917.58µs)13502026/10/01 09:48:03 OK 2_object_stats_trigger.sql (255.88µs)13512026/10/01 09:48:03 OK 3_commit_push.sql (185.92µs)13522026/10/01 09:48:03 goose: up to current file version: 31353--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1354=== CONT TestGCTaskStore_Fail1355--- PASS: TestGCTaskStore_Fail (0.00s)1356=== CONT TestGCTaskStore_PhaseUpdates1357--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1358=== CONT TestGCTaskStore_CompletedAllowsNewTask1359--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1360=== CONT TestGCTaskStore_GetReturnsLatest1361--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1362=== CONT TestGCTaskStore_GetEmpty1363--- PASS: TestGCTaskStore_GetEmpty (0.00s)1364=== CONT TestGCTaskStore_ConflictDifferentParams1365--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1366=== CONT TestGCTaskStore_DeduplicateSameParams1367--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1368=== CONT TestReadProxyNarinfoAlreadyDecompressed13692026/10/01 09:48:03 INFO Received push request method=POST path=/api/pushes13702026/10/01 09:48:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13712026/10/01 09:48:03 INFO Uploading jrmmzjjnjsgaicdlzszmfh5fk9p12n4s-unpinned-file.txt (128B)13722026/10/01 09:48:03 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13732026/10/01 09:48:03 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13742026/10/01 09:48:03 WARN Failed to register uploaded object key=jrmmzjjnjsgaicdlzszmfh5fk9p12n4s.ls error="server returned 404: 404 page not found\n"13752026/10/01 09:48:03 INFO Signed narinfos id=2 count=113762026/10/01 09:48:03 INFO Uploading 1 narinfos13772026/10/01 09:48:03 INFO Received complete push request method=POST path=/api/pushes/2/complete13782026/10/01 09:48:03 WARN Failed to register uploaded object key=jrmmzjjnjsgaicdlzszmfh5fk9p12n4s.narinfo error="server returned 404: 404 page not found\n"13792026/10/01 09:48:03 INFO Upload complete. (172ms)13802026/10/01 09:48:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures13812026/10/01 09:48:03 INFO Garbage collection started13822026/10/01 09:48:03 INFO Aborted multipart uploads count=013832026/10/01 09:48:03 WARN Force mode enabled - objects will be deleted immediately without grace period13842026/10/01 09:48:03 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=013852026/10/01 09:48:03 OK 20241026095416_initial_model.sql (331.22ms)13862026/10/01 09:48:03 OK 20251210153512_drop_unused_gin_index.sql (15.92ms)13872026/10/01 09:48:03 INFO Vacuumed table table=pending_closures13882026/10/01 09:48:03 INFO Received uploads request method=POST path=/api/pending_closures13892026/10/01 09:48:03 INFO Received uploads request method=POST path=/api/pending_closures13902026/10/01 09:48:03 INFO Received uploads request method=POST path=/api/pending_closures13912026/10/01 09:48:03 OK 20251218171726_add_pins.sql (50.49ms)13922026/10/01 09:48:03 INFO Vacuumed table table=pending_objects13932026/10/01 09:48:03 INFO Vacuumed table table=multipart_uploads13942026/10/01 09:48:03 INFO Vacuumed table table=closures13952026/10/01 09:48:03 OK 20260628120000_add_object_size_and_stats.sql (82.82ms)13962026/10/01 09:48:03 INFO Vacuumed table table=objects13972026/10/01 09:48:03 OK 20260905000000_add_claims.sql (68.8ms)13982026/10/01 09:48:03 OK 20260920000000_drop_claims.sql (56.43ms)13992026-10-01 09:48:03.788 UTC [79013] ERROR: relation "goose_db_version" does not exist at character 3614002026-10-01 09:48:03.788 UTC [79013] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14012026/10/01 09:48:03 OK 20260923120000_add_pushes.sql (17.08ms)14022026/10/01 09:48:03 goose: successfully migrated database to version: 2026092312000014032026/10/01 09:48:03 OK 1_commit_pending_closure.sql (1.87ms)14042026/10/01 09:48:03 OK 2_object_stats_trigger.sql (235.71µs)14052026/10/01 09:48:03 OK 3_commit_push.sql (195.88µs)14062026/10/01 09:48:03 goose: up to current file version: 314072026-10-01 09:48:04.105 UTC [79029] ERROR: relation "goose_db_version" does not exist at character 3614082026-10-01 09:48:04.105 UTC [79029] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14092026/10/01 09:48:04 OK 20241026095416_initial_model.sql (263.4ms)14102026/10/01 09:48:04 OK 20251210153512_drop_unused_gin_index.sql (16.82ms)14112026/10/01 09:48:04 INFO Received cleanup request method=DELETE path=/api/pending_closures14122026/10/01 09:48:04 INFO Aborted multipart uploads count=014132026/10/01 09:48:04 INFO Received uploads request method=POST path=/api/pending_closures14142026/10/01 09:48:04 OK 20251218171726_add_pins.sql (46.25ms)14152026/10/01 09:48:04 INFO Received cleanup request method=DELETE path=/api/pending_closures14162026/10/01 09:48:04 OK 20260628120000_add_object_size_and_stats.sql (67.96ms)14172026/10/01 09:48:04 INFO Aborted multipart uploads count=114182026/10/01 09:48:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14192026-10-01 09:48:04.316 UTC [78965] ERROR: Closure does not exist: id=114202026-10-01 09:48:04.316 UTC [78965] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE14212026-10-01 09:48:04.316 UTC [78965] STATEMENT: -- name: CommitPendingClosure :exec1422 SELECT commit_pending_closure($1::bigint)1423 1424--- PASS: TestService_cleanupPendingClosuresHandler (4.69s)1425=== CONT TestReadProxyConditionalGet14262026/10/01 09:48:04 OK 20241026095416_initial_model.sql (210.25ms)14272026/10/01 09:48:04 OK 20260905000000_add_claims.sql (129.29ms)14282026/10/01 09:48:04 OK 20251210153512_drop_unused_gin_index.sql (19.47ms)14292026/10/01 09:48:04 OK 20260920000000_drop_claims.sql (30.22ms)14302026/10/01 09:48:04 OK 20251218171726_add_pins.sql (53.38ms)14312026/10/01 09:48:04 OK 20260923120000_add_pushes.sql (43.24ms)14322026/10/01 09:48:04 goose: successfully migrated database to version: 2026092312000014332026/10/01 09:48:04 OK 1_commit_pending_closure.sql (2.2ms)14342026/10/01 09:48:04 OK 2_object_stats_trigger.sql (451.33µs)14352026/10/01 09:48:04 OK 3_commit_push.sql (230.21µs)14362026/10/01 09:48:04 goose: up to current file version: 314372026/10/01 09:48:04 OK 20260628120000_add_object_size_and_stats.sql (71.31ms)14382026/10/01 09:48:04 OK 20260905000000_add_claims.sql (79.19ms)14392026/10/01 09:48:04 OK 20260920000000_drop_claims.sql (94.03ms)14402026/10/01 09:48:04 OK 20260923120000_add_pushes.sql (45.95ms)14412026/10/01 09:48:04 goose: successfully migrated database to version: 2026092312000014422026/10/01 09:48:04 OK 1_commit_pending_closure.sql (1.27ms)14432026/10/01 09:48:04 OK 2_object_stats_trigger.sql (313.71µs)14442026/10/01 09:48:04 OK 3_commit_push.sql (235.58µs)14452026/10/01 09:48:04 goose: up to current file version: 314462026/10/01 09:48:04 INFO Received uploads request method=POST path=/api/pending_closures14472026/10/01 09:48:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14482026/10/01 09:48:05 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=014492026/10/01 09:48:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14502026/10/01 09:48:05 INFO Received create pin request method=POST path=/api/pins/myapp1451--- PASS: TestService_Rustfstest (4.63s)1452=== CONT TestReadProxyHead14532026/10/01 09:48:05 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-77474-458540005/TestPinProtectsFromGC2593343253/001/store/c85cmzah6629wdj99bgwsmzhly7mhx9d-pinned-file.txt narinfo_key=c85cmzah6629wdj99bgwsmzhly7mhx9d.narinfo14542026/10/01 09:48:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures14552026/10/01 09:48:05 INFO Garbage collection started14562026/10/01 09:48:05 INFO Aborted multipart uploads count=014572026/10/01 09:48:05 WARN Force mode enabled - objects will be deleted immediately without grace period14582026/10/01 09:48:05 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=014592026/10/01 09:48:05 INFO Vacuumed table table=pending_closures14602026/10/01 09:48:05 INFO Vacuumed table table=pending_objects14612026/10/01 09:48:05 INFO Vacuumed table table=multipart_uploads14622026/10/01 09:48:05 INFO Vacuumed table table=closures14632026/10/01 09:48:05 INFO Vacuumed table table=objects14642026/10/01 09:48:05 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTIxMTFiYmYtNmIxNi00OGU2LWJhZTUtNjliOTNmY2JiZDg0LmY1YTI2OWUzLTI1MWQtNGNmMC04ZjhiLTRhNmJiOTBiY2FkNHgxNzkwODQ4MDgzNTk3NzM1MDAw parts=1014652026/10/01 09:48:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14662026/10/01 09:48:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14672026/10/01 09:48:05 INFO Completed upload id=114682026/10/01 09:48:05 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTIxMTFiYmYtNmIxNi00OGU2LWJhZTUtNjliOTNmY2JiZDg0LmRlNTk3NDlhLWU5NmMtNGY5Yy1iM2MzLWJkMTBjYWU1M2RlZHgxNzkwODQ4MDgzMTkwNjQ5MDAw parts=1214692026/10/01 09:48:05 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014702026/10/01 09:48:05 INFO Received uploads request method=POST path=/api/pending_closures14712026/10/01 09:48:05 INFO Received uploads request method=POST path=/api/pending_closures14722026/10/01 09:48:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures1473--- PASS: TestCompletedNarNotReofferedAcrossClosures (6.83s)1474=== CONT TestReadProxyInvalidPath14752026/10/01 09:48:05 INFO Aborted multipart uploads count=014762026/10/01 09:48:05 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=014772026/10/01 09:48:05 INFO Vacuumed table table=pending_closures14782026/10/01 09:48:05 INFO Vacuumed table table=pending_objects14792026/10/01 09:48:05 INFO Vacuumed table table=multipart_uploads14802026/10/01 09:48:05 INFO Vacuumed table table=closures14812026/10/01 09:48:05 INFO Vacuumed table table=objects14822026-10-01 09:48:05.553 UTC [79057] ERROR: relation "goose_db_version" does not exist at character 3614832026-10-01 09:48:05.553 UTC [79057] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14842026/10/01 09:48:05 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001485--- PASS: TestService_createPendingClosureHandler (6.63s)1486=== CONT TestReadProxy40414872026/10/01 09:48:05 OK 20241026095416_initial_model.sql (103.34ms)14882026/10/01 09:48:05 OK 20251210153512_drop_unused_gin_index.sql (8.86ms)14892026/10/01 09:48:05 OK 20251218171726_add_pins.sql (21ms)14902026-10-01 09:48:05.732 UTC [79062] ERROR: relation "goose_db_version" does not exist at character 3614912026-10-01 09:48:05.732 UTC [79062] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14922026-10-01 09:48:05.762 UTC [79063] ERROR: relation "goose_db_version" does not exist at character 3614932026-10-01 09:48:05.762 UTC [79063] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14942026/10/01 09:48:05 OK 20260628120000_add_object_size_and_stats.sql (39.47ms)14952026/10/01 09:48:05 OK 20260905000000_add_claims.sql (30.72ms)14962026/10/01 09:48:05 OK 20260920000000_drop_claims.sql (4.16ms)14972026/10/01 09:48:05 OK 20260923120000_add_pushes.sql (8.16ms)14982026/10/01 09:48:05 goose: successfully migrated database to version: 2026092312000014992026/10/01 09:48:05 OK 1_commit_pending_closure.sql (1.08ms)15002026/10/01 09:48:05 OK 2_object_stats_trigger.sql (230.21µs)15012026/10/01 09:48:05 OK 3_commit_push.sql (169.58µs)15022026/10/01 09:48:05 goose: up to current file version: 315032026-10-01 09:48:05.845 UTC [79065] ERROR: relation "goose_db_version" does not exist at character 3615042026-10-01 09:48:05.845 UTC [79065] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15052026/10/01 09:48:05 OK 20241026095416_initial_model.sql (91.35ms)15062026/10/01 09:48:05 OK 20251210153512_drop_unused_gin_index.sql (8.99ms)15072026/10/01 09:48:05 OK 20251218171726_add_pins.sql (20.21ms)15082026/10/01 09:48:05 OK 20241026095416_initial_model.sql (102.65ms)15092026/10/01 09:48:05 OK 20251210153512_drop_unused_gin_index.sql (7.97ms)15102026/10/01 09:48:05 OK 20251218171726_add_pins.sql (13.49ms)15112026/10/01 09:48:05 OK 20260628120000_add_object_size_and_stats.sql (30.81ms)15122026/10/01 09:48:05 OK 20260628120000_add_object_size_and_stats.sql (47.17ms)15132026/10/01 09:48:06 OK 20260905000000_add_claims.sql (77.39ms)15142026/10/01 09:48:06 OK 20260905000000_add_claims.sql (53.49ms)15152026/10/01 09:48:06 OK 20260920000000_drop_claims.sql (39.81ms)15162026/10/01 09:48:06 OK 20260920000000_drop_claims.sql (30.4ms)15172026/10/01 09:48:06 OK 20260923120000_add_pushes.sql (12.41ms)15182026/10/01 09:48:06 goose: successfully migrated database to version: 2026092312000015192026/10/01 09:48:06 OK 1_commit_pending_closure.sql (1.65ms)15202026/10/01 09:48:06 OK 2_object_stats_trigger.sql (271.33µs)15212026/10/01 09:48:06 OK 3_commit_push.sql (240.58µs)15222026/10/01 09:48:06 goose: up to current file version: 315232026/10/01 09:48:06 OK 20260923120000_add_pushes.sql (9.96ms)15242026/10/01 09:48:06 goose: successfully migrated database to version: 2026092312000015252026/10/01 09:48:06 OK 1_commit_pending_closure.sql (837.75µs)15262026/10/01 09:48:06 OK 20241026095416_initial_model.sql (163.38ms)15272026/10/01 09:48:06 OK 2_object_stats_trigger.sql (692.75µs)15282026/10/01 09:48:06 OK 3_commit_push.sql (486.29µs)15292026/10/01 09:48:06 goose: up to current file version: 315302026/10/01 09:48:06 OK 20251210153512_drop_unused_gin_index.sql (7.21ms)15312026/10/01 09:48:06 INFO Received uploads request method=POST path=/api/pending_closures15322026/10/01 09:48:06 OK 20251218171726_add_pins.sql (76.74ms)15332026/10/01 09:48:06 OK 20260628120000_add_object_size_and_stats.sql (38.76ms)15342026/10/01 09:48:06 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15352026/10/01 09:48:06 INFO Received uploads request method=POST path=/api/pending_closures1536--- PASS: TestPresignedUploadRegisteredBeforeCommit (3.89s)1537=== CONT TestReadProxyNarStreaming15382026/10/01 09:48:06 OK 20260905000000_add_claims.sql (98.37ms)15392026/10/01 09:48:06 OK 20260920000000_drop_claims.sql (39.06ms)15402026/10/01 09:48:06 OK 20260923120000_add_pushes.sql (31.93ms)15412026/10/01 09:48:06 goose: successfully migrated database to version: 2026092312000015422026/10/01 09:48:06 OK 1_commit_pending_closure.sql (1.16ms)15432026/10/01 09:48:06 OK 2_object_stats_trigger.sql (226.29µs)15442026/10/01 09:48:06 OK 3_commit_push.sql (195.96µs)15452026/10/01 09:48:06 goose: up to current file version: 315462026/10/01 09:48:06 WARN readiness check failed error="closed pool"1547--- PASS: TestService_readinessHandler (3.49s)1548=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1549--- PASS: TestService_healthCheckHandler (3.76s)1550=== CONT TestCreatePin_ReservedPins15512026/10/01 09:48:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52812/oidc15522026-10-01 09:48:07.021 UTC [79079] ERROR: relation "goose_db_version" does not exist at character 3615532026-10-01 09:48:07.021 UTC [79079] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1554--- PASS: TestReadProxyNarinfoAlreadyDecompressed (3.93s)1555=== CONT TestOrphanedObjectsGCStressTest15562026/10/01 09:48:07 OK 20241026095416_initial_model.sql (200.14ms)15572026/10/01 09:48:07 OK 20251210153512_drop_unused_gin_index.sql (16.09ms)15582026/10/01 09:48:07 OK 20251218171726_add_pins.sql (25.14ms)15592026/10/01 09:48:07 OK 20260628120000_add_object_size_and_stats.sql (19.42ms)15602026/10/01 09:48:07 OK 20260905000000_add_claims.sql (12.34ms)15612026/10/01 09:48:07 OK 20260920000000_drop_claims.sql (12.11ms)15622026-10-01 09:48:07.367 UTC [79082] ERROR: relation "goose_db_version" does not exist at character 3615632026-10-01 09:48:07.367 UTC [79082] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15642026/10/01 09:48:07 OK 20260923120000_add_pushes.sql (40.95ms)15652026/10/01 09:48:07 goose: successfully migrated database to version: 2026092312000015662026/10/01 09:48:07 OK 1_commit_pending_closure.sql (2ms)15672026/10/01 09:48:07 OK 2_object_stats_trigger.sql (528.5µs)15682026/10/01 09:48:07 OK 3_commit_push.sql (339.21µs)15692026/10/01 09:48:07 goose: up to current file version: 315702026-10-01 09:48:07.428 UTC [79083] ERROR: relation "goose_db_version" does not exist at character 3615712026-10-01 09:48:07.428 UTC [79083] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1572=== NAME TestPinProtectsFromGC1573 client_integration_test.go:840: Pin successfully protected closure from garbage collection1574--- PASS: TestPinProtectsFromGC (9.85s)1575=== CONT TestOrphanedObjectsGC15762026-10-01 09:48:07.523 UTC [79085] ERROR: relation "goose_db_version" does not exist at character 3615772026-10-01 09:48:07.523 UTC [79085] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15782026/10/01 09:48:07 OK 20241026095416_initial_model.sql (116.54ms)15792026/10/01 09:48:07 OK 20251210153512_drop_unused_gin_index.sql (14.4ms)15802026/10/01 09:48:07 OK 20251218171726_add_pins.sql (15.85ms)15812026/10/01 09:48:07 OK 20260628120000_add_object_size_and_stats.sql (27.76ms)15822026/10/01 09:48:07 OK 20241026095416_initial_model.sql (191.72ms)15832026/10/01 09:48:07 OK 20260905000000_add_claims.sql (84.26ms)15842026/10/01 09:48:07 OK 20251210153512_drop_unused_gin_index.sql (12.23ms)15852026/10/01 09:48:07 OK 20260920000000_drop_claims.sql (45.36ms)15862026/10/01 09:48:07 OK 20251218171726_add_pins.sql (42.55ms)15872026/10/01 09:48:07 OK 20260923120000_add_pushes.sql (10.24ms)15882026/10/01 09:48:07 goose: successfully migrated database to version: 2026092312000015892026/10/01 09:48:07 OK 1_commit_pending_closure.sql (3.29ms)15902026/10/01 09:48:07 OK 2_object_stats_trigger.sql (2.78ms)15912026/10/01 09:48:07 OK 3_commit_push.sql (544.46µs)15922026/10/01 09:48:07 goose: up to current file version: 31593--- PASS: TestReadProxyConditionalGet (3.44s)1594=== CONT TestObjectStatsTrigger15952026/10/01 09:48:07 OK 20260628120000_add_object_size_and_stats.sql (46.31ms)15962026/10/01 09:48:07 OK 20241026095416_initial_model.sql (185.59ms)15972026/10/01 09:48:07 OK 20251210153512_drop_unused_gin_index.sql (14.21ms)15982026/10/01 09:48:07 OK 20251218171726_add_pins.sql (42.73ms)15992026/10/01 09:48:07 OK 20260905000000_add_claims.sql (82.67ms)16002026/10/01 09:48:07 OK 20260628120000_add_object_size_and_stats.sql (74.72ms)16012026/10/01 09:48:07 OK 20260920000000_drop_claims.sql (72.44ms)16022026/10/01 09:48:07 OK 20260923120000_add_pushes.sql (24.35ms)16032026/10/01 09:48:07 goose: successfully migrated database to version: 2026092312000016042026/10/01 09:48:07 OK 1_commit_pending_closure.sql (4.97ms)16052026/10/01 09:48:07 OK 2_object_stats_trigger.sql (772.38µs)16062026/10/01 09:48:07 OK 3_commit_push.sql (545.21µs)16072026/10/01 09:48:07 goose: up to current file version: 316082026/10/01 09:48:07 OK 20260905000000_add_claims.sql (55.33ms)16092026/10/01 09:48:07 OK 20260920000000_drop_claims.sql (21.08ms)16102026/10/01 09:48:08 OK 20260923120000_add_pushes.sql (27.84ms)16112026/10/01 09:48:08 goose: successfully migrated database to version: 2026092312000016122026/10/01 09:48:08 OK 1_commit_pending_closure.sql (2.94ms)16132026/10/01 09:48:08 OK 2_object_stats_trigger.sql (712.79µs)16142026/10/01 09:48:08 OK 3_commit_push.sql (444.75µs)16152026/10/01 09:48:08 goose: up to current file version: 31616--- PASS: TestReadProxyHead (2.76s)1617=== CONT TestPendingCleanupUsesOneCutoff1618--- PASS: TestReadProxyInvalidPath (3.03s)1619=== CONT TestPush_CompleteCommitsEveryRoot1620--- PASS: TestReadProxy404 (3.45s)1621=== CONT TestCompleteMultipartUpload_ErrorButObjectExists16222026-10-01 09:48:09.172 UTC [79111] ERROR: relation "goose_db_version" does not exist at character 3616232026-10-01 09:48:09.172 UTC [79111] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16242026-10-01 09:48:09.451 UTC [79114] ERROR: relation "goose_db_version" does not exist at character 3616252026-10-01 09:48:09.451 UTC [79114] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16262026/10/01 09:48:09 OK 20241026095416_initial_model.sql (247.48ms)16272026/10/01 09:48:09 OK 20251210153512_drop_unused_gin_index.sql (5.37ms)16282026/10/01 09:48:09 OK 20251218171726_add_pins.sql (25.37ms)16292026/10/01 09:48:09 OK 20260628120000_add_object_size_and_stats.sql (67.67ms)16302026/10/01 09:48:09 OK 20260905000000_add_claims.sql (69.14ms)16312026/10/01 09:48:09 OK 20241026095416_initial_model.sql (174.19ms)16322026/10/01 09:48:09 OK 20260920000000_drop_claims.sql (13.87ms)16332026/10/01 09:48:09 OK 20251210153512_drop_unused_gin_index.sql (5.47ms)16342026/10/01 09:48:09 OK 20260923120000_add_pushes.sql (5.49ms)16352026/10/01 09:48:09 goose: successfully migrated database to version: 2026092312000016362026/10/01 09:48:09 OK 20251218171726_add_pins.sql (7.37ms)16372026-10-01 09:48:09.704 UTC [79119] ERROR: relation "goose_db_version" does not exist at character 3616382026-10-01 09:48:09.704 UTC [79119] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16392026/10/01 09:48:09 OK 1_commit_pending_closure.sql (5.68ms)16402026/10/01 09:48:09 OK 2_object_stats_trigger.sql (1.13ms)16412026-10-01 09:48:09.706 UTC [79120] ERROR: relation "goose_db_version" does not exist at character 3616422026-10-01 09:48:09.706 UTC [79120] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16432026/10/01 09:48:09 OK 3_commit_push.sql (855.63µs)16442026/10/01 09:48:09 goose: up to current file version: 316452026/10/01 09:48:09 OK 20260628120000_add_object_size_and_stats.sql (10.38ms)16462026/10/01 09:48:09 OK 20260905000000_add_claims.sql (106.85ms)16472026/10/01 09:48:09 OK 20260920000000_drop_claims.sql (64.47ms)16482026/10/01 09:48:09 OK 20260923120000_add_pushes.sql (17.98ms)16492026/10/01 09:48:09 goose: successfully migrated database to version: 2026092312000016502026/10/01 09:48:09 OK 1_commit_pending_closure.sql (4.51ms)16512026/10/01 09:48:09 OK 2_object_stats_trigger.sql (1.42ms)16522026/10/01 09:48:09 OK 3_commit_push.sql (704.17µs)16532026/10/01 09:48:09 goose: up to current file version: 316542026/10/01 09:48:09 OK 20241026095416_initial_model.sql (201.29ms)16552026/10/01 09:48:09 OK 20241026095416_initial_model.sql (209.72ms)16562026/10/01 09:48:10 OK 20251210153512_drop_unused_gin_index.sql (20.95ms)16572026/10/01 09:48:10 OK 20251210153512_drop_unused_gin_index.sql (15.84ms)16582026/10/01 09:48:10 OK 20251218171726_add_pins.sql (34.85ms)16592026/10/01 09:48:10 OK 20251218171726_add_pins.sql (38.09ms)16602026/10/01 09:48:10 OK 20260628120000_add_object_size_and_stats.sql (37.18ms)16612026/10/01 09:48:10 OK 20260628120000_add_object_size_and_stats.sql (39.27ms)16622026/10/01 09:48:10 WARN Rate limiter enabled after throttle name=s3-test rate=516632026/10/01 09:48:10 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1664=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1665 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101666 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001667--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.89s)1668=== CONT TestRedundantMultipartUpload16692026/10/01 09:48:10 OK 20260905000000_add_claims.sql (104.6ms)1670--- PASS: TestReadProxyNarStreaming (4.00s)1671=== CONT TestPush_SignsNarinfosOfItsPendingObjects16722026/10/01 09:48:10 OK 20260905000000_add_claims.sql (108.66ms)16732026/10/01 09:48:10 OK 20260920000000_drop_claims.sql (77.26ms)16742026/10/01 09:48:10 OK 20260920000000_drop_claims.sql (83.42ms)16752026/10/01 09:48:10 OK 20260923120000_add_pushes.sql (28.76ms)16762026/10/01 09:48:10 goose: successfully migrated database to version: 2026092312000016772026/10/01 09:48:10 OK 1_commit_pending_closure.sql (1.5ms)16782026/10/01 09:48:10 OK 2_object_stats_trigger.sql (355.67µs)16792026/10/01 09:48:10 OK 3_commit_push.sql (290.83µs)16802026/10/01 09:48:10 goose: up to current file version: 316812026/10/01 09:48:10 OK 20260923120000_add_pushes.sql (36.98ms)16822026/10/01 09:48:10 goose: successfully migrated database to version: 2026092312000016832026/10/01 09:48:10 OK 1_commit_pending_closure.sql (1.53ms)16842026/10/01 09:48:10 OK 2_object_stats_trigger.sql (346.08µs)16852026/10/01 09:48:10 OK 3_commit_push.sql (258.71µs)16862026/10/01 09:48:10 goose: up to current file version: 316872026/10/01 09:48:10 INFO Received uploads request method=POST path=/api/pending_closures1688--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.27s)1689=== CONT TestPush_RejectsBadRequests16902026-10-01 09:48:10.752 UTC [79178] ERROR: relation "goose_db_version" does not exist at character 3616912026-10-01 09:48:10.752 UTC [79178] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16922026/10/01 09:48:11 OK 20241026095416_initial_model.sql (275.03ms)16932026/10/01 09:48:11 OK 20251210153512_drop_unused_gin_index.sql (28.53ms)16942026/10/01 09:48:11 OK 20251218171726_add_pins.sql (55.54ms)16952026/10/01 09:48:11 OK 20260628120000_add_object_size_and_stats.sql (64.43ms)16962026-10-01 09:48:11.356 UTC [79200] ERROR: relation "goose_db_version" does not exist at character 3616972026-10-01 09:48:11.356 UTC [79200] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16982026/10/01 09:48:11 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux16992026/10/01 09:48:11 WARN Refused reserved pin name=worker-x86_64-linux17002026/10/01 09:48:11 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17012026/10/01 09:48:11 INFO Received create pin request method=POST path=/api/pins/my-app17022026/10/01 09:48:11 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1703--- PASS: TestCreatePin_ReservedPins (4.62s)1704=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit17052026/10/01 09:48:11 OK 20260905000000_add_claims.sql (112.04ms)17062026/10/01 09:48:11 OK 20260920000000_drop_claims.sql (74.42ms)17072026/10/01 09:48:11 OK 20260923120000_add_pushes.sql (20.9ms)17082026/10/01 09:48:11 goose: successfully migrated database to version: 2026092312000017092026/10/01 09:48:11 OK 1_commit_pending_closure.sql (2.14ms)17102026/10/01 09:48:11 OK 2_object_stats_trigger.sql (506.5µs)17112026/10/01 09:48:11 OK 3_commit_push.sql (404.21µs)17122026/10/01 09:48:11 goose: up to current file version: 317132026/10/01 09:48:11 OK 20241026095416_initial_model.sql (359.28ms)17142026/10/01 09:48:11 OK 20251210153512_drop_unused_gin_index.sql (18.03ms)17152026/10/01 09:48:11 OK 20251218171726_add_pins.sql (75.38ms)17162026/10/01 09:48:11 OK 20260628120000_add_object_size_and_stats.sql (65.06ms)17172026-10-01 09:48:12.095 UTC [79208] ERROR: relation "goose_db_version" does not exist at character 3617182026-10-01 09:48:12.095 UTC [79208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17192026/10/01 09:48:12 OK 20260905000000_add_claims.sql (111.1ms)17202026/10/01 09:48:12 OK 20260920000000_drop_claims.sql (29.61ms)17212026/10/01 09:48:12 OK 20260923120000_add_pushes.sql (31.37ms)17222026/10/01 09:48:12 goose: successfully migrated database to version: 2026092312000017232026/10/01 09:48:12 OK 1_commit_pending_closure.sql (5.68ms)17242026/10/01 09:48:12 OK 2_object_stats_trigger.sql (984µs)17252026/10/01 09:48:12 OK 3_commit_push.sql (479.96µs)17262026/10/01 09:48:12 goose: up to current file version: 317272026-10-01 09:48:12.354 UTC [79212] ERROR: relation "goose_db_version" does not exist at character 3617282026-10-01 09:48:12.354 UTC [79212] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17292026/10/01 09:48:12 OK 20241026095416_initial_model.sql (301.06ms)17302026/10/01 09:48:12 OK 20251210153512_drop_unused_gin_index.sql (23.6ms)17312026/10/01 09:48:12 OK 20251218171726_add_pins.sql (55.48ms)17322026/10/01 09:48:12 OK 20260628120000_add_object_size_and_stats.sql (55.61ms)17332026-10-01 09:48:12.640 UTC [79216] ERROR: relation "goose_db_version" does not exist at character 3617342026-10-01 09:48:12.640 UTC [79216] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1735--- PASS: TestObjectStatsTrigger (4.88s)1736=== CONT TestService_NativeMTLS17372026/10/01 09:48:12 OK 20260905000000_add_claims.sql (80.94ms)17382026/10/01 09:48:12 OK 20241026095416_initial_model.sql (245.78ms)17392026/10/01 09:48:12 OK 20251210153512_drop_unused_gin_index.sql (18.22ms)17402026/10/01 09:48:12 OK 20260920000000_drop_claims.sql (68.54ms)17412026/10/01 09:48:12 OK 20251218171726_add_pins.sql (50.75ms)17422026/10/01 09:48:12 OK 20260923120000_add_pushes.sql (21.49ms)17432026/10/01 09:48:12 goose: successfully migrated database to version: 2026092312000017442026/10/01 09:48:12 OK 1_commit_pending_closure.sql (1.41ms)17452026/10/01 09:48:12 OK 2_object_stats_trigger.sql (310.13µs)17462026/10/01 09:48:12 OK 3_commit_push.sql (287.46µs)17472026/10/01 09:48:12 goose: up to current file version: 317482026/10/01 09:48:12 OK 20260628120000_add_object_size_and_stats.sql (62.12ms)17492026/10/01 09:48:12 OK 20260905000000_add_claims.sql (134.8ms)17502026/10/01 09:48:13 OK 20260920000000_drop_claims.sql (49.62ms)17512026/10/01 09:48:13 OK 20260923120000_add_pushes.sql (52.97ms)17522026/10/01 09:48:13 goose: successfully migrated database to version: 2026092312000017532026/10/01 09:48:13 OK 1_commit_pending_closure.sql (5.6ms)17542026/10/01 09:48:13 OK 2_object_stats_trigger.sql (986.42µs)17552026/10/01 09:48:13 OK 3_commit_push.sql (578.17µs)17562026/10/01 09:48:13 goose: up to current file version: 317572026/10/01 09:48:13 OK 20241026095416_initial_model.sql (347.78ms)17582026/10/01 09:48:13 OK 20251210153512_drop_unused_gin_index.sql (19.69ms)1759=== NAME TestOrphanedObjectsGC1760 orphaned_objects_gc_test.go:290: GC Test Summary:1761 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1762 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1763 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1764 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1765 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1766--- PASS: TestOrphanedObjectsGC (5.66s)1767=== CONT TestMultipartCleanup17682026/10/01 09:48:13 OK 20251218171726_add_pins.sql (72.86ms)17692026/10/01 09:48:13 OK 20260628120000_add_object_size_and_stats.sql (62.47ms)17702026/10/01 09:48:13 INFO Received uploads request method=POST path=/api/pending_closures17712026/10/01 09:48:13 OK 20260905000000_add_claims.sql (123.35ms)17722026/10/01 09:48:13 INFO Received uploads request method=POST path=/api/pending_closures17732026/10/01 09:48:13 OK 20260920000000_drop_claims.sql (128.85ms)17742026/10/01 09:48:13 OK 20260923120000_add_pushes.sql (35.77ms)17752026/10/01 09:48:13 goose: successfully migrated database to version: 2026092312000017762026/10/01 09:48:13 OK 1_commit_pending_closure.sql (2.96ms)17772026/10/01 09:48:13 OK 2_object_stats_trigger.sql (586.83µs)17782026/10/01 09:48:13 OK 3_commit_push.sql (391.25µs)17792026/10/01 09:48:13 goose: up to current file version: 317802026/10/01 09:48:13 INFO Received cleanup request method=DELETE path=/api/pending_closures17812026-10-01 09:48:13.838 UTC [79237] ERROR: relation "goose_db_version" does not exist at character 3617822026-10-01 09:48:13.838 UTC [79237] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17832026-10-01 09:48:13.843 UTC [79236] ERROR: relation "goose_db_version" does not exist at character 3617842026-10-01 09:48:13.843 UTC [79236] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17852026/10/01 09:48:13 INFO Received push request method=POST path=/api/pushes17862026/10/01 09:48:13 INFO Received complete push request method=POST path=/api/pushes/1/complete1787--- PASS: TestPush_CompleteCommitsEveryRoot (5.52s)1788=== CONT TestServerTLSConfig1789=== RUN TestServerTLSConfig/no_client_CA1790=== PAUSE TestServerTLSConfig/no_client_CA1791=== RUN TestServerTLSConfig/missing_CA_file1792=== PAUSE TestServerTLSConfig/missing_CA_file1793=== RUN TestServerTLSConfig/not_a_PEM_file1794=== PAUSE TestServerTLSConfig/not_a_PEM_file1795=== CONT TestProxyHeadersOnlyTrustedOnSocket17962026-10-01 09:48:14.199 UTC [79247] ERROR: relation "goose_db_version" does not exist at character 3617972026-10-01 09:48:14.199 UTC [79247] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17982026/10/01 09:48:14 OK 20241026095416_initial_model.sql (296.24ms)17992026/10/01 09:48:14 OK 20241026095416_initial_model.sql (294.5ms)18002026/10/01 09:48:14 OK 20251210153512_drop_unused_gin_index.sql (14.74ms)18012026/10/01 09:48:14 OK 20251210153512_drop_unused_gin_index.sql (17.05ms)18022026/10/01 09:48:14 INFO Received uploads request method=POST path=/api/pending_closures18032026/10/01 09:48:14 OK 20251218171726_add_pins.sql (42.32ms)18042026/10/01 09:48:14 OK 20251218171726_add_pins.sql (42.32ms)18052026/10/01 09:48:14 OK 20260628120000_add_object_size_and_stats.sql (38.31ms)18062026/10/01 09:48:14 OK 20260628120000_add_object_size_and_stats.sql (53.38ms)18072026/10/01 09:48:14 OK 20260905000000_add_claims.sql (96.76ms)18082026/10/01 09:48:14 OK 20260905000000_add_claims.sql (111.44ms)18092026/10/01 09:48:14 OK 20260920000000_drop_claims.sql (41.1ms)18102026/10/01 09:48:14 OK 20260920000000_drop_claims.sql (48.67ms)18112026/10/01 09:48:14 OK 20260923120000_add_pushes.sql (14.51ms)18122026/10/01 09:48:14 goose: successfully migrated database to version: 2026092312000018132026/10/01 09:48:14 OK 1_commit_pending_closure.sql (2.98ms)18142026/10/01 09:48:14 OK 2_object_stats_trigger.sql (634.13µs)18152026/10/01 09:48:14 OK 3_commit_push.sql (411.5µs)18162026/10/01 09:48:14 goose: up to current file version: 318172026/10/01 09:48:14 OK 20260923120000_add_pushes.sql (29.45ms)18182026/10/01 09:48:14 goose: successfully migrated database to version: 2026092312000018192026/10/01 09:48:14 OK 1_commit_pending_closure.sql (4.64ms)18202026/10/01 09:48:14 OK 2_object_stats_trigger.sql (572.96µs)18212026/10/01 09:48:14 OK 3_commit_push.sql (416.96µs)18222026/10/01 09:48:14 goose: up to current file version: 318232026/10/01 09:48:14 OK 20241026095416_initial_model.sql (292.61ms)18242026/10/01 09:48:14 OK 20251210153512_drop_unused_gin_index.sql (11.78ms)18252026/10/01 09:48:14 OK 20251218171726_add_pins.sql (53.51ms)18262026/10/01 09:48:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18272026/10/01 09:48:14 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTIxMTFiYmYtNmIxNi00OGU2LWJhZTUtNjliOTNmY2JiZDg0LmM5NTk4OGE3LWE5NmEtNDI0Zi04NDYxLWM3ZTU5MzAyN2UxN3gxNzkwODQ4MDk0MzMyOTM5MDAw18282026/10/01 09:48:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTIxMTFiYmYtNmIxNi00OGU2LWJhZTUtNjliOTNmY2JiZDg0LmM5NTk4OGE3LWE5NmEtNDI0Zi04NDYxLWM3ZTU5MzAyN2UxN3gxNzkwODQ4MDk0MzMyOTM5MDAw parts=11829--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.66s)1830=== CONT TestReadProxyNarinfo18312026/10/01 09:48:14 OK 20260628120000_add_object_size_and_stats.sql (44.67ms)18322026/10/01 09:48:14 OK 20260905000000_add_claims.sql (76.04ms)18332026/10/01 09:48:14 OK 20260920000000_drop_claims.sql (26.32ms)18342026/10/01 09:48:14 OK 20260923120000_add_pushes.sql (11.92ms)18352026/10/01 09:48:14 goose: successfully migrated database to version: 2026092312000018362026/10/01 09:48:14 OK 1_commit_pending_closure.sql (3.05ms)18372026/10/01 09:48:14 OK 2_object_stats_trigger.sql (451.96µs)18382026/10/01 09:48:14 OK 3_commit_push.sql (363.38µs)18392026/10/01 09:48:14 goose: up to current file version: 318402026-10-01 09:48:14.884 UTC [79259] ERROR: relation "goose_db_version" does not exist at character 3618412026-10-01 09:48:14.884 UTC [79259] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18422026/10/01 09:48:14 INFO Received push request method=POST path=/api/pushes18432026/10/01 09:48:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18442026/10/01 09:48:15 INFO Signed narinfos id=1 count=11845--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.83s)1846=== CONT TestIsValidCachePath1847=== RUN TestIsValidCachePath/narinfo1848=== PAUSE TestIsValidCachePath/narinfo1849=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1850=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1851=== RUN TestIsValidCachePath/nar_zst1852=== PAUSE TestIsValidCachePath/nar_zst1853=== RUN TestIsValidCachePath/nar_xz1854=== PAUSE TestIsValidCachePath/nar_xz1855=== RUN TestIsValidCachePath/nar_bz21856=== PAUSE TestIsValidCachePath/nar_bz21857=== RUN TestIsValidCachePath/nar_uncompressed1858=== PAUSE TestIsValidCachePath/nar_uncompressed1859=== RUN TestIsValidCachePath/ls1860=== PAUSE TestIsValidCachePath/ls1861=== RUN TestIsValidCachePath/log1862=== PAUSE TestIsValidCachePath/log1863=== RUN TestIsValidCachePath/realisation1864=== PAUSE TestIsValidCachePath/realisation1865=== RUN TestIsValidCachePath/nix-cache-info1866=== PAUSE TestIsValidCachePath/nix-cache-info1867=== RUN TestIsValidCachePath/index.html1868=== PAUSE TestIsValidCachePath/index.html1869=== RUN TestIsValidCachePath/traversal_parent1870=== PAUSE TestIsValidCachePath/traversal_parent1871=== RUN TestIsValidCachePath/traversal_in_middle1872=== PAUSE TestIsValidCachePath/traversal_in_middle1873=== RUN TestIsValidCachePath/invalid_char_e1874=== PAUSE TestIsValidCachePath/invalid_char_e1875=== RUN TestIsValidCachePath/invalid_char_u1876=== PAUSE TestIsValidCachePath/invalid_char_u1877=== RUN TestIsValidCachePath/random_path1878=== PAUSE TestIsValidCachePath/random_path1879=== RUN TestIsValidCachePath/empty1880=== PAUSE TestIsValidCachePath/empty1881=== RUN TestIsValidCachePath/leading_slash1882=== PAUSE TestIsValidCachePath/leading_slash1883=== RUN TestIsValidCachePath/wrong_extension1884=== PAUSE TestIsValidCachePath/wrong_extension1885=== RUN TestIsValidCachePath/short_hash1886=== PAUSE TestIsValidCachePath/short_hash1887=== CONT TestService_RequireScope_OIDC18882026/10/01 09:48:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52886/oidc18892026/10/01 09:48:15 OK 20241026095416_initial_model.sql (231.15ms)18902026/10/01 09:48:15 OK 20251210153512_drop_unused_gin_index.sql (6.04ms)18912026/10/01 09:48:15 OK 20251218171726_add_pins.sql (39.42ms)18922026/10/01 09:48:15 INFO Received uploads request method=POST path=/api/pending_closures18932026/10/01 09:48:15 OK 20260628120000_add_object_size_and_stats.sql (80.48ms)18942026/10/01 09:48:15 INFO Received uploads request method=POST path=/api/pending_closures18952026/10/01 09:48:15 OK 20260905000000_add_claims.sql (61.96ms)18962026/10/01 09:48:15 OK 20260920000000_drop_claims.sql (56.28ms)18972026/10/01 09:48:15 OK 20260923120000_add_pushes.sql (13.98ms)18982026/10/01 09:48:15 goose: successfully migrated database to version: 2026092312000018992026/10/01 09:48:15 OK 1_commit_pending_closure.sql (1.19ms)19002026/10/01 09:48:15 OK 2_object_stats_trigger.sql (240.67µs)19012026/10/01 09:48:15 OK 3_commit_push.sql (188.67µs)19022026/10/01 09:48:15 goose: up to current file version: 31903=== RUN TestPush_RejectsBadRequests/no_roots1904=== PAUSE TestPush_RejectsBadRequests/no_roots1905=== RUN TestPush_RejectsBadRequests/no_objects1906=== PAUSE TestPush_RejectsBadRequests/no_objects1907=== RUN TestPush_RejectsBadRequests/bad_root1908=== PAUSE TestPush_RejectsBadRequests/bad_root1909=== RUN TestPush_RejectsBadRequests/root_not_in_objects1910=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1911=== CONT TestService_ReadScope_PublicByDefault19122026-10-01 09:48:15.921 UTC [79277] ERROR: relation "goose_db_version" does not exist at character 3619132026-10-01 09:48:15.921 UTC [79277] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19142026/10/01 09:48:15 INFO Received push request method=POST path=/api/pushes19152026/10/01 09:48:16 INFO Received complete push request method=POST path=/api/pushes/1/complete19162026/10/01 09:48:16 INFO Received push request method=POST path=/api/pushes19172026/10/01 09:48:16 INFO Aborted multipart uploads count=019182026/10/01 09:48:16 WARN Force mode enabled - objects will be deleted immediately without grace period19192026/10/01 09:48:16 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=019202026/10/01 09:48:16 OK 20241026095416_initial_model.sql (219.42ms)19212026/10/01 09:48:16 OK 20251210153512_drop_unused_gin_index.sql (12.21ms)19222026/10/01 09:48:16 INFO Vacuumed table table=pending_closures19232026/10/01 09:48:16 OK 20251218171726_add_pins.sql (32.82ms)19242026/10/01 09:48:16 INFO Vacuumed table table=pending_objects19252026/10/01 09:48:16 OK 20260628120000_add_object_size_and_stats.sql (19.58ms)19262026/10/01 09:48:16 INFO Vacuumed table table=multipart_uploads19272026-10-01 09:48:16.305 UTC [79285] ERROR: relation "goose_db_version" does not exist at character 3619282026-10-01 09:48:16.305 UTC [79285] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19292026/10/01 09:48:16 INFO Vacuumed table table=closures19302026/10/01 09:48:16 INFO Vacuumed table table=objects19312026/10/01 09:48:16 INFO Received complete push request method=POST path=/api/pushes/2/complete1932--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.01s)1933=== CONT TestClientIntegration19342026/10/01 09:48:16 OK 20260905000000_add_claims.sql (97.13ms)19352026/10/01 09:48:16 OK 20260920000000_drop_claims.sql (36.52ms)19362026/10/01 09:48:16 OK 20260923120000_add_pushes.sql (12.51ms)19372026/10/01 09:48:16 goose: successfully migrated database to version: 2026092312000019382026/10/01 09:48:16 OK 1_commit_pending_closure.sql (1.62ms)19392026/10/01 09:48:16 OK 2_object_stats_trigger.sql (496.88µs)19402026/10/01 09:48:16 OK 3_commit_push.sql (1.11ms)19412026/10/01 09:48:16 goose: up to current file version: 319422026/10/01 09:48:16 OK 20241026095416_initial_model.sql (263.13ms)19432026/10/01 09:48:16 OK 20251210153512_drop_unused_gin_index.sql (23.84ms)19442026/10/01 09:48:16 OK 20251218171726_add_pins.sql (40.79ms)19452026/10/01 09:48:16 OK 20260628120000_add_object_size_and_stats.sql (70.47ms)19462026/10/01 09:48:16 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19472026/10/01 09:48:16 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1948--- PASS: TestService_NativeMTLS (4.22s)1949=== CONT TestClientErrorHandling1950=== RUN TestClientErrorHandling/InvalidStorePath1951=== PAUSE TestClientErrorHandling/InvalidStorePath1952=== RUN TestClientErrorHandling/InvalidAuthToken1953=== PAUSE TestClientErrorHandling/InvalidAuthToken1954=== RUN TestClientErrorHandling/ServerNotAvailable1955=== PAUSE TestClientErrorHandling/ServerNotAvailable1956=== CONT TestClientCADerivations19572026/10/01 09:48:16 OK 20260905000000_add_claims.sql (97.65ms)19582026/10/01 09:48:16 OK 20260920000000_drop_claims.sql (43.35ms)19592026/10/01 09:48:16 OK 20260923120000_add_pushes.sql (16.98ms)19602026/10/01 09:48:16 goose: successfully migrated database to version: 2026092312000019612026-10-01 09:48:16.954 UTC [79295] ERROR: relation "goose_db_version" does not exist at character 3619622026-10-01 09:48:16.954 UTC [79295] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19632026/10/01 09:48:16 OK 1_commit_pending_closure.sql (1.9ms)19642026/10/01 09:48:16 OK 2_object_stats_trigger.sql (302.63µs)19652026/10/01 09:48:16 OK 3_commit_push.sql (198.04µs)19662026/10/01 09:48:16 goose: up to current file version: 319672026/10/01 09:48:17 OK 20241026095416_initial_model.sql (257.89ms)19682026/10/01 09:48:17 OK 20251210153512_drop_unused_gin_index.sql (10.87ms)19692026/10/01 09:48:17 INFO Received uploads request method=POST path=/api/pending_closures19702026/10/01 09:48:17 OK 20251218171726_add_pins.sql (39.16ms)19712026/10/01 09:48:17 OK 20260628120000_add_object_size_and_stats.sql (61.29ms)19722026/10/01 09:48:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19732026/10/01 09:48:17 OK 20260905000000_add_claims.sql (94.29ms)19742026/10/01 09:48:17 INFO Received cleanup request method=DELETE path=/api/pending_closures19752026/10/01 09:48:17 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTIxMTFiYmYtNmIxNi00OGU2LWJhZTUtNjliOTNmY2JiZDg0LjEzOWE4ZmViLThkODgtNGUwMS1iZTYxLTdjNmE4NDljYTMzZHgxNzkwODQ4MDk1MzIzOTUyMDAw parts=121976--- PASS: TestRedundantMultipartUpload (7.44s)1977=== CONT TestCacheStatsHandler19782026/10/01 09:48:17 INFO Aborted multipart uploads count=119792026/10/01 09:48:17 OK 20260920000000_drop_claims.sql (37.03ms)1980--- PASS: TestMultipartCleanup (4.42s)1981=== CONT TestCacheConfigHandler1982=== RUN TestCacheConfigHandler/full_config,_no_issuer1983=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1984=== RUN TestCacheConfigHandler/no_cache_url_configured1985=== PAUSE TestCacheConfigHandler/no_cache_url_configured1986=== RUN TestCacheConfigHandler/no_signing_keys1987=== PAUSE TestCacheConfigHandler/no_signing_keys1988=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1989=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1990=== CONT TestService_AuthMiddleware_MTLSBoundSubjects19912026/10/01 09:48:17 OK 20260923120000_add_pushes.sql (12.47ms)19922026/10/01 09:48:17 goose: successfully migrated database to version: 2026092312000019932026/10/01 09:48:17 OK 1_commit_pending_closure.sql (1.25ms)19942026/10/01 09:48:17 OK 2_object_stats_trigger.sql (281.92µs)19952026/10/01 09:48:17 OK 3_commit_push.sql (204.17µs)19962026/10/01 09:48:17 goose: up to current file version: 319972026-10-01 09:48:17.652 UTC [79327] ERROR: relation "goose_db_version" does not exist at character 3619982026-10-01 09:48:17.652 UTC [79327] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19992026/10/01 09:48:17 INFO Starting HTTP server address=/nix/var/nix/builds/nix-77474-458540005/TestProxyHeadersOnlyTrustedOnSocket1152870583/001/proxy.sock20002026/10/01 09:48:17 INFO Starting HTTP server address=127.0.0.1:5291920012026/10/01 09:48:17 WARN mTLS auth: subject not in bound subjects subject="CN=someone"20022026/10/01 09:48:17 INFO Shutdown signal received, draining in-flight requests timeout=10s2003--- PASS: TestProxyHeadersOnlyTrustedOnSocket (3.98s)2004=== CONT TestService_ReadAuthMiddleware20052026/10/01 09:48:18 OK 20241026095416_initial_model.sql (265.75ms)20062026/10/01 09:48:18 OK 20251210153512_drop_unused_gin_index.sql (28.97ms)20072026/10/01 09:48:18 OK 20251218171726_add_pins.sql (26.05ms)20082026/10/01 09:48:18 OK 20260628120000_add_object_size_and_stats.sql (34.82ms)20092026-10-01 09:48:18.148 UTC [79360] ERROR: relation "goose_db_version" does not exist at character 3620102026-10-01 09:48:18.148 UTC [79360] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20112026/10/01 09:48:18 OK 20260905000000_add_claims.sql (48.68ms)20122026/10/01 09:48:18 OK 20260920000000_drop_claims.sql (46.11ms)20132026/10/01 09:48:18 OK 20260923120000_add_pushes.sql (26.77ms)20142026/10/01 09:48:18 goose: successfully migrated database to version: 2026092312000020152026/10/01 09:48:18 OK 1_commit_pending_closure.sql (1.34ms)20162026/10/01 09:48:18 OK 2_object_stats_trigger.sql (302.08µs)20172026/10/01 09:48:18 OK 3_commit_push.sql (245.92µs)20182026/10/01 09:48:18 goose: up to current file version: 320192026/10/01 09:48:18 OK 20241026095416_initial_model.sql (250.01ms)20202026/10/01 09:48:18 OK 20251210153512_drop_unused_gin_index.sql (16.65ms)20212026/10/01 09:48:18 OK 20251218171726_add_pins.sql (43.25ms)20222026-10-01 09:48:18.571 UTC [79366] ERROR: relation "goose_db_version" does not exist at character 3620232026-10-01 09:48:18.571 UTC [79366] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20242026/10/01 09:48:18 OK 20260628120000_add_object_size_and_stats.sql (59.49ms)20252026/10/01 09:48:18 OK 20260905000000_add_claims.sql (60.17ms)2026--- PASS: TestReadProxyNarinfo (3.96s)2027=== CONT TestReadProxyRangeRequest20282026/10/01 09:48:18 OK 20260920000000_drop_claims.sql (18.46ms)20292026/10/01 09:48:18 OK 20260923120000_add_pushes.sql (12.11ms)20302026/10/01 09:48:18 goose: successfully migrated database to version: 2026092312000020312026/10/01 09:48:18 OK 1_commit_pending_closure.sql (1.42ms)20322026/10/01 09:48:18 OK 2_object_stats_trigger.sql (254.21µs)20332026/10/01 09:48:18 OK 3_commit_push.sql (175.79µs)20342026/10/01 09:48:18 goose: up to current file version: 320352026/10/01 09:48:18 OK 20241026095416_initial_model.sql (166.38ms)20362026/10/01 09:48:18 OK 20251210153512_drop_unused_gin_index.sql (75.4ms)20372026/10/01 09:48:18 OK 20251218171726_add_pins.sql (25.22ms)20382026/10/01 09:48:18 OK 20260628120000_add_object_size_and_stats.sql (36.49ms)20392026/10/01 09:48:19 OK 20260905000000_add_claims.sql (77.1ms)2040=== RUN TestService_RequireScope_OIDC/builder_may_write2041=== PAUSE TestService_RequireScope_OIDC/builder_may_write2042=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2043=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2044=== RUN TestService_RequireScope_OIDC/ops_may_admin2045=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2046=== RUN TestService_RequireScope_OIDC/ops_may_not_write2047=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2048=== RUN TestService_RequireScope_OIDC/reader_may_not_write2049=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2050=== RUN TestService_RequireScope_OIDC/static_token_may_admin2051=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2052=== RUN TestService_RequireScope_OIDC/static_token_may_write2053=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2054=== RUN TestService_RequireScope_OIDC/reader_may_read2055=== PAUSE TestService_RequireScope_OIDC/reader_may_read2056=== RUN TestService_RequireScope_OIDC/writer_implies_read2057=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2058=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2059=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2060=== CONT TestPush_OverlappingRootsStoreOneRowPerKey20612026/10/01 09:48:19 OK 20260920000000_drop_claims.sql (29.61ms)20622026/10/01 09:48:19 OK 20260923120000_add_pushes.sql (10.64ms)20632026/10/01 09:48:19 goose: successfully migrated database to version: 2026092312000020642026/10/01 09:48:19 OK 1_commit_pending_closure.sql (2.86ms)20652026/10/01 09:48:19 OK 2_object_stats_trigger.sql (297.58µs)20662026/10/01 09:48:19 OK 3_commit_push.sql (171.38µs)20672026/10/01 09:48:19 goose: up to current file version: 320682026-10-01 09:48:19.143 UTC [79376] ERROR: relation "goose_db_version" does not exist at character 3620692026-10-01 09:48:19.143 UTC [79376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2070=== NAME TestOrphanedObjectsGCStressTest2071 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2072 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion20732026-10-01 09:48:19.255 UTC [79377] ERROR: relation "goose_db_version" does not exist at character 3620742026-10-01 09:48:19.255 UTC [79377] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20752026/10/01 09:48:19 OK 20241026095416_initial_model.sql (147.99ms)2076--- PASS: TestService_ReadScope_PublicByDefault (3.74s)2077=== CONT TestReadRedirectUsesPublicS3URL20782026/10/01 09:48:19 OK 20251210153512_drop_unused_gin_index.sql (3.68ms)20792026/10/01 09:48:19 OK 20251218171726_add_pins.sql (19.2ms)20802026/10/01 09:48:19 OK 20260628120000_add_object_size_and_stats.sql (22.42ms)20812026/10/01 09:48:19 OK 20241026095416_initial_model.sql (91.96ms)20822026/10/01 09:48:19 OK 20260905000000_add_claims.sql (5.26ms)20832026/10/01 09:48:19 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)20842026/10/01 09:48:19 OK 20260920000000_drop_claims.sql (2.51ms)20852026/10/01 09:48:19 OK 20251218171726_add_pins.sql (4.45ms)20862026/10/01 09:48:19 OK 20260923120000_add_pushes.sql (2.51ms)20872026/10/01 09:48:19 goose: successfully migrated database to version: 2026092312000020882026/10/01 09:48:19 OK 1_commit_pending_closure.sql (3.16ms)20892026/10/01 09:48:19 OK 2_object_stats_trigger.sql (957.58µs)20902026/10/01 09:48:19 OK 3_commit_push.sql (584.58µs)20912026/10/01 09:48:19 goose: up to current file version: 320922026/10/01 09:48:19 OK 20260628120000_add_object_size_and_stats.sql (35.59ms)20932026/10/01 09:48:19 OK 20260905000000_add_claims.sql (43.47ms)20942026/10/01 09:48:19 OK 20260920000000_drop_claims.sql (71.68ms)20952026/10/01 09:48:19 INFO Aborted multipart uploads count=120962026/10/01 09:48:19 OK 20260923120000_add_pushes.sql (10.15ms)20972026/10/01 09:48:19 goose: successfully migrated database to version: 2026092312000020982026/10/01 09:48:19 OK 1_commit_pending_closure.sql (2.06ms)20992026/10/01 09:48:19 OK 2_object_stats_trigger.sql (250.08µs)21002026/10/01 09:48:19 OK 3_commit_push.sql (210.75µs)21012026/10/01 09:48:19 goose: up to current file version: 321022026/10/01 09:48:19 INFO Received cleanup request method=DELETE path=/api/pending_closures21032026/10/01 09:48:19 INFO Aborted multipart uploads count=12104--- PASS: TestPendingCleanupUsesOneCutoff (11.43s)2105=== CONT TestRegisterCompletedObjectNeedsPendingRow21062026-10-01 09:48:19.651 UTC [79384] ERROR: relation "goose_db_version" does not exist at character 3621072026-10-01 09:48:19.651 UTC [79384] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21082026-10-01 09:48:19.652 UTC [79383] ERROR: relation "goose_db_version" does not exist at character 3621092026-10-01 09:48:19.652 UTC [79383] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21102026/10/01 09:48:20 OK 20241026095416_initial_model.sql (344.66ms)21112026/10/01 09:48:20 OK 20241026095416_initial_model.sql (358.57ms)21122026/10/01 09:48:20 OK 20251210153512_drop_unused_gin_index.sql (6.89ms)21132026/10/01 09:48:20 OK 20251210153512_drop_unused_gin_index.sql (8.54ms)21142026/10/01 09:48:20 OK 20251218171726_add_pins.sql (30.34ms)21152026/10/01 09:48:20 OK 20251218171726_add_pins.sql (32.09ms)21162026/10/01 09:48:20 OK 20260628120000_add_object_size_and_stats.sql (59.9ms)2117=== NAME TestClientIntegration2118 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-77474-458540005/TestClientIntegration747208386/002/store/8q468db6566gh20qvx42pzvfzcf4pclr-test-file.txt21192026/10/01 09:48:20 OK 20260628120000_add_object_size_and_stats.sql (127.85ms)21202026/10/01 09:48:20 OK 20260905000000_add_claims.sql (68.54ms)21212026/10/01 09:48:20 OK 20260920000000_drop_claims.sql (52.62ms)21222026/10/01 09:48:20 OK 20260923120000_add_pushes.sql (16.09ms)21232026/10/01 09:48:20 goose: successfully migrated database to version: 2026092312000021242026/10/01 09:48:20 OK 1_commit_pending_closure.sql (983.54µs)21252026/10/01 09:48:20 OK 2_object_stats_trigger.sql (263.67µs)21262026/10/01 09:48:20 OK 3_commit_push.sql (200µs)21272026/10/01 09:48:20 goose: up to current file version: 321282026/10/01 09:48:20 OK 20260905000000_add_claims.sql (79.58ms)21292026/10/01 09:48:20 INFO Received push request method=POST path=/api/pushes21302026/10/01 09:48:20 OK 20260920000000_drop_claims.sql (78.61ms)21312026/10/01 09:48:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21322026/10/01 09:48:20 INFO Uploading 8q468db6566gh20qvx42pzvfzcf4pclr-test-file.txt (152B)21332026/10/01 09:48:20 OK 20260923120000_add_pushes.sql (3.96ms)21342026/10/01 09:48:20 goose: successfully migrated database to version: 2026092312000021352026/10/01 09:48:20 OK 1_commit_pending_closure.sql (1.21ms)21362026/10/01 09:48:20 OK 2_object_stats_trigger.sql (234.54µs)21372026/10/01 09:48:20 OK 3_commit_push.sql (192.54µs)21382026/10/01 09:48:20 goose: up to current file version: 321392026/10/01 09:48:20 WARN Failed to register uploaded object key=8q468db6566gh20qvx42pzvfzcf4pclr.ls error="server returned 404: 404 page not found\n"21402026/10/01 09:48:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21412026/10/01 09:48:20 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"21422026/10/01 09:48:20 INFO Signed narinfos id=1 count=121432026/10/01 09:48:20 INFO Uploading 1 narinfos21442026/10/01 09:48:20 INFO Received complete push request method=POST path=/api/pushes/1/complete21452026/10/01 09:48:20 WARN Failed to register uploaded object key=8q468db6566gh20qvx42pzvfzcf4pclr.narinfo error="server returned 404: 404 page not found\n"21462026/10/01 09:48:20 INFO Upload complete. (259ms)21472026/10/01 09:48:20 INFO All 1 paths already cached2148 client_integration_test.go:312: Retrieved narinfo from S3:2149 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientIntegration747208386/002/store/8q468db6566gh20qvx42pzvfzcf4pclr-test-file.txt2150 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2151 Compression: zstd2152 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12153 NarSize: 1522154 References: 2155 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12156 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2157 client_integration_test.go:313: Decompressed .ls content (64 bytes):2158 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2159 client_integration_test.go:316: Testing garbage collection...21602026/10/01 09:48:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures21612026/10/01 09:48:20 INFO Garbage collection started21622026/10/01 09:48:20 INFO Aborted multipart uploads count=021632026-10-01 09:48:20.663 UTC [79412] ERROR: relation "goose_db_version" does not exist at character 3621642026-10-01 09:48:20.663 UTC [79412] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21652026/10/01 09:48:20 WARN Force mode enabled - objects will be deleted immediately without grace period21662026/10/01 09:48:20 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=02167--- PASS: TestCacheStatsHandler (3.25s)2168=== CONT TestGCEndsOnShutdown21692026/10/01 09:48:20 INFO Vacuumed table table=pending_closures21702026/10/01 09:48:20 INFO Vacuumed table table=pending_objects21712026/10/01 09:48:20 INFO Vacuumed table table=multipart_uploads21722026/10/01 09:48:20 INFO Vacuumed table table=closures21732026/10/01 09:48:20 INFO Vacuumed table table=objects2174=== NAME TestClientCADerivations2175 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-77474-458540005/TestClientCADerivations2154321711/001/store/2b3a3r1k28xvly3apj5d8r4vl2ph5hgz-ca-test21762026/10/01 09:48:20 OK 20241026095416_initial_model.sql (253.28ms)2177 client_ca_test.go:139: Found 1 dependencies (including self)21782026/10/01 09:48:21 OK 20251210153512_drop_unused_gin_index.sql (13.63ms)21792026/10/01 09:48:21 OK 20251218171726_add_pins.sql (35.88ms)21802026/10/01 09:48:21 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21812026/10/01 09:48:21 WARN mTLS auth: bound subjects configured but subject DN unavailable21822026/10/01 09:48:21 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2183--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (3.50s)2184=== CONT TestCommitRacingPendingCleanupKeepsObjects21852026/10/01 09:48:21 OK 20260628120000_add_object_size_and_stats.sql (55.13ms)21862026/10/01 09:48:21 INFO Received push request method=POST path=/api/pushes21872026/10/01 09:48:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21882026/10/01 09:48:21 INFO Uploading 2b3a3r1k28xvly3apj5d8r4vl2ph5hgz-ca-test (144B)21892026/10/01 09:48:21 OK 20260905000000_add_claims.sql (88.98ms)21902026/10/01 09:48:21 WARN Failed to register uploaded object key=2b3a3r1k28xvly3apj5d8r4vl2ph5hgz.ls error="server returned 404: 404 page not found\n"21912026/10/01 09:48:21 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21922026/10/01 09:48:21 OK 20260920000000_drop_claims.sql (44.24ms)21932026/10/01 09:48:21 WARN Failed to register uploaded object key=log/hq5hyzvpl9fypv92lbaib7rhaahmqs58-ca-test.drv error="server returned 404: 404 page not found\n"21942026/10/01 09:48:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21952026/10/01 09:48:21 INFO Signed narinfos id=1 count=121962026/10/01 09:48:21 INFO Uploading 1 narinfos21972026/10/01 09:48:21 OK 20260923120000_add_pushes.sql (41.69ms)21982026/10/01 09:48:21 goose: successfully migrated database to version: 2026092312000021992026-10-01 09:48:21.278 UTC [79438] ERROR: relation "goose_db_version" does not exist at character 3622002026-10-01 09:48:21.278 UTC [79438] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22012026/10/01 09:48:21 OK 1_commit_pending_closure.sql (1.34ms)22022026/10/01 09:48:21 OK 2_object_stats_trigger.sql (296.13µs)22032026/10/01 09:48:21 OK 3_commit_push.sql (245.17µs)22042026/10/01 09:48:21 goose: up to current file version: 322052026/10/01 09:48:21 INFO Received complete push request method=POST path=/api/pushes/1/complete22062026/10/01 09:48:21 WARN Failed to register uploaded object key=2b3a3r1k28xvly3apj5d8r4vl2ph5hgz.narinfo error="server returned 404: 404 page not found\n"22072026/10/01 09:48:21 INFO Upload complete. (298ms)2208=== NAME TestClientCADerivations2209 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-77474-458540005/TestClientCADerivations2154321711/001/store/2b3a3r1k28xvly3apj5d8r4vl2ph5hgz-ca-test2210 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2211 Compression: zstd2212 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2213 NarSize: 1442214 References: 2215 Deriver: /nix/var/nix/builds/nix-77474-458540005/TestClientCADerivations2154321711/001/store/hq5hyzvpl9fypv92lbaib7rhaahmqs58-ca-test.drv2216 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2217 client_ca_test.go:185: Checking for realisation files in S3...2218 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2219 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2220 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket55?endpoint=http://localhost:52300®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-77474-458540005/TestClientCADerivations2154321711/001/store'2221 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 122222026/10/01 09:48:21 OK 20241026095416_initial_model.sql (323.42ms)2223--- PASS: TestService_ReadAuthMiddleware (3.73s)2224=== CONT TestPushWaitsForSweepHoldingRow22252026/10/01 09:48:21 OK 20251210153512_drop_unused_gin_index.sql (16.23ms)2226--- PASS: TestClientCADerivations (4.88s)2227=== CONT TestSweepRechecksPendingAfterLocking22282026/10/01 09:48:21 OK 20251218171726_add_pins.sql (56.14ms)22292026/10/01 09:48:21 OK 20260628120000_add_object_size_and_stats.sql (28.11ms)22302026/10/01 09:48:21 OK 20260905000000_add_claims.sql (7.47ms)22312026/10/01 09:48:21 OK 20260920000000_drop_claims.sql (4.33ms)22322026-10-01 09:48:21.832 UTC [79476] ERROR: relation "goose_db_version" does not exist at character 3622332026-10-01 09:48:21.832 UTC [79476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22342026/10/01 09:48:21 OK 20260923120000_add_pushes.sql (4.63ms)22352026/10/01 09:48:21 goose: successfully migrated database to version: 2026092312000022362026/10/01 09:48:21 OK 1_commit_pending_closure.sql (2.59ms)22372026/10/01 09:48:21 OK 2_object_stats_trigger.sql (1.29ms)22382026/10/01 09:48:21 OK 3_commit_push.sql (610.38µs)22392026/10/01 09:48:21 goose: up to current file version: 322402026-10-01 09:48:21.931 UTC [79478] ERROR: relation "goose_db_version" does not exist at character 3622412026-10-01 09:48:21.931 UTC [79478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22422026/10/01 09:48:22 OK 20241026095416_initial_model.sql (184.65ms)22432026/10/01 09:48:22 OK 20251210153512_drop_unused_gin_index.sql (10.28ms)22442026/10/01 09:48:22 OK 20251218171726_add_pins.sql (39.14ms)22452026/10/01 09:48:22 OK 20260628120000_add_object_size_and_stats.sql (56.64ms)22462026/10/01 09:48:22 OK 20241026095416_initial_model.sql (201.61ms)22472026/10/01 09:48:22 OK 20251210153512_drop_unused_gin_index.sql (9.28ms)2248--- PASS: TestReadProxyRangeRequest (3.57s)2249=== CONT TestGetExistingObjectsLocksRows22502026/10/01 09:48:22 OK 20251218171726_add_pins.sql (39.31ms)22512026/10/01 09:48:22 OK 20260905000000_add_claims.sql (96.28ms)22522026/10/01 09:48:22 OK 20260920000000_drop_claims.sql (23.62ms)22532026/10/01 09:48:22 OK 20260628120000_add_object_size_and_stats.sql (34.85ms)22542026/10/01 09:48:22 OK 20260923120000_add_pushes.sql (12.55ms)22552026/10/01 09:48:22 goose: successfully migrated database to version: 2026092312000022562026-10-01 09:48:22.296 UTC [79491] ERROR: relation "goose_db_version" does not exist at character 3622572026-10-01 09:48:22.296 UTC [79491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22582026/10/01 09:48:22 OK 1_commit_pending_closure.sql (5.51ms)22592026/10/01 09:48:22 OK 2_object_stats_trigger.sql (1.73ms)22602026/10/01 09:48:22 OK 20260905000000_add_claims.sql (20.3ms)22612026/10/01 09:48:22 OK 3_commit_push.sql (1.06ms)22622026/10/01 09:48:22 goose: up to current file version: 322632026/10/01 09:48:22 OK 20260920000000_drop_claims.sql (65.36ms)22642026/10/01 09:48:22 OK 20260923120000_add_pushes.sql (15.25ms)22652026/10/01 09:48:22 goose: successfully migrated database to version: 2026092312000022662026/10/01 09:48:22 OK 1_commit_pending_closure.sql (961.29µs)22672026/10/01 09:48:22 OK 2_object_stats_trigger.sql (262.17µs)22682026/10/01 09:48:22 OK 3_commit_push.sql (204.04µs)22692026/10/01 09:48:22 goose: up to current file version: 322702026/10/01 09:48:22 OK 20241026095416_initial_model.sql (222.31ms)22712026/10/01 09:48:22 OK 20251210153512_drop_unused_gin_index.sql (12.46ms)22722026/10/01 09:48:22 INFO Received push request method=POST path=/api/pushes22732026/10/01 09:48:22 OK 20251218171726_add_pins.sql (37.93ms)22742026/10/01 09:48:22 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02275=== NAME TestClientIntegration2276 client_integration_test.go:323: Objects in database after GC:2277 client_integration_test.go:323: Successfully deleted all objects with GC --force22782026/10/01 09:48:22 OK 20260628120000_add_object_size_and_stats.sql (57.74ms)2279--- PASS: TestClientIntegration (6.38s)2280=== CONT TestForceGCDuringPushOffersSweptObject2281=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows2282=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows2283=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check2284=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check2285=== CONT TestSweepSkipsRowsLockedByPush22862026/10/01 09:48:22 OK 20260905000000_add_claims.sql (71.05ms)2287--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.75s)2288=== CONT TestFailedS3DeleteKeepsTombstone22892026/10/01 09:48:22 OK 20260920000000_drop_claims.sql (57.61ms)22902026/10/01 09:48:22 OK 20260923120000_add_pushes.sql (29.96ms)22912026/10/01 09:48:22 goose: successfully migrated database to version: 2026092312000022922026/10/01 09:48:22 OK 1_commit_pending_closure.sql (1.53ms)22932026/10/01 09:48:22 OK 2_object_stats_trigger.sql (199.33µs)22942026/10/01 09:48:22 OK 3_commit_push.sql (142.88µs)22952026/10/01 09:48:22 goose: up to current file version: 32296--- PASS: TestReadRedirectUsesPublicS3URL (3.68s)2297=== CONT TestParseSingleRange2298=== RUN TestParseSingleRange/none2299=== PAUSE TestParseSingleRange/none2300=== RUN TestParseSingleRange/unknown_unit2301=== PAUSE TestParseSingleRange/unknown_unit2302=== RUN TestParseSingleRange/multi-range_ignored2303=== PAUSE TestParseSingleRange/multi-range_ignored2304=== RUN TestParseSingleRange/malformed_no_dash2305=== PAUSE TestParseSingleRange/malformed_no_dash2306=== RUN TestParseSingleRange/malformed_both_empty2307=== PAUSE TestParseSingleRange/malformed_both_empty2308=== RUN TestParseSingleRange/malformed_end_before_start2309=== PAUSE TestParseSingleRange/malformed_end_before_start2310=== RUN TestParseSingleRange/closed2311=== PAUSE TestParseSingleRange/closed2312=== RUN TestParseSingleRange/open-ended2313=== PAUSE TestParseSingleRange/open-ended2314=== RUN TestParseSingleRange/end_clamped_to_size2315=== PAUSE TestParseSingleRange/end_clamped_to_size2316=== RUN TestParseSingleRange/suffix2317=== PAUSE TestParseSingleRange/suffix2318=== RUN TestParseSingleRange/suffix_exceeds_size2319=== PAUSE TestParseSingleRange/suffix_exceeds_size2320=== RUN TestParseSingleRange/single_byte2321=== PAUSE TestParseSingleRange/single_byte2322=== RUN TestParseSingleRange/start_past_EOF2323=== PAUSE TestParseSingleRange/start_past_EOF2324=== RUN TestParseSingleRange/start_far_past_EOF2325=== PAUSE TestParseSingleRange/start_far_past_EOF2326=== CONT TestReadRedirectNar2327--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.75s)2328=== CONT TestReadRedirectKeepsNarinfoProxied23292026-10-01 09:48:23.498 UTC [79536] ERROR: relation "goose_db_version" does not exist at character 3623302026-10-01 09:48:23.498 UTC [79536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23312026-10-01 09:48:23.599 UTC [79540] ERROR: relation "goose_db_version" does not exist at character 3623322026-10-01 09:48:23.599 UTC [79540] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2333=== NAME TestOrphanedObjectsGCStressTest2334 orphaned_objects_gc_test.go:509: Stress test completed successfully:2335 orphaned_objects_gc_test.go:510: - Active objects preserved: 202336 orphaned_objects_gc_test.go:511: - Objects deleted: 2102337 orphaned_objects_gc_test.go:512: - Total GC'd: 2102338--- PASS: TestOrphanedObjectsGCStressTest (16.47s)2339=== CONT TestReadProxyDisabled23402026/10/01 09:48:23 OK 20241026095416_initial_model.sql (109.5ms)23412026/10/01 09:48:23 OK 20251210153512_drop_unused_gin_index.sql (11.73ms)23422026-10-01 09:48:23.730 UTC [79553] ERROR: relation "goose_db_version" does not exist at character 3623432026-10-01 09:48:23.730 UTC [79553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23442026/10/01 09:48:23 OK 20251218171726_add_pins.sql (21.71ms)23452026-10-01 09:48:23.755 UTC [79554] ERROR: relation "goose_db_version" does not exist at character 3623462026-10-01 09:48:23.755 UTC [79554] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23472026/10/01 09:48:23 OK 20241026095416_initial_model.sql (107.4ms)23482026/10/01 09:48:23 OK 20260628120000_add_object_size_and_stats.sql (25.29ms)23492026/10/01 09:48:23 OK 20251210153512_drop_unused_gin_index.sql (7.54ms)23502026/10/01 09:48:23 OK 20251218171726_add_pins.sql (20.3ms)23512026/10/01 09:48:23 OK 20260905000000_add_claims.sql (21.98ms)23522026/10/01 09:48:23 OK 20260920000000_drop_claims.sql (2.9ms)23532026/10/01 09:48:23 OK 20260923120000_add_pushes.sql (872µs)23542026/10/01 09:48:23 goose: successfully migrated database to version: 2026092312000023552026/10/01 09:48:23 OK 1_commit_pending_closure.sql (1.45ms)23562026/10/01 09:48:23 OK 2_object_stats_trigger.sql (458.54µs)23572026/10/01 09:48:23 OK 20260628120000_add_object_size_and_stats.sql (7.27ms)23582026/10/01 09:48:23 OK 3_commit_push.sql (769.08µs)23592026/10/01 09:48:23 goose: up to current file version: 323602026/10/01 09:48:23 OK 20260905000000_add_claims.sql (61.97ms)23612026/10/01 09:48:23 OK 20260920000000_drop_claims.sql (48.45ms)23622026/10/01 09:48:23 OK 20260923120000_add_pushes.sql (8.14ms)23632026/10/01 09:48:23 goose: successfully migrated database to version: 2026092312000023642026/10/01 09:48:23 OK 1_commit_pending_closure.sql (1.26ms)23652026/10/01 09:48:23 OK 2_object_stats_trigger.sql (242.54µs)23662026/10/01 09:48:23 OK 3_commit_push.sql (187.54µs)23672026/10/01 09:48:23 goose: up to current file version: 323682026/10/01 09:48:23 OK 20241026095416_initial_model.sql (159.52ms)23692026/10/01 09:48:23 OK 20251210153512_drop_unused_gin_index.sql (13.15ms)23702026/10/01 09:48:23 OK 20241026095416_initial_model.sql (202.93ms)23712026/10/01 09:48:23 OK 20251218171726_add_pins.sql (46.26ms)23722026/10/01 09:48:24 OK 20251210153512_drop_unused_gin_index.sql (9.27ms)23732026/10/01 09:48:24 OK 20251218171726_add_pins.sql (34.32ms)23742026/10/01 09:48:24 OK 20260628120000_add_object_size_and_stats.sql (65.52ms)23752026/10/01 09:48:24 OK 20260628120000_add_object_size_and_stats.sql (45.96ms)23762026/10/01 09:48:24 OK 20260905000000_add_claims.sql (90.97ms)23772026/10/01 09:48:24 OK 20260905000000_add_claims.sql (101.53ms)23782026/10/01 09:48:24 OK 20260920000000_drop_claims.sql (81.93ms)2379--- PASS: TestGCEndsOnShutdown (3.45s)2380=== CONT TestNARDeduplicationMetadataUploadBug23812026/10/01 09:48:24 OK 20260920000000_drop_claims.sql (62.45ms)23822026/10/01 09:48:24 OK 20260923120000_add_pushes.sql (36.31ms)23832026/10/01 09:48:24 goose: successfully migrated database to version: 2026092312000023842026/10/01 09:48:24 OK 1_commit_pending_closure.sql (896.33µs)23852026/10/01 09:48:24 OK 2_object_stats_trigger.sql (223.88µs)23862026/10/01 09:48:24 OK 3_commit_push.sql (208.04µs)23872026/10/01 09:48:24 goose: up to current file version: 323882026/10/01 09:48:24 OK 20260923120000_add_pushes.sql (40.71ms)23892026/10/01 09:48:24 goose: successfully migrated database to version: 2026092312000023902026/10/01 09:48:24 OK 1_commit_pending_closure.sql (954.42µs)23912026/10/01 09:48:24 OK 2_object_stats_trigger.sql (223.21µs)23922026/10/01 09:48:24 OK 3_commit_push.sql (176.54µs)23932026/10/01 09:48:24 goose: up to current file version: 323942026/10/01 09:48:24 INFO Aborted multipart uploads count=023952026/10/01 09:48:24 WARN Force mode enabled - objects will be deleted immediately without grace period23962026/10/01 09:48:24 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=023972026/10/01 09:48:24 INFO Vacuumed table table=pending_closures23982026/10/01 09:48:24 INFO Vacuumed table table=pending_objects23992026/10/01 09:48:24 INFO Vacuumed table table=multipart_uploads24002026/10/01 09:48:25 INFO Vacuumed table table=closures24012026/10/01 09:48:25 INFO Vacuumed table table=objects2402--- PASS: TestCommitRacingPendingCleanupKeepsObjects (3.98s)2403=== CONT TestMetricsInventory24042026/10/01 09:48:25 INFO Received uploads request method=POST path=/api/pending_closures24052026-10-01 09:48:25.187 UTC [79629] ERROR: relation "goose_db_version" does not exist at character 3624062026-10-01 09:48:25.187 UTC [79629] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24072026/10/01 09:48:25 INFO Aborted multipart uploads count=024082026/10/01 09:48:25 WARN Force mode enabled - objects will be deleted immediately without grace period24092026/10/01 09:48:25 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=024102026/10/01 09:48:25 INFO Vacuumed table table=pending_closures2411--- PASS: TestPushWaitsForSweepHoldingRow (3.87s)2412=== CONT TestCreatePendingClosureRejectsOversizedNAR24132026/10/01 09:48:25 INFO Received uploads request method=POST path=/api/pending_closures2414--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2415=== CONT TestPresentNotReportedWhileGCDeletesClosure24162026/10/01 09:48:25 OK 20241026095416_initial_model.sql (357.66ms)24172026/10/01 09:48:25 INFO Vacuumed table table=pending_objects24182026/10/01 09:48:25 OK 20251210153512_drop_unused_gin_index.sql (20.05ms)24192026/10/01 09:48:25 INFO Vacuumed table table=multipart_uploads24202026/10/01 09:48:25 INFO Vacuumed table table=closures24212026/10/01 09:48:25 INFO Vacuumed table table=objects2422--- PASS: TestSweepRechecksPendingAfterLocking (3.95s)2423=== CONT TestGCSweepDeliversEachKeyOnce24242026/10/01 09:48:25 OK 20251218171726_add_pins.sql (53.41ms)24252026/10/01 09:48:25 OK 20260628120000_add_object_size_and_stats.sql (18.84ms)24262026/10/01 09:48:25 OK 20260905000000_add_claims.sql (7.51ms)24272026/10/01 09:48:25 OK 20260920000000_drop_claims.sql (8.43ms)24282026-10-01 09:48:25.738 UTC [79643] ERROR: relation "goose_db_version" does not exist at character 3624292026-10-01 09:48:25.738 UTC [79643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24302026-10-01 09:48:25.741 UTC [79644] ERROR: relation "goose_db_version" does not exist at character 3624312026-10-01 09:48:25.741 UTC [79644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24322026/10/01 09:48:25 OK 20260923120000_add_pushes.sql (34.55ms)24332026/10/01 09:48:25 goose: successfully migrated database to version: 2026092312000024342026/10/01 09:48:25 OK 1_commit_pending_closure.sql (1.01ms)24352026/10/01 09:48:25 OK 2_object_stats_trigger.sql (232.5µs)24362026/10/01 09:48:25 OK 3_commit_push.sql (179.88µs)24372026/10/01 09:48:25 goose: up to current file version: 324382026-10-01 09:48:25.918 UTC [79651] ERROR: relation "goose_db_version" does not exist at character 3624392026-10-01 09:48:25.918 UTC [79651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24402026/10/01 09:48:26 OK 20241026095416_initial_model.sql (259.3ms)24412026/10/01 09:48:26 OK 20241026095416_initial_model.sql (254.02ms)24422026/10/01 09:48:26 OK 20251210153512_drop_unused_gin_index.sql (9.39ms)24432026/10/01 09:48:26 OK 20251210153512_drop_unused_gin_index.sql (19.53ms)2444--- PASS: TestGetExistingObjectsLocksRows (4.00s)2445=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection24462026/10/01 09:48:26 OK 20251218171726_add_pins.sql (55.19ms)24472026/10/01 09:48:26 OK 20251218171726_add_pins.sql (71.37ms)24482026-10-01 09:48:26.296 UTC [79655] ERROR: relation "goose_db_version" does not exist at character 3624492026-10-01 09:48:26.296 UTC [79655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24502026/10/01 09:48:26 OK 20260628120000_add_object_size_and_stats.sql (76.49ms)24512026/10/01 09:48:26 OK 20241026095416_initial_model.sql (269.02ms)24522026/10/01 09:48:26 OK 20251210153512_drop_unused_gin_index.sql (2.89ms)24532026/10/01 09:48:26 OK 20260628120000_add_object_size_and_stats.sql (61.45ms)24542026/10/01 09:48:26 OK 20260905000000_add_claims.sql (14.48ms)24552026/10/01 09:48:26 OK 20251218171726_add_pins.sql (37.92ms)24562026/10/01 09:48:26 OK 20260920000000_drop_claims.sql (55.03ms)24572026/10/01 09:48:26 OK 20260905000000_add_claims.sql (57.97ms)24582026/10/01 09:48:26 OK 20260923120000_add_pushes.sql (15.68ms)24592026/10/01 09:48:26 goose: successfully migrated database to version: 2026092312000024602026/10/01 09:48:26 OK 1_commit_pending_closure.sql (1.01ms)24612026/10/01 09:48:26 OK 2_object_stats_trigger.sql (227.21µs)24622026/10/01 09:48:26 OK 3_commit_push.sql (192.33µs)24632026/10/01 09:48:26 goose: up to current file version: 324642026/10/01 09:48:26 OK 20260628120000_add_object_size_and_stats.sql (46.03ms)24652026/10/01 09:48:26 OK 20260920000000_drop_claims.sql (17.23ms)24662026/10/01 09:48:26 OK 20260923120000_add_pushes.sql (30.03ms)24672026/10/01 09:48:26 goose: successfully migrated database to version: 2026092312000024682026/10/01 09:48:26 OK 1_commit_pending_closure.sql (927.17µs)24692026/10/01 09:48:26 OK 2_object_stats_trigger.sql (227.88µs)24702026/10/01 09:48:26 OK 3_commit_push.sql (173.38µs)24712026/10/01 09:48:26 goose: up to current file version: 324722026/10/01 09:48:26 OK 20260905000000_add_claims.sql (66.09ms)24732026/10/01 09:48:26 OK 20260920000000_drop_claims.sql (35.74ms)24742026/10/01 09:48:26 OK 20260923120000_add_pushes.sql (19.13ms)24752026/10/01 09:48:26 goose: successfully migrated database to version: 2026092312000024762026/10/01 09:48:26 OK 1_commit_pending_closure.sql (1.17ms)24772026/10/01 09:48:26 OK 2_object_stats_trigger.sql (255.83µs)24782026/10/01 09:48:26 OK 3_commit_push.sql (177.96µs)24792026/10/01 09:48:26 goose: up to current file version: 324802026-10-01 09:48:26.543 UTC [79662] ERROR: relation "goose_db_version" does not exist at character 3624812026-10-01 09:48:26.543 UTC [79662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24822026/10/01 09:48:26 OK 20241026095416_initial_model.sql (198.79ms)24832026/10/01 09:48:26 OK 20251210153512_drop_unused_gin_index.sql (16.55ms)24842026/10/01 09:48:26 OK 20251218171726_add_pins.sql (112.8ms)24852026/10/01 09:48:26 OK 20260628120000_add_object_size_and_stats.sql (50.22ms)24862026/10/01 09:48:26 INFO Aborted multipart uploads count=024872026/10/01 09:48:26 WARN Force mode enabled - objects will be deleted immediately without grace period24882026/10/01 09:48:26 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=024892026/10/01 09:48:26 INFO Vacuumed table table=pending_closures24902026/10/01 09:48:26 INFO Vacuumed table table=pending_objects24912026/10/01 09:48:26 INFO Vacuumed table table=multipart_uploads24922026/10/01 09:48:26 INFO Vacuumed table table=closures24932026/10/01 09:48:26 OK 20260905000000_add_claims.sql (128.38ms)24942026/10/01 09:48:26 INFO Vacuumed table table=objects24952026/10/01 09:48:26 INFO Aborted multipart uploads count=024962026/10/01 09:48:26 WARN Force mode enabled - objects will be deleted immediately without grace period24972026/10/01 09:48:26 OK 20260920000000_drop_claims.sql (74.8ms)24982026/10/01 09:48:26 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=024992026/10/01 09:48:26 INFO Vacuumed table table=pending_closures25002026/10/01 09:48:26 INFO Vacuumed table table=pending_objects25012026/10/01 09:48:26 INFO Vacuumed table table=multipart_uploads25022026/10/01 09:48:26 INFO Vacuumed table table=closures25032026/10/01 09:48:26 OK 20260923120000_add_pushes.sql (27.97ms)25042026/10/01 09:48:26 goose: successfully migrated database to version: 2026092312000025052026/10/01 09:48:26 OK 1_commit_pending_closure.sql (1.2ms)25062026/10/01 09:48:26 OK 2_object_stats_trigger.sql (288.17µs)25072026/10/01 09:48:26 OK 3_commit_push.sql (234.33µs)25082026/10/01 09:48:26 goose: up to current file version: 325092026/10/01 09:48:26 INFO Vacuumed table table=objects2510--- PASS: TestSweepSkipsRowsLockedByPush (4.23s)2511=== CONT TestTombstonedObjectOfferedWithoutWaiting25122026/10/01 09:48:27 OK 20241026095416_initial_model.sql (314.6ms)25132026/10/01 09:48:27 OK 20251210153512_drop_unused_gin_index.sql (12.57ms)25142026/10/01 09:48:27 OK 20251218171726_add_pins.sql (64.24ms)25152026/10/01 09:48:27 OK 20260628120000_add_object_size_and_stats.sql (67.01ms)25162026/10/01 09:48:27 INFO Received uploads request method=POST path=/api/pending_closures25172026/10/01 09:48:27 OK 20260905000000_add_claims.sql (129.19ms)25182026/10/01 09:48:27 OK 20260920000000_drop_claims.sql (75.55ms)25192026/10/01 09:48:27 OK 20260923120000_add_pushes.sql (36.34ms)25202026/10/01 09:48:27 goose: successfully migrated database to version: 2026092312000025212026/10/01 09:48:27 OK 1_commit_pending_closure.sql (2.67ms)25222026/10/01 09:48:27 OK 2_object_stats_trigger.sql (497.92µs)25232026/10/01 09:48:27 OK 3_commit_push.sql (373.17µs)25242026/10/01 09:48:27 goose: up to current file version: 325252026/10/01 09:48:27 INFO Aborted multipart uploads count=025262026/10/01 09:48:27 WARN Force mode enabled - objects will be deleted immediately without grace period25272026/10/01 09:48:27 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."25282026/10/01 09:48:27 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2529--- PASS: TestFailedS3DeleteKeepsTombstone (4.74s)2530=== CONT TestService_AuthMiddleware_MTLSProxyHeader2531--- PASS: TestReadRedirectNar (4.70s)2532=== CONT TestService_AuthMiddleware_OIDC25332026/10/01 09:48:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53209/oidc25342026-10-01 09:48:28.053 UTC [79714] ERROR: relation "goose_db_version" does not exist at character 3625352026-10-01 09:48:28.053 UTC [79714] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2536--- PASS: TestReadRedirectKeepsNarinfoProxied (4.75s)2537=== CONT TestGCSweepSkipsPendingObjects25382026-10-01 09:48:28.400 UTC [79717] ERROR: relation "goose_db_version" does not exist at character 3625392026-10-01 09:48:28.400 UTC [79717] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25402026/10/01 09:48:28 OK 20241026095416_initial_model.sql (306.06ms)2541--- PASS: TestReadProxyDisabled (4.88s)2542=== CONT TestResolveDBConnectionString/flag_wins2543=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2544=== CONT TestResolveDBConnectionString/nothing_configured2545=== CONT TestResolveDBConnectionString/missing_file_is_an_error2546=== CONT TestResolveDBConnectionString/file_when_flag_empty2547=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure25482026/10/01 09:48:28 INFO Received uploads request method=POST path=/2549--- PASS: TestResolveDBConnectionString (0.03s)2550 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2551 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2552 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2553 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2554 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)25552026/10/01 09:48:28 OK 20251210153512_drop_unused_gin_index.sql (23.05ms)25562026/10/01 09:48:28 OK 20251218171726_add_pins.sql (34.4ms)25572026/10/01 09:48:28 OK 20260628120000_add_object_size_and_stats.sql (65.58ms)25582026/10/01 09:48:28 OK 20260905000000_add_claims.sql (82.12ms)25592026/10/01 09:48:28 OK 20260920000000_drop_claims.sql (10.87ms)25602026/10/01 09:48:28 OK 20260923120000_add_pushes.sql (27.31ms)25612026/10/01 09:48:28 goose: successfully migrated database to version: 2026092312000025622026/10/01 09:48:28 OK 20241026095416_initial_model.sql (206.91ms)25632026/10/01 09:48:28 OK 1_commit_pending_closure.sql (941.63µs)25642026/10/01 09:48:28 OK 2_object_stats_trigger.sql (215.88µs)25652026/10/01 09:48:28 OK 3_commit_push.sql (145.33µs)25662026/10/01 09:48:28 goose: up to current file version: 325672026/10/01 09:48:28 OK 20251210153512_drop_unused_gin_index.sql (14.35ms)25682026-10-01 09:48:28.766 UTC [79718] ERROR: relation "goose_db_version" does not exist at character 3625692026-10-01 09:48:28.766 UTC [79718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25702026/10/01 09:48:28 OK 20251218171726_add_pins.sql (50.79ms)2571=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25722026/10/01 09:48:28 INFO Received request for more parts method=POST path=/2573=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25742026/10/01 09:48:28 INFO Received complete multipart upload request method=POST path=/2575--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2576 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)2577 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2578 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2579=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info25802026/10/01 09:48:28 INFO Received uploads request method=POST path=/2581=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal25822026/10/01 09:48:28 INFO Received uploads request method=POST path=/2583=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key25842026/10/01 09:48:28 INFO Received request for more parts method=POST path=/2585=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key25862026/10/01 09:48:28 INFO Received complete multipart upload request method=POST path=/2587--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2588 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2589 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2590 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2591 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2592=== CONT TestIsValidUploadKey/narinfo2593=== CONT TestProxyWriteTimeout/narinfo2594=== CONT TestIsValidUploadKey/realisation2595=== CONT TestIsValidUploadKey/build_log_equals2596=== CONT TestIsValidUploadKey/build_log_question_mark2597=== CONT TestIsValidUploadKey/build_log_plus_in_name2598=== CONT TestIsValidUploadKey/build_log_home-manager_file2599=== CONT TestIsValidUploadKey/build_log2600=== CONT TestIsValidUploadKey/listing2601=== CONT TestIsValidUploadKey/nar_plain2602=== CONT TestIsValidUploadKey/nar_xz2603=== CONT TestIsValidUploadKey/nar_zst2604=== CONT TestIsValidUploadKey/traversal2605=== CONT TestIsValidUploadKey/unknown_type2606=== CONT TestIsValidUploadKey/empty_key2607=== CONT TestIsValidUploadKey/absolute2608=== CONT TestIsValidUploadKey/traversal_nar2609=== CONT TestProxyWriteTimeout/10_GiB_nar2610=== CONT TestProxyWriteTimeout/unknown_size2611=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2612=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2613=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2614=== CONT TestIsValidUploadKey/index.html2615=== CONT TestIsValidUploadKey/nix-cache-info2616=== CONT TestProxyWriteTimeout/1_GiB_nar2617--- PASS: TestProxyWriteTimeout (0.00s)2618 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2619 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2620 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2621 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2622=== CONT TestIsValidUploadKey/realisation_plus_in_output2623--- PASS: TestIsValidUploadKey (0.00s)2624 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2625 --- PASS: TestIsValidUploadKey/realisation (0.00s)2626 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2627 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2628 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2629 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2630 --- PASS: TestIsValidUploadKey/build_log (0.00s)2631 --- PASS: TestIsValidUploadKey/listing (0.00s)2632 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2633 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2634 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2635 --- PASS: TestIsValidUploadKey/traversal (0.00s)2636 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2637 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2638 --- PASS: TestIsValidUploadKey/absolute (0.00s)2639 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2640 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2641 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2642 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2643 --- PASS: TestIsValidUploadKey/index.html (0.00s)2644 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2645 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2646=== CONT TestServerTLSConfig/no_client_CA2647=== CONT TestServerTLSConfig/not_a_PEM_file26482026/10/01 09:48:28 OK 20260628120000_add_object_size_and_stats.sql (58.47ms)2649=== CONT TestServerTLSConfig/missing_CA_file2650--- PASS: TestServerTLSConfig (0.00s)2651 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2652 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2653 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2654=== CONT TestIsValidCachePath/narinfo2655=== CONT TestIsValidCachePath/short_hash2656=== CONT TestIsValidCachePath/wrong_extension2657=== CONT TestIsValidCachePath/leading_slash2658=== CONT TestIsValidCachePath/empty2659=== CONT TestIsValidCachePath/random_path2660=== CONT TestIsValidCachePath/invalid_char_u2661=== CONT TestIsValidCachePath/invalid_char_e2662=== CONT TestIsValidCachePath/traversal_in_middle2663=== CONT TestIsValidCachePath/traversal_parent2664=== CONT TestIsValidCachePath/index.html2665=== CONT TestIsValidCachePath/nix-cache-info2666=== CONT TestIsValidCachePath/realisation2667=== CONT TestIsValidCachePath/log2668=== CONT TestIsValidCachePath/ls2669=== CONT TestIsValidCachePath/nar_uncompressed2670=== CONT TestIsValidCachePath/nar_bz22671=== CONT TestIsValidCachePath/nar_xz2672=== CONT TestIsValidCachePath/nar_zst2673=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2674--- PASS: TestIsValidCachePath (0.00s)2675 --- PASS: TestIsValidCachePath/narinfo (0.00s)2676 --- PASS: TestIsValidCachePath/short_hash (0.00s)2677 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2678 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2679 --- PASS: TestIsValidCachePath/empty (0.00s)2680 --- PASS: TestIsValidCachePath/random_path (0.00s)2681 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2682 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2683 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2684 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2685 --- PASS: TestIsValidCachePath/index.html (0.00s)2686 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2687 --- PASS: TestIsValidCachePath/realisation (0.00s)2688 --- PASS: TestIsValidCachePath/log (0.00s)2689 --- PASS: TestIsValidCachePath/ls (0.00s)2690 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2691 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2692 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2693 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2694 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2695=== CONT TestPush_RejectsBadRequests/no_roots26962026/10/01 09:48:28 INFO Received push request method=POST path=/api/pushes2697=== CONT TestPush_RejectsBadRequests/bad_root26982026/10/01 09:48:28 INFO Received push request method=POST path=/api/pushes2699=== CONT TestPush_RejectsBadRequests/root_not_in_objects27002026/10/01 09:48:28 INFO Received push request method=POST path=/api/pushes2701=== CONT TestPush_RejectsBadRequests/no_objects27022026/10/01 09:48:28 INFO Received push request method=POST path=/api/pushes2703=== CONT TestClientErrorHandling/InvalidStorePath2704--- PASS: TestPush_RejectsBadRequests (4.91s)2705 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2706 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2707 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2708 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)27092026/10/01 09:48:28 OK 20260905000000_add_claims.sql (112.24ms)27102026/10/01 09:48:29 OK 20260920000000_drop_claims.sql (87.15ms)27112026/10/01 09:48:29 OK 20260923120000_add_pushes.sql (36.3ms)27122026/10/01 09:48:29 goose: successfully migrated database to version: 2026092312000027132026/10/01 09:48:29 OK 1_commit_pending_closure.sql (1.59ms)27142026/10/01 09:48:29 OK 2_object_stats_trigger.sql (380.13µs)27152026/10/01 09:48:29 OK 3_commit_push.sql (305.92µs)27162026/10/01 09:48:29 goose: up to current file version: 327172026/10/01 09:48:29 OK 20241026095416_initial_model.sql (401.95ms)27182026/10/01 09:48:29 OK 20251210153512_drop_unused_gin_index.sql (17.89ms)27192026/10/01 09:48:29 OK 20251218171726_add_pins.sql (76.52ms)27202026-10-01 09:48:29.401 UTC [79726] ERROR: relation "goose_db_version" does not exist at character 3627212026-10-01 09:48:29.401 UTC [79726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27222026/10/01 09:48:29 OK 20260628120000_add_object_size_and_stats.sql (73.81ms)27232026/10/01 09:48:29 OK 20260905000000_add_claims.sql (84.27ms)27242026/10/01 09:48:29 OK 20260920000000_drop_claims.sql (49.07ms)27252026/10/01 09:48:29 OK 20260923120000_add_pushes.sql (14.91ms)27262026/10/01 09:48:29 goose: successfully migrated database to version: 202609231200002727=== NAME TestNARDeduplicationMetadataUploadBug2728 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-77474-458540005/TestNARDeduplicationMetadataUploadBug2880885818/001/store/04fkwb7yn95m7yyh4ycnvksy2386iag0-file1.txt27292026/10/01 09:48:29 OK 1_commit_pending_closure.sql (3.56ms)27302026/10/01 09:48:29 OK 2_object_stats_trigger.sql (1.17ms)27312026/10/01 09:48:29 OK 3_commit_push.sql (257.33µs)27322026/10/01 09:48:29 goose: up to current file version: 32733--- PASS: TestMetricsInventory (4.64s)2734=== CONT TestClientErrorHandling/ServerNotAvailable27352026/10/01 09:48:29 OK 20241026095416_initial_model.sql (200.91ms)27362026/10/01 09:48:29 OK 20251210153512_drop_unused_gin_index.sql (9.48ms)27372026/10/01 09:48:29 INFO Received push request method=POST path=/api/pushes27382026-10-01 09:48:29.717 UTC [79736] ERROR: relation "goose_db_version" does not exist at character 3627392026-10-01 09:48:29.717 UTC [79736] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27402026/10/01 09:48:29 OK 20251218171726_add_pins.sql (16.6ms)27412026/10/01 09:48:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27422026/10/01 09:48:29 INFO Uploading 04fkwb7yn95m7yyh4ycnvksy2386iag0-file1.txt (160B)27432026/10/01 09:48:29 OK 20260628120000_add_object_size_and_stats.sql (45.24ms)27442026/10/01 09:48:29 WARN Failed to register uploaded object key=04fkwb7yn95m7yyh4ycnvksy2386iag0.ls error="server returned 404: 404 page not found\n"27452026/10/01 09:48:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27462026/10/01 09:48:29 INFO Signed narinfos id=1 count=127472026/10/01 09:48:29 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"27482026/10/01 09:48:29 INFO Uploading 1 narinfos27492026/10/01 09:48:29 INFO Received complete push request method=POST path=/api/pushes/1/complete27502026/10/01 09:48:29 WARN Failed to register uploaded object key=04fkwb7yn95m7yyh4ycnvksy2386iag0.narinfo error="server returned 404: 404 page not found\n"27512026/10/01 09:48:29 INFO Upload complete. (188ms)2752=== NAME TestNARDeduplicationMetadataUploadBug2753 metadata_upload_test.go:54: Retrieved narinfo from S3:2754 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestNARDeduplicationMetadataUploadBug2880885818/001/store/04fkwb7yn95m7yyh4ycnvksy2386iag0-file1.txt2755 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2756 Compression: zstd2757 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2758 NarSize: 1602759 References: 2760 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2761 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2762 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2763 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}27642026/10/01 09:48:29 OK 20260905000000_add_claims.sql (101.16ms)27652026/10/01 09:48:29 OK 20260920000000_drop_claims.sql (60.3ms)27662026/10/01 09:48:29 OK 20260923120000_add_pushes.sql (31.33ms)27672026/10/01 09:48:29 goose: successfully migrated database to version: 2026092312000027682026/10/01 09:48:29 OK 1_commit_pending_closure.sql (913.13µs)27692026/10/01 09:48:29 OK 2_object_stats_trigger.sql (265.92µs)27702026/10/01 09:48:29 OK 3_commit_push.sql (210µs)27712026/10/01 09:48:29 goose: up to current file version: 32772 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-77474-458540005/TestNARDeduplicationMetadataUploadBug2880885818/001/store/d6ipwdpypfb41y3dnzjdc3gm8mswazr8-file2.txt27732026/10/01 09:48:30 OK 20241026095416_initial_model.sql (304.65ms)27742026/10/01 09:48:30 OK 20251210153512_drop_unused_gin_index.sql (14.85ms)27752026/10/01 09:48:30 INFO Received push request method=POST path=/api/pushes27762026/10/01 09:48:30 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)27772026/10/01 09:48:30 OK 20251218171726_add_pins.sql (49.77ms)27782026/10/01 09:48:30 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign27792026/10/01 09:48:30 WARN Failed to register uploaded object key=d6ipwdpypfb41y3dnzjdc3gm8mswazr8.ls error="server returned 404: 404 page not found\n"27802026/10/01 09:48:30 INFO Signed narinfos id=2 count=127812026/10/01 09:48:30 INFO Uploading 1 narinfos27822026/10/01 09:48:30 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/present27832026/10/01 09:48:30 INFO Received complete push request method=POST path=/api/pushes/2/complete27842026/10/01 09:48:30 WARN Failed to register uploaded object key=d6ipwdpypfb41y3dnzjdc3gm8mswazr8.narinfo error="server returned 404: 404 page not found\n"27852026/10/01 09:48:30 INFO Upload complete. (174ms)2786 metadata_upload_test.go:76: Retrieved narinfo from S3:2787 StorePath: /nix/var/nix/builds/nix-77474-458540005/TestNARDeduplicationMetadataUploadBug2880885818/001/store/d6ipwdpypfb41y3dnzjdc3gm8mswazr8-file2.txt2788 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2789 Compression: zstd2790 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2791 NarSize: 1602792 References: 2793 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2794 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2795 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2796 {"version":1,"root":{"type":"regular","size":44}}27972026/10/01 09:48:30 OK 20260628120000_add_object_size_and_stats.sql (70.19ms)27982026/10/01 09:48:30 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.512264ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27992026/10/01 09:48:30 OK 20260905000000_add_claims.sql (117.88ms)2800--- PASS: TestNARDeduplicationMetadataUploadBug (6.21s)2801=== CONT TestClientErrorHandling/InvalidAuthToken28022026/10/01 09:48:30 OK 20260920000000_drop_claims.sql (72.54ms)28032026/10/01 09:48:30 OK 20260923120000_add_pushes.sql (26.18ms)28042026/10/01 09:48:30 goose: successfully migrated database to version: 2026092312000028052026/10/01 09:48:30 OK 1_commit_pending_closure.sql (913µs)28062026/10/01 09:48:30 OK 2_object_stats_trigger.sql (246.58µs)28072026/10/01 09:48:30 OK 3_commit_push.sql (202.21µs)28082026/10/01 09:48:30 goose: up to current file version: 328092026/10/01 09:48:30 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=371.25483ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2810--- PASS: TestPresentNotReportedWhileGCDeletesClosure (5.03s)2811=== CONT TestCacheConfigHandler/full_config,_no_issuer2812=== CONT TestCacheConfigHandler/no_signing_keys2813=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2814=== CONT TestCacheConfigHandler/no_cache_url_configured2815--- PASS: TestCacheConfigHandler (0.00s)2816 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2817 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2818 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2819 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2820=== CONT TestService_RequireScope_OIDC/builder_may_write2821=== CONT TestService_RequireScope_OIDC/writer_implies_read2822=== CONT TestService_RequireScope_OIDC/reader_may_read2823=== CONT TestService_RequireScope_OIDC/static_token_may_write2824=== CONT TestService_RequireScope_OIDC/static_token_may_admin2825=== CONT TestService_RequireScope_OIDC/reader_may_not_write2826=== CONT TestService_RequireScope_OIDC/ops_may_not_write2827=== CONT TestService_RequireScope_OIDC/ops_may_admin2828=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2829=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2830=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2831--- PASS: TestService_RequireScope_OIDC (4.02s)2832 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2833 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2834 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2835 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2836 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2837 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2838 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2839 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2840 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2841 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)28422026-10-01 09:48:30.713 UTC [79774] ERROR: relation "goose_db_version" does not exist at character 3628432026-10-01 09:48:30.713 UTC [79774] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28442026/10/01 09:48:30 INFO Aborted multipart uploads count=028452026/10/01 09:48:30 WARN Force mode enabled - objects will be deleted immediately without grace period28462026/10/01 09:48:30 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=799.360601ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28472026/10/01 09:48:30 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=028482026/10/01 09:48:30 INFO Vacuumed table table=pending_closures28492026/10/01 09:48:30 INFO Vacuumed table table=pending_objects28502026/10/01 09:48:30 INFO Vacuumed table table=multipart_uploads28512026/10/01 09:48:30 INFO Vacuumed table table=closures28522026/10/01 09:48:31 INFO Vacuumed table table=objects2853--- PASS: TestGCSweepDeliversEachKeyOnce (5.34s)2854=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check28552026/10/01 09:48:31 INFO Received uploads request method=POST path=/api/pending_closures28562026/10/01 09:48:31 OK 20241026095416_initial_model.sql (326.61ms)28572026/10/01 09:48:31 OK 20251210153512_drop_unused_gin_index.sql (15.36ms)28582026-10-01 09:48:31.258 UTC [79791] ERROR: relation "goose_db_version" does not exist at character 3628592026-10-01 09:48:31.258 UTC [79791] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28602026/10/01 09:48:31 OK 20251218171726_add_pins.sql (73.17ms)2861--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.09s)2862=== CONT TestParseSingleRange/none2863=== CONT TestParseSingleRange/open-ended2864=== CONT TestParseSingleRange/start_far_past_EOF2865=== CONT TestParseSingleRange/start_past_EOF2866=== CONT TestParseSingleRange/single_byte2867=== CONT TestParseSingleRange/suffix_exceeds_size2868=== CONT TestParseSingleRange/suffix2869=== CONT TestParseSingleRange/end_clamped_to_size2870=== CONT TestParseSingleRange/malformed_both_empty2871=== CONT TestParseSingleRange/closed2872=== CONT TestParseSingleRange/malformed_end_before_start2873=== CONT TestParseSingleRange/multi-range_ignored2874=== CONT TestParseSingleRange/malformed_no_dash2875=== CONT TestParseSingleRange/unknown_unit2876--- PASS: TestParseSingleRange (0.00s)2877 --- PASS: TestParseSingleRange/none (0.00s)2878 --- PASS: TestParseSingleRange/open-ended (0.00s)2879 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2880 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2881 --- PASS: TestParseSingleRange/single_byte (0.00s)2882 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2883 --- PASS: TestParseSingleRange/suffix (0.00s)2884 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2885 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2886 --- PASS: TestParseSingleRange/closed (0.00s)2887 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2888 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2889 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2890 --- PASS: TestParseSingleRange/unknown_unit (0.00s)28912026/10/01 09:48:31 OK 20260628120000_add_object_size_and_stats.sql (27.9ms)28922026/10/01 09:48:31 OK 20260905000000_add_claims.sql (121.86ms)28932026/10/01 09:48:31 OK 20260920000000_drop_claims.sql (55.67ms)28942026/10/01 09:48:31 OK 20260923120000_add_pushes.sql (23.74ms)28952026/10/01 09:48:31 goose: successfully migrated database to version: 2026092312000028962026/10/01 09:48:31 OK 1_commit_pending_closure.sql (2.22ms)28972026/10/01 09:48:31 OK 2_object_stats_trigger.sql (312.5µs)28982026/10/01 09:48:31 OK 3_commit_push.sql (238µs)28992026/10/01 09:48:31 goose: up to current file version: 329002026-10-01 09:48:31.617 UTC [79801] ERROR: relation "goose_db_version" does not exist at character 3629012026-10-01 09:48:31.617 UTC [79801] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29022026/10/01 09:48:31 OK 20241026095416_initial_model.sql (305.01ms)29032026/10/01 09:48:31 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.724651628s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29042026/10/01 09:48:31 OK 20251210153512_drop_unused_gin_index.sql (19.13ms)29052026/10/01 09:48:31 OK 20251218171726_add_pins.sql (79.98ms)29062026/10/01 09:48:31 OK 20260628120000_add_object_size_and_stats.sql (59.56ms)29072026/10/01 09:48:31 OK 20260905000000_add_claims.sql (148.43ms)29082026/10/01 09:48:31 INFO Received uploads request method=POST path=/api/pending_closures2909--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.06s)29102026/10/01 09:48:32 OK 20260920000000_drop_claims.sql (88.8ms)29112026/10/01 09:48:32 OK 20260923120000_add_pushes.sql (24.41ms)29122026/10/01 09:48:32 goose: successfully migrated database to version: 2026092312000029132026/10/01 09:48:32 OK 1_commit_pending_closure.sql (1.52ms)29142026/10/01 09:48:32 OK 2_object_stats_trigger.sql (246.04µs)29152026/10/01 09:48:32 OK 3_commit_push.sql (196.17µs)29162026/10/01 09:48:32 goose: up to current file version: 329172026/10/01 09:48:32 OK 20241026095416_initial_model.sql (382.06ms)29182026/10/01 09:48:32 OK 20251210153512_drop_unused_gin_index.sql (19.15ms)29192026-10-01 09:48:32.151 UTC [79804] ERROR: relation "goose_db_version" does not exist at character 3629202026-10-01 09:48:32.151 UTC [79804] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29212026/10/01 09:48:32 OK 20251218171726_add_pins.sql (50.32ms)29222026/10/01 09:48:32 OK 20260628120000_add_object_size_and_stats.sql (62.51ms)29232026/10/01 09:48:32 OK 20260905000000_add_claims.sql (122.43ms)29242026/10/01 09:48:32 OK 20260920000000_drop_claims.sql (29.87ms)29252026/10/01 09:48:32 OK 20260923120000_add_pushes.sql (25.99ms)29262026/10/01 09:48:32 goose: successfully migrated database to version: 2026092312000029272026/10/01 09:48:32 OK 1_commit_pending_closure.sql (2ms)29282026/10/01 09:48:32 OK 2_object_stats_trigger.sql (467.83µs)29292026/10/01 09:48:32 OK 3_commit_push.sql (330.63µs)29302026/10/01 09:48:32 goose: up to current file version: 32931--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.03s)29322026/10/01 09:48:32 OK 20241026095416_initial_model.sql (324.14ms)29332026/10/01 09:48:32 OK 20251210153512_drop_unused_gin_index.sql (17.27ms)29342026/10/01 09:48:32 OK 20251218171726_add_pins.sql (24.03ms)29352026/10/01 09:48:32 OK 20260628120000_add_object_size_and_stats.sql (18.69ms)29362026-10-01 09:48:32.711 UTC [79819] ERROR: relation "goose_db_version" does not exist at character 3629372026-10-01 09:48:32.711 UTC [79819] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29382026/10/01 09:48:32 OK 20260905000000_add_claims.sql (84.68ms)29392026/10/01 09:48:32 OK 20260920000000_drop_claims.sql (9.92ms)29402026/10/01 09:48:32 OK 20260923120000_add_pushes.sql (4.97ms)29412026/10/01 09:48:32 goose: successfully migrated database to version: 2026092312000029422026/10/01 09:48:32 OK 1_commit_pending_closure.sql (1.81ms)29432026/10/01 09:48:32 OK 2_object_stats_trigger.sql (243.5µs)29442026/10/01 09:48:32 OK 3_commit_push.sql (172.46µs)29452026/10/01 09:48:32 goose: up to current file version: 32946=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2947=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2948=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2949=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2950=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2951=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2952=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2953=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2954=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2955=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected29562026/10/01 09:48:32 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]2957=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2958=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured29592026/10/01 09:48:32 WARN Authentication failed token_preview=eyJhbGciOi...598VRyToVQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2960--- PASS: TestService_AuthMiddleware_OIDC (5.15s)2961 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2962 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2963 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2964 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)29652026/10/01 09:48:33 OK 20241026095416_initial_model.sql (296.77ms)29662026/10/01 09:48:33 OK 20251210153512_drop_unused_gin_index.sql (26.44ms)29672026/10/01 09:48:33 OK 20251218171726_add_pins.sql (53.7ms)29682026/10/01 09:48:33 INFO Received uploads request method=POST path=/api/pending_closures29692026/10/01 09:48:33 OK 20260628120000_add_object_size_and_stats.sql (161.01ms)29702026/10/01 09:48:33 INFO Aborted multipart uploads count=029712026/10/01 09:48:33 WARN Force mode enabled - objects will be deleted immediately without grace period29722026/10/01 09:48:33 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=029732026/10/01 09:48:33 INFO Vacuumed table table=pending_closures29742026/10/01 09:48:33 OK 20260905000000_add_claims.sql (167.78ms)29752026/10/01 09:48:33 INFO Vacuumed table table=pending_objects29762026/10/01 09:48:33 INFO Vacuumed table table=multipart_uploads29772026/10/01 09:48:33 INFO Vacuumed table table=closures29782026/10/01 09:48:33 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-config29792026/10/01 09:48:33 INFO Vacuumed table table=objects29802026/10/01 09:48:33 OK 20260920000000_drop_claims.sql (110.62ms)29812026/10/01 09:48:33 OK 20260923120000_add_pushes.sql (24.76ms)29822026/10/01 09:48:33 goose: successfully migrated database to version: 2026092312000029832026/10/01 09:48:33 OK 1_commit_pending_closure.sql (1.24ms)29842026/10/01 09:48:33 OK 2_object_stats_trigger.sql (293.17µs)29852026/10/01 09:48:33 OK 3_commit_push.sql (215.92µs)29862026/10/01 09:48:33 goose: up to current file version: 32987--- PASS: TestGCSweepSkipsPendingObjects (5.50s)29882026/10/01 09:48:33 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.738431ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29892026/10/01 09:48:33 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=415.502877ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29902026-10-01 09:48:34.201 UTC [79838] ERROR: relation "goose_db_version" does not exist at character 3629912026-10-01 09:48:34.201 UTC [79838] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29922026-10-01 09:48:34.204 UTC [79839] ERROR: relation "goose_db_version" does not exist at character 3629932026-10-01 09:48:34.204 UTC [79839] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29942026/10/01 09:48:34 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=849.117644ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29952026-10-01 09:48:34.279 UTC [79840] ERROR: relation "goose_db_version" does not exist at character 3629962026-10-01 09:48:34.279 UTC [79840] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29972026/10/01 09:48:34 OK 20241026095416_initial_model.sql (74.81ms)29982026/10/01 09:48:34 OK 20241026095416_initial_model.sql (80.95ms)29992026/10/01 09:48:34 OK 20251210153512_drop_unused_gin_index.sql (4.21ms)30002026/10/01 09:48:34 OK 20251210153512_drop_unused_gin_index.sql (9.61ms)30012026/10/01 09:48:34 OK 20251218171726_add_pins.sql (18.29ms)30022026/10/01 09:48:34 OK 20251218171726_add_pins.sql (9.83ms)30032026/10/01 09:48:34 OK 20260628120000_add_object_size_and_stats.sql (19.92ms)30042026/10/01 09:48:34 OK 20260628120000_add_object_size_and_stats.sql (18.81ms)30052026/10/01 09:48:34 OK 20260905000000_add_claims.sql (45.51ms)30062026/10/01 09:48:34 OK 20260905000000_add_claims.sql (52.78ms)30072026/10/01 09:48:34 OK 20241026095416_initial_model.sql (104.54ms)30082026/10/01 09:48:34 OK 20251210153512_drop_unused_gin_index.sql (7.23ms)30092026/10/01 09:48:34 OK 20260920000000_drop_claims.sql (43.51ms)30102026/10/01 09:48:34 OK 20260920000000_drop_claims.sql (42.18ms)30112026/10/01 09:48:34 OK 20260923120000_add_pushes.sql (7.09ms)30122026/10/01 09:48:34 goose: successfully migrated database to version: 2026092312000030132026/10/01 09:48:34 OK 20251218171726_add_pins.sql (24.12ms)30142026/10/01 09:48:34 OK 1_commit_pending_closure.sql (917.96µs)30152026/10/01 09:48:34 OK 2_object_stats_trigger.sql (177.54µs)30162026/10/01 09:48:34 OK 3_commit_push.sql (157.46µs)30172026/10/01 09:48:34 goose: up to current file version: 330182026/10/01 09:48:34 OK 20260923120000_add_pushes.sql (19.03ms)30192026/10/01 09:48:34 goose: successfully migrated database to version: 2026092312000030202026/10/01 09:48:34 OK 1_commit_pending_closure.sql (887.38µs)30212026/10/01 09:48:34 OK 2_object_stats_trigger.sql (174.46µs)30222026/10/01 09:48:34 OK 3_commit_push.sql (150.46µs)30232026/10/01 09:48:34 goose: up to current file version: 330242026/10/01 09:48:34 OK 20260628120000_add_object_size_and_stats.sql (30.27ms)30252026/10/01 09:48:34 OK 20260905000000_add_claims.sql (50.37ms)30262026/10/01 09:48:34 OK 20260920000000_drop_claims.sql (63.67ms)30272026/10/01 09:48:34 OK 20260923120000_add_pushes.sql (12.56ms)30282026/10/01 09:48:34 goose: successfully migrated database to version: 2026092312000030292026/10/01 09:48:34 OK 1_commit_pending_closure.sql (2.74ms)30302026/10/01 09:48:34 OK 2_object_stats_trigger.sql (606.21µs)30312026/10/01 09:48:34 OK 3_commit_push.sql (416.25µs)30322026/10/01 09:48:34 goose: up to current file version: 330332026/10/01 09:48:35 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.749732895s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30342026/10/01 09:48:35 INFO Received uploads request method=POST path=/api/pending_closures30352026/10/01 09:48:35 INFO Aborted multipart uploads count=030362026/10/01 09:48:35 WARN Force mode enabled - objects will be deleted immediately without grace period30372026/10/01 09:48:35 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=030382026/10/01 09:48:35 INFO Vacuumed table table=pending_closures30392026/10/01 09:48:35 INFO Vacuumed table table=pending_objects30402026/10/01 09:48:35 INFO Vacuumed table table=multipart_uploads30412026/10/01 09:48:35 INFO Vacuumed table table=closures30422026/10/01 09:48:35 INFO Vacuumed table table=objects30432026/10/01 09:48:35 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30442026/10/01 09:48:35 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30452026/10/01 09:48:35 INFO Received uploads request method=POST path=/api/pending_closures30462026/10/01 09:48:35 INFO Aborted multipart uploads count=030472026/10/01 09:48:35 WARN Force mode enabled - objects will be deleted immediately without grace period30482026/10/01 09:48:35 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=030492026/10/01 09:48:35 INFO Vacuumed table table=pending_closures30502026/10/01 09:48:35 INFO Vacuumed table table=pending_objects30512026/10/01 09:48:35 INFO Vacuumed table table=multipart_uploads30522026/10/01 09:48:35 INFO Vacuumed table table=closures30532026/10/01 09:48:36 INFO Vacuumed table table=objects3054--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3055 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.08s)3056 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.04s)30572026/10/01 09:48:36 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"30582026/10/01 09:48:36 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-config30592026/10/01 09:48:36 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=213.18519ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30602026/10/01 09:48:37 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=375.231963ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30612026/10/01 09:48:37 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=862.705469ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30622026/10/01 09:48:38 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.726205464s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30632026/10/01 09:48:40 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_closures30642026/10/01 09:48:40 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.826857ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30652026/10/01 09:48:40 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=431.714666ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30662026/10/01 09:48:40 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=807.749765ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30672026/10/01 09:48:41 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.748062206s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3068--- PASS: TestClientErrorHandling (0.00s)3069 --- PASS: TestClientErrorHandling/InvalidStorePath (5.19s)3070 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.39s)3071 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.82s)3072PASS30732026-10-01 09:48:49.574 UTC [78141] LOG: received smart shutdown request30742026-10-01 09:48:49.577 UTC [78141] LOG: background worker "logical replication launcher" (PID 78159) exited with exit code 130752026-10-01 09:48:49.818 UTC [78151] LOG: shutting down30762026-10-01 09:48:49.819 UTC [78151] LOG: checkpoint starting: shutdown immediate30772026/10/01 09:48:53 ERROR failed to kill rustfs error="no such process"30782026/10/01 09:48:59 INFO killed rustfs30792026/10/01 09:48:59 ERROR failed to wait for rustfs error="signal: killed"30802026-10-01 09:49:03.666 UTC [78151] PANIC: could not fsync file "base/17885/17993": No such file or directory3081Running OIDC tests...3082=== RUN TestAudienceForIssuer3083=== PAUSE TestAudienceForIssuer3084=== RUN TestGlobMatch3085=== PAUSE TestGlobMatch3086=== RUN TestValidateToken_ValidToken3087=== PAUSE TestValidateToken_ValidToken3088=== RUN TestValidateToken_WrongAudience3089=== PAUSE TestValidateToken_WrongAudience3090=== RUN TestValidateToken_Expired3091=== PAUSE TestValidateToken_Expired3092=== RUN TestValidateToken_BoundClaimsMismatch3093=== PAUSE TestValidateToken_BoundClaimsMismatch3094=== RUN TestValidateToken_BoundSubjectMismatch3095=== PAUSE TestValidateToken_BoundSubjectMismatch3096=== RUN TestValidateToken_MultipleProviders3097=== PAUSE TestValidateToken_MultipleProviders3098=== RUN TestValidateToken_NoMatchingProvider3099=== PAUSE TestValidateToken_NoMatchingProvider3100=== RUN TestValidateToken_KubernetesServiceAccount3101=== PAUSE TestValidateToken_KubernetesServiceAccount3102=== RUN TestNewValidator_KubernetesRequiresCA3103=== PAUSE TestNewValidator_KubernetesRequiresCA3104=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3105=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3106=== RUN TestPins_ReservedForMatchingRule3107=== PAUSE TestPins_ReservedForMatchingRule3108=== RUN TestPins_TopLevelShorthand3109=== PAUSE TestPins_TopLevelShorthand3110=== RUN TestPins_ConfigValidation3111=== PAUSE TestPins_ConfigValidation3112=== RUN TestScopes_LegacyProviderDefaultsToWrite3113=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3114=== RUN TestScopes_Rules3115=== PAUSE TestScopes_Rules3116=== RUN TestScopes_ConfigValidation3117=== PAUSE TestScopes_ConfigValidation3118=== CONT TestAudienceForIssuer3119=== CONT TestValidateToken_KubernetesServiceAccount3120--- PASS: TestAudienceForIssuer (0.00s)3121=== CONT TestValidateToken_NoMatchingProvider3122=== CONT TestPins_ConfigValidation3123=== CONT TestValidateToken_WrongAudience3124=== CONT TestValidateToken_ValidToken3125=== CONT TestGlobMatch3126=== RUN TestGlobMatch/foo_foo3127=== PAUSE TestGlobMatch/foo_foo3128=== RUN TestGlobMatch/foo_bar3129=== PAUSE TestGlobMatch/foo_bar3130=== RUN TestGlobMatch/*_3131=== PAUSE TestGlobMatch/*_3132=== RUN TestGlobMatch/*_anything3133=== CONT TestPins_ReservedForMatchingRule3134=== CONT TestPins_TopLevelShorthand3135=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3136=== CONT TestNewValidator_KubernetesRequiresCA3137--- PASS: TestPins_ConfigValidation (0.00s)3138=== CONT TestScopes_Rules3139=== PAUSE TestGlobMatch/*_anything3140=== RUN TestGlobMatch/foo*_foo3141=== PAUSE TestGlobMatch/foo*_foo3142=== RUN TestGlobMatch/foo*_foobar3143=== PAUSE TestGlobMatch/foo*_foobar3144=== RUN TestGlobMatch/foo*_bar3145=== PAUSE TestGlobMatch/foo*_bar3146=== RUN TestGlobMatch/*bar_bar3147=== PAUSE TestGlobMatch/*bar_bar3148=== RUN TestGlobMatch/*bar_foobar3149=== PAUSE TestGlobMatch/*bar_foobar3150=== RUN TestGlobMatch/*bar_foo3151=== PAUSE TestGlobMatch/*bar_foo3152=== RUN TestGlobMatch/foo*bar_foobar3153=== PAUSE TestGlobMatch/foo*bar_foobar3154=== RUN TestGlobMatch/foo*bar_foo123bar3155=== PAUSE TestGlobMatch/foo*bar_foo123bar3156=== RUN TestGlobMatch/foo*bar_foobarbaz3157=== PAUSE TestGlobMatch/foo*bar_foobarbaz3158=== RUN TestGlobMatch/*/*_foo/bar3159=== PAUSE TestGlobMatch/*/*_foo/bar3160=== RUN TestGlobMatch/*/*_foo3161=== PAUSE TestGlobMatch/*/*_foo3162=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3163=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3164=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03165=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03166=== RUN TestGlobMatch/refs/*/main_refs/heads/main3167=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3168=== RUN TestGlobMatch/fo?_foo3169=== PAUSE TestGlobMatch/fo?_foo3170=== RUN TestGlobMatch/fo?_fo3171=== PAUSE TestGlobMatch/fo?_fo3172=== RUN TestGlobMatch/fo?_fooo3173=== PAUSE TestGlobMatch/fo?_fooo3174=== RUN TestGlobMatch/?oo_foo3175=== PAUSE TestGlobMatch/?oo_foo3176=== RUN TestGlobMatch/?oo_boo3177=== PAUSE TestGlobMatch/?oo_boo3178=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3179=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3180=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3181=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3182=== CONT TestScopes_ConfigValidation3183--- PASS: TestScopes_ConfigValidation (0.01s)3184=== CONT TestValidateToken_BoundSubjectMismatch31852026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54579/oidc31862026/10/01 09:49:58 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:545773187--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)3188=== CONT TestValidateToken_MultipleProviders31892026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54581/oidc3190--- PASS: TestPins_TopLevelShorthand (0.07s)3191=== CONT TestValidateToken_BoundClaimsMismatch3192--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)3193=== CONT TestScopes_LegacyProviderDefaultsToWrite31942026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54583/oidc3195--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)3196=== CONT TestValidateToken_Expired31972026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54585/oidc3198--- PASS: TestScopes_Rules (0.26s)3199=== CONT TestGlobMatch/foo_foo3200=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3201=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3202=== CONT TestGlobMatch/?oo_boo3203=== CONT TestGlobMatch/?oo_foo3204=== CONT TestGlobMatch/fo?_fooo3205=== CONT TestGlobMatch/fo?_fo3206=== CONT TestGlobMatch/fo?_foo3207=== CONT TestGlobMatch/refs/*/main_refs/heads/main3208=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03209=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3210=== CONT TestGlobMatch/*/*_foo3211=== CONT TestGlobMatch/*/*_foo/bar3212=== CONT TestGlobMatch/foo*bar_foobarbaz3213=== CONT TestGlobMatch/foo*bar_foo123bar3214=== CONT TestGlobMatch/foo*bar_foobar3215=== CONT TestGlobMatch/*bar_foo3216=== CONT TestGlobMatch/*bar_foobar3217=== CONT TestGlobMatch/*bar_bar3218=== CONT TestGlobMatch/foo*_bar3219=== CONT TestGlobMatch/foo*_foobar3220=== CONT TestGlobMatch/foo*_foo3221=== CONT TestGlobMatch/*_anything3222=== CONT TestGlobMatch/*_3223=== CONT TestGlobMatch/foo_bar3224--- PASS: TestGlobMatch (0.01s)3225 --- PASS: TestGlobMatch/foo_foo (0.00s)3226 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3227 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3228 --- PASS: TestGlobMatch/?oo_boo (0.00s)3229 --- PASS: TestGlobMatch/?oo_foo (0.00s)3230 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3231 --- PASS: TestGlobMatch/fo?_fo (0.00s)3232 --- PASS: TestGlobMatch/fo?_foo (0.00s)3233 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3234 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3235 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3236 --- PASS: TestGlobMatch/*/*_foo (0.00s)3237 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3238 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3239 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3240 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3241 --- PASS: TestGlobMatch/*bar_foo (0.00s)3242 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3243 --- PASS: TestGlobMatch/*bar_bar (0.00s)3244 --- PASS: TestGlobMatch/foo*_bar (0.00s)3245 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3246 --- PASS: TestGlobMatch/foo*_foo (0.00s)3247 --- PASS: TestGlobMatch/*_anything (0.00s)3248 --- PASS: TestGlobMatch/*_ (0.00s)3249 --- PASS: TestGlobMatch/foo_bar (0.00s)32502026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54587/oidc3251--- PASS: TestValidateToken_ValidToken (0.28s)32522026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54589/oidc3253--- PASS: TestValidateToken_WrongAudience (0.34s)32542026/10/01 09:49:58 http: TLS handshake error from 127.0.0.1:54592: read tcp 127.0.0.1:54591->127.0.0.1:54592: use of closed network connection3255--- PASS: TestNewValidator_KubernetesRequiresCA (0.34s)32562026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54596/oidc3257--- PASS: TestPins_ReservedForMatchingRule (0.39s)32582026/10/01 09:49:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54598/oidc3259--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.33s)32602026/10/01 09:49:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54593/oidc32612026/10/01 09:49:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54601/oidc3262--- PASS: TestValidateToken_MultipleProviders (0.42s)32632026/10/01 09:49:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54600/oidc3264--- PASS: TestValidateToken_NoMatchingProvider (0.61s)32652026/10/01 09:49:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54606/oidc3266--- PASS: TestValidateToken_Expired (0.48s)32672026/10/01 09:49:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233268--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.66s)3269PASS3270Running hook tests...3271=== RUN TestSendPathsEmpty3272=== PAUSE TestSendPathsEmpty3273=== RUN TestQueueEnqueueAndFetch3274=== PAUSE TestQueueEnqueueAndFetch3275=== RUN TestQueueDeduplication3276=== PAUSE TestQueueDeduplication3277=== RUN TestQueueRemove3278=== PAUSE TestQueueRemove3279=== RUN TestQueueFetchBatchLimit3280=== PAUSE TestQueueFetchBatchLimit3281=== RUN TestQueueRetryMovesToBack3282=== PAUSE TestQueueRetryMovesToBack3283=== RUN TestQueueFetchRemoveLifecycle3284=== PAUSE TestQueueFetchRemoveLifecycle3285=== RUN TestQueueConcurrentWriters3286=== PAUSE TestQueueConcurrentWriters3287=== RUN TestQueueRemoveLargeClosure3288=== PAUSE TestQueueRemoveLargeClosure3289=== RUN TestServerClientIntegration3290=== PAUSE TestServerClientIntegration3291=== RUN TestServerQueueError3292=== PAUSE TestServerQueueError3293=== RUN TestGetListenerSocketActivation3294 server_test.go:210: === RUN TestGetListenerSocketActivation3295 --- PASS: TestGetListenerSocketActivation (0.00s)3296 PASS3297 3298--- PASS: TestGetListenerSocketActivation (0.01s)3299=== RUN TestDrainIsolatesPoisonPath3300=== PAUSE TestDrainIsolatesPoisonPath3301=== RUN TestRunNotBlockedByPoisonHead3302=== PAUSE TestRunNotBlockedByPoisonHead3303=== RUN TestDrainGivesUpWhenServerDown3304=== PAUSE TestDrainGivesUpWhenServerDown3305=== RUN TestFailedPathPrunedByLaterClosure3306=== PAUSE TestFailedPathPrunedByLaterClosure3307=== RUN TestWorkerUploadsAndRemoves3308=== PAUSE TestWorkerUploadsAndRemoves3309=== RUN TestWorkerSkipsGCdPaths3310=== PAUSE TestWorkerSkipsGCdPaths3311=== RUN TestWorkerPrunesClosureDeps3312=== PAUSE TestWorkerPrunesClosureDeps3313=== RUN TestDrainTimeout3314=== PAUSE TestDrainTimeout3315=== CONT TestSendPathsEmpty3316--- PASS: TestSendPathsEmpty (0.00s)3317=== CONT TestDrainTimeout3318=== CONT TestServerClientIntegration3319=== CONT TestQueueRetryMovesToBack3320=== CONT TestFailedPathPrunedByLaterClosure3321=== CONT TestWorkerPrunesClosureDeps3322=== CONT TestWorkerSkipsGCdPaths3323=== CONT TestWorkerUploadsAndRemoves3324=== CONT TestQueueDeduplication3325=== CONT TestRunNotBlockedByPoisonHead3326=== CONT TestDrainGivesUpWhenServerDown3327--- PASS: TestServerClientIntegration (0.01s)3328=== CONT TestQueueConcurrentWriters33292026/10/01 09:49:59 INFO Upload queue status pending=233302026/10/01 09:49:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-77474-458540005/TestWorkerSkipsGCdPaths1853186206/002/nonexistent33312026/10/01 09:49:59 INFO Upload queue status pending=233322026/10/01 09:49:59 INFO Upload queue status pending=233332026/10/01 09:49:59 INFO Uploading batch count=233342026/10/01 09:49:59 INFO Uploading batch count=133352026/10/01 09:49:59 INFO Uploading batch count=133362026/10/01 09:49:59 INFO Uploading batch count=133372026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=133382026/10/01 09:49:59 INFO Uploading batch count=233392026/10/01 09:49:59 INFO Uploading batch count=133402026/10/01 09:49:59 INFO Uploading batch count=233412026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=233422026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainGivesUpWhenServerDown3789748841/002/a3343--- PASS: TestQueueRetryMovesToBack (0.01s)3344=== CONT TestQueueRemoveLargeClosure33452026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainGivesUpWhenServerDown3789748841/002/b33462026/10/01 09:49:59 INFO Upload queue status pending=333472026/10/01 09:49:59 INFO Uploading batch count=133482026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=133492026/10/01 09:49:59 INFO Uploading batch count=233502026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=233512026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainGivesUpWhenServerDown3789748841/002/c33522026/10/01 09:49:59 INFO Uploading batch count=133532026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainGivesUpWhenServerDown3789748841/002/d3354--- PASS: TestQueueDeduplication (0.01s)3355=== CONT TestQueueFetchBatchLimit33562026/10/01 09:49:59 INFO Uploading batch count=233572026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=233582026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainGivesUpWhenServerDown3789748841/002/e33592026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainGivesUpWhenServerDown3789748841/002/f33602026/10/01 09:49:59 ERROR Drain finished with paths left in queue remaining=103361--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)3362=== CONT TestQueueFetchRemoveLifecycle3363--- PASS: TestQueueFetchBatchLimit (0.00s)3364=== CONT TestQueueEnqueueAndFetch3365--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3366=== CONT TestDrainIsolatesPoisonPath3367--- PASS: TestQueueFetchRemoveLifecycle (0.00s)3368=== CONT TestServerQueueError33692026/10/01 09:49:59 ERROR Failed to queue paths error="permission denied" count=13370--- PASS: TestQueueEnqueueAndFetch (0.00s)3371=== CONT TestQueueRemove3372--- PASS: TestServerQueueError (0.00s)33732026/10/01 09:49:59 INFO Uploading batch count=433742026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=433752026/10/01 09:49:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-77474-458540005/TestDrainIsolatesPoisonPath1942793622/002/bbb33762026/10/01 09:49:59 INFO Uploading batch count=133772026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=133782026/10/01 09:49:59 INFO Uploading batch count=133792026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=133802026/10/01 09:49:59 INFO Uploading batch count=133812026/10/01 09:49:59 ERROR Upload failed error="upload failed" count=133822026/10/01 09:49:59 ERROR Drain finished with paths left in queue remaining=13383--- PASS: TestQueueRemove (0.00s)3384--- PASS: TestDrainIsolatesPoisonPath (0.01s)3385--- PASS: TestWorkerUploadsAndRemoves (0.03s)3386--- PASS: TestWorkerSkipsGCdPaths (0.03s)3387--- PASS: TestWorkerPrunesClosureDeps (0.03s)3388--- PASS: TestQueueRemoveLargeClosure (0.09s)3389--- PASS: TestQueueConcurrentWriters (0.13s)33902026/10/01 09:49:59 ERROR Upload failed error="context deadline exceeded" count=233912026/10/01 09:49:59 ERROR Drain finished with paths left in queue remaining=43392--- PASS: TestDrainTimeout (0.23s)33932026/10/01 09:50:00 INFO Uploading batch count=133942026/10/01 09:50:00 INFO Uploading batch count=133952026/10/01 09:50:00 INFO Uploading batch count=133962026/10/01 09:50:00 ERROR Upload failed error="upload failed" count=133972026/10/01 09:50:00 INFO Uploading batch count=133982026/10/01 09:50:00 ERROR Upload failed error="upload failed" count=133992026/10/01 09:50:00 INFO Uploading batch count=134002026/10/01 09:50:00 ERROR Upload failed error="upload failed" count=134012026/10/01 09:50:00 INFO Uploading batch count=134022026/10/01 09:50:00 ERROR Upload failed error="upload failed" count=134032026/10/01 09:50:00 ERROR Drain finished with paths left in queue remaining=13404--- PASS: TestRunNotBlockedByPoisonHead (1.02s)3405PASS