niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #311
· 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.39s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplitErrors96=== CONT TestConvertHashToNix3297--- PASS: TestShellSplitErrors (0.00s)98=== CONT TestScriptTokenEmptyCommand99--- PASS: TestScriptTokenEmptyCommand (0.00s)100=== CONT TestScriptTokenScriptFails101=== RUN TestConvertHashToNix32/SRI_format_to_Nix32102=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32103=== RUN TestConvertHashToNix32/already_Nix32_format104=== PAUSE TestConvertHashToNix32/already_Nix32_format105=== RUN TestConvertHashToNix32/invalid_format106=== CONT TestUploadMultipart_SupersededByPeer107=== RUN TestUploadMultipart_SupersededByPeer/exists108=== PAUSE TestUploadMultipart_SupersededByPeer/exists109=== CONT TestEncodeNixBase32WithRealHash110--- PASS: TestEncodeNixBase32WithRealHash (0.00s)111=== CONT TestScriptTokenBadJSON112=== CONT TestEncodeNixBase32113=== RUN TestEncodeNixBase32/test_string_hash114=== PAUSE TestEncodeNixBase32/test_string_hash115=== RUN TestEncodeNixBase32/empty_input116=== PAUSE TestEncodeNixBase32/empty_input117=== CONT TestScriptTokenEmptyToken118=== CONT TestDumpPathWriterError119=== CONT TestDumpPathSingleFile120=== CONT TestDumpPathMatchesNix121=== CONT TestStaticToken122--- PASS: TestStaticToken (0.00s)123=== CONT TestScriptTokenCachesUntilRefresh124=== PAUSE TestConvertHashToNix32/invalid_format125=== RUN TestUploadMultipart_SupersededByPeer/missing126=== CONT TestScriptTokenNoExpiryRerunsEveryCall127=== PAUSE TestUploadMultipart_SupersededByPeer/missing128=== CONT TestFileTokenEmpty129--- PASS: TestScriptTokenScriptFails (0.01s)130=== CONT TestFileTokenMissing131--- PASS: TestFileTokenEmpty (0.00s)132=== CONT TestFileTokenReadsAndCaches133--- PASS: TestDoServerRequestAttachesToken (0.01s)134=== CONT TestRateLimiterFeedback135=== RUN TestRateLimiterFeedback/429_enables_limiter136=== PAUSE TestRateLimiterFeedback/429_enables_limiter137=== RUN TestRateLimiterFeedback/503_enables_limiter138=== PAUSE TestRateLimiterFeedback/503_enables_limiter139=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter140=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter141=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter142=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter143=== CONT TestShellSplit144--- PASS: TestShellSplit (0.00s)145=== CONT TestDoWithRetry_BodyReplayedViaGetBody146--- PASS: TestFileTokenMissing (0.00s)147=== CONT TestResolveStorePath148--- PASS: TestResolveStorePath (0.00s)149=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1502026/10/01 09:40:00 WARN Rate limiter enabled after throttle name=server-test rate=5151--- PASS: TestFileTokenReadsAndCaches (0.00s)152=== CONT TestStreamPushReportsSignatures1532026/10/01 09:40:00 WARN Rate limiter enabled after throttle name=server-test rate=51542026/10/01 09:40:00 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:495131552026/10/01 09:40:00 ERROR Upload failed error=boom count=1156--- PASS: TestStreamPushReportsSignatures (0.00s)157=== CONT TestSetClientTLSErrors1582026/10/01 09:40:00 WARN Rate limiter backed off name=server-test rate=51592026/10/01 09:40:00 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:49513160--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)161=== CONT TestSetClientTLSDoesNotMutateDefaultTransport162=== RUN TestSetClientTLSErrors/missing_cert_file163=== PAUSE TestSetClientTLSErrors/missing_cert_file164=== RUN TestSetClientTLSErrors/missing_key_file165=== PAUSE TestSetClientTLSErrors/missing_key_file166=== RUN TestSetClientTLSErrors/missing_ca_file167=== PAUSE TestSetClientTLSErrors/missing_ca_file168=== RUN TestSetClientTLSErrors/invalid_ca_file169=== PAUSE TestSetClientTLSErrors/invalid_ca_file170=== CONT TestSetClientTLS171--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)172=== CONT TestClientSignaturesByStorePath173--- PASS: TestClientSignaturesByStorePath (0.00s)174=== CONT TestFilterOversizedClosures175=== RUN TestFilterOversizedClosures/no_limit_keeps_everything176=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything177=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped178=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped179=== RUN TestFilterOversizedClosures/all_closures_skipped180=== PAUSE TestFilterOversizedClosures/all_closures_skipped181=== CONT TestPartSizeForNAR182=== RUN TestPartSizeForNAR/zero_stays_at_minimum183=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum184=== RUN TestPartSizeForNAR/small_stays_at_minimum185=== PAUSE TestPartSizeForNAR/small_stays_at_minimum186=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum187=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum188=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts189=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts190=== RUN TestPartSizeForNAR/1_TiB191=== PAUSE TestPartSizeForNAR/1_TiB192=== RUN TestPartSizeForNAR/5_TiB_S3_max_object193=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object194=== RUN TestPartSizeForNAR/capped_at_5_GiB195=== PAUSE TestPartSizeForNAR/capped_at_5_GiB196=== CONT TestUploadMultipart_PartsInParallel197=== RUN TestSetClientTLS/rejects_connection_without_client_cert198=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert199=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA200=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA201=== RUN TestSetClientTLS/preserves_debug_logging_transport202--- PASS: TestScriptTokenBadJSON (0.01s)203=== CONT TestCaseHackSuffix204=== PAUSE TestSetClientTLS/preserves_debug_logging_transport205=== CONT TestStreamPushIsolatesFailures2062026/10/01 09:40:00 ERROR Upload failed error="bad path" count=3207--- PASS: TestStreamPushIsolatesFailures (0.00s)208=== CONT TestStreamPushRequestLine2092026/10/01 09:40:00 ERROR Upload failed error=boom count=1210--- PASS: TestScriptTokenEmptyToken (0.02s)211=== CONT TestStreamPushGivesUpOnDeadServer2122026/10/01 09:40:00 ERROR Upload failed error="connection refused" count=202132026/10/01 09:40:00 ERROR Server seems unavailable, giving up on batch untried=17214--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)215=== CONT TestParsePathInfoJSON216=== RUN TestParsePathInfoJSON/Nix_format217=== PAUSE TestParsePathInfoJSON/Nix_format218=== RUN TestParsePathInfoJSON/Lix_format219=== PAUSE TestParsePathInfoJSON/Lix_format220=== RUN TestParsePathInfoJSON/empty_input221=== PAUSE TestParsePathInfoJSON/empty_input222=== RUN TestParsePathInfoJSON/whitespace_only223=== PAUSE TestParsePathInfoJSON/whitespace_only224=== RUN TestParsePathInfoJSON/invalid_JSON225=== PAUSE TestParsePathInfoJSON/invalid_JSON226=== CONT TestPathInfoCACompatibility227=== RUN TestPathInfoCACompatibility/null_ca_field228=== PAUSE TestPathInfoCACompatibility/null_ca_field229=== RUN TestPathInfoCACompatibility/old_string_format_-_text230=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text231=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive232=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive233=== RUN TestPathInfoCACompatibility/new_structured_format_-_text234=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text235=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method236=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method237=== CONT TestParsePathInfoJSONMultiplePaths238=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths239=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths240=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths241=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths242=== CONT TestStreamPushBatchesUnderLoad243--- PASS: TestStreamPushRequestLine (0.02s)244=== CONT TestStreamPushReportsEveryPath245--- PASS: TestStreamPushReportsEveryPath (0.00s)246=== CONT TestRegisterUploadedObjectReusesConnections247--- PASS: TestDumpPathWriterError (0.06s)248=== CONT TestPathInfoHashCompatibility249=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)250=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)251=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon252=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon253=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI254=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI255=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512256=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512257=== CONT TestGetStorePathHash258=== RUN TestGetStorePathHash/valid_store_path259=== PAUSE TestGetStorePathHash/valid_store_path260=== RUN TestGetStorePathHash/basename_without_hyphen_should_error261=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error262=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error263=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error264=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error265=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error266=== CONT TestEncodeNixBase32/test_string_hash267=== CONT TestEncodeNixBase32/empty_input268--- PASS: TestEncodeNixBase32 (0.00s)269 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)270 --- PASS: TestEncodeNixBase32/empty_input (0.00s)271=== CONT TestConvertHashToNix32/SRI_format_to_Nix32272=== CONT TestConvertHashToNix32/invalid_format273=== CONT TestConvertHashToNix32/already_Nix32_format274--- PASS: TestConvertHashToNix32 (0.00s)275 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)276 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)277 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)278=== CONT TestUploadMultipart_SupersededByPeer/exists279=== CONT TestUploadMultipart_SupersededByPeer/missing280--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)281 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)282 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)283=== CONT TestRateLimiterFeedback/429_enables_limiter2842026/10/01 09:40:00 WARN Rate limiter enabled after throttle name=server-test rate=52852026/10/01 09:40:00 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:495922862026/10/01 09:40:00 WARN Rate limiter backed off name=server-test rate=5287=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter288--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)289=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter290=== CONT TestRateLimiterFeedback/503_enables_limiter2912026/10/01 09:40:00 WARN Rate limiter enabled after throttle name=server-test rate=52922026/10/01 09:40:00 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:49598293=== CONT TestSetClientTLSErrors/missing_cert_file294=== CONT TestSetClientTLSErrors/missing_ca_file2952026/10/01 09:40:00 WARN Rate limiter backed off name=server-test rate=5296--- PASS: TestRateLimiterFeedback (0.00s)297 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)298 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)299 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)300 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)301=== CONT TestSetClientTLSErrors/invalid_ca_file302=== CONT TestSetClientTLSErrors/missing_key_file303=== CONT TestFilterOversizedClosures/no_limit_keeps_everything304=== CONT TestFilterOversizedClosures/all_closures_skipped3052026/10/01 09:40:00 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50306=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3072026/10/01 09:40:00 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=2000308--- PASS: TestFilterOversizedClosures (0.00s)309 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)310 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)311 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)312=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts313=== CONT TestPartSizeForNAR/capped_at_5_GiB314=== CONT TestPartSizeForNAR/5_TiB_S3_max_object315=== CONT TestPartSizeForNAR/1_TiB316=== CONT TestPartSizeForNAR/small_stays_at_minimum317=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum318=== CONT TestSetClientTLS/rejects_connection_without_client_cert319=== CONT TestPartSizeForNAR/zero_stays_at_minimum320--- PASS: TestPartSizeForNAR (0.00s)321 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)322 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)323 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)324 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)325 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)326 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)327 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)328=== CONT TestSetClientTLS/preserves_debug_logging_transport329--- PASS: TestSetClientTLSErrors (0.00s)330 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)331 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)332 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)334--- PASS: TestScriptTokenCachesUntilRefresh (0.07s)335=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA336=== CONT TestParsePathInfoJSON/Nix_format337=== CONT TestPathInfoCACompatibility/null_ca_field338=== CONT TestParsePathInfoJSON/invalid_JSON339=== CONT TestParsePathInfoJSON/whitespace_only340=== CONT TestParsePathInfoJSON/empty_input341=== CONT TestParsePathInfoJSON/Lix_format342--- PASS: TestParsePathInfoJSON (0.00s)343 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)344 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)345 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)346 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)347 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)348=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths349=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method350=== CONT TestPathInfoCACompatibility/new_structured_format_-_text351=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive352=== CONT TestPathInfoCACompatibility/old_string_format_-_text353--- PASS: TestPathInfoCACompatibility (0.00s)354 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)355 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)356 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)357 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)358 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)359=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths360=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)361--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)362 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)363 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)364=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI365=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512366=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon367--- PASS: TestPathInfoHashCompatibility (0.00s)368 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)369 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)370 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)371 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)372=== CONT TestGetStorePathHash/valid_store_path373=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error374=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error375=== CONT TestGetStorePathHash/basename_without_hyphen_should_error376--- PASS: TestGetStorePathHash (0.00s)377 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)378 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)379 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)380 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)381--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)3822026/10/01 09:40:00 http: TLS handshake error from 127.0.0.1:49600: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.00s)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: TestStreamPushBatchesUnderLoad (0.10s)388--- PASS: TestDumpPathSingleFile (0.48s)389--- PASS: TestCaseHackSuffix (0.48s)390--- PASS: TestDumpPathMatchesNix (0.57s)391--- PASS: TestUploadMultipart_PartsInParallel (0.61s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld1".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-51549-3085653128/postgres267850904/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-51549-3085653128/postgres267850904/data -l logfile start421422/nix/var/nix/builds/nix-51549-3085653128/postgres267850904:5432 - no response4232026-10-01 09:40:03.454 UTC [52392] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:40:03.455 UTC [52392] LOG: listening on Unix socket "/nix/var/nix/builds/nix-51549-3085653128/postgres267850904/.s.PGSQL.5432"4252026-10-01 09:40:03.460 UTC [52401] LOG: database system was shut down at 2026-10-01 09:40:03 UTC4262026-10-01 09:40:03.461 UTC [52392] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-51549-3085653128/postgres267850904:5432 - accepting connections428{"timestamp":"2026-10-01T09:40:03.681848Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2752457e-40ba-40e3-abf4-d83d4f98172e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock466=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== RUN TestResolveDBConnectionString468=== PAUSE TestResolveDBConnectionString469=== RUN TestLeadElectsOneAndHandsOver470=== PAUSE TestLeadElectsOneAndHandsOver471=== RUN TestLeadIncumbentWinsAfterRestart4722026-10-01 09:40:03.953 UTC [52449] ERROR: relation "goose_db_version" does not exist at character 364732026-10-01 09:40:03.953 UTC [52449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4742026/10/01 09:40:03 OK 20241026095416_initial_model.sql (4.28ms)4752026/10/01 09:40:03 OK 20251210153512_drop_unused_gin_index.sql (586.88µs)4762026/10/01 09:40:03 OK 20251218171726_add_pins.sql (956.58µs)4772026/10/01 09:40:03 OK 20260628120000_add_object_size_and_stats.sql (933.79µs)4782026/10/01 09:40:03 OK 20260905000000_add_claims.sql (1.06ms)4792026/10/01 09:40:03 OK 20260920000000_drop_claims.sql (729.67µs)4802026/10/01 09:40:03 OK 20260923120000_add_pushes.sql (592.96µs)4812026/10/01 09:40:03 goose: successfully migrated database to version: 202609231200004822026/10/01 09:40:03 OK 1_commit_pending_closure.sql (1.42ms)4832026/10/01 09:40:03 OK 2_object_stats_trigger.sql (329.42µs)4842026/10/01 09:40:03 OK 3_commit_push.sql (271.58µs)4852026/10/01 09:40:03 goose: up to current file version: 34862026/10/01 09:40:04 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 09:40:04 INFO lead: released remote=192.0.2.1:12344882026/10/01 09:40:04 INFO lead: acquired remote=192.0.2.1:12344892026/10/01 09:40:04 INFO lead: released remote=192.0.2.1:1234490--- PASS: TestLeadIncumbentWinsAfterRestart (0.92s)491=== RUN TestLeadEndsOnShutdown492=== PAUSE TestLeadEndsOnShutdown493=== RUN TestGCAdvisoryLockBlocksConcurrentRun4942026-10-01 09:40:04.781 UTC [52492] ERROR: relation "goose_db_version" does not exist at character 364952026-10-01 09:40:04.781 UTC [52492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4962026/10/01 09:40:04 OK 20241026095416_initial_model.sql (4.37ms)4972026/10/01 09:40:04 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)4982026/10/01 09:40:04 OK 20251218171726_add_pins.sql (2.31ms)4992026/10/01 09:40:04 OK 20260628120000_add_object_size_and_stats.sql (2.27ms)5002026/10/01 09:40:04 OK 20260905000000_add_claims.sql (3.33ms)5012026/10/01 09:40:04 OK 20260920000000_drop_claims.sql (1.77ms)5022026/10/01 09:40:04 OK 20260923120000_add_pushes.sql (2.94ms)5032026/10/01 09:40:04 goose: successfully migrated database to version: 202609231200005042026/10/01 09:40:04 OK 1_commit_pending_closure.sql (2ms)5052026/10/01 09:40:04 OK 2_object_stats_trigger.sql (496.17µs)5062026/10/01 09:40:04 OK 3_commit_push.sql (442.13µs)5072026/10/01 09:40:04 goose: up to current file version: 3508--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.20s)509=== RUN TestGCBugBareHashReferences510=== PAUSE TestGCBugBareHashReferences511=== RUN TestGCMetrics512=== PAUSE TestGCMetrics513=== RUN TestPushDedupSurvivesConcurrentGC514=== PAUSE TestPushDedupSurvivesConcurrentGC515=== RUN TestDeduplicatedObjectsRecordedAsPending516=== PAUSE TestDeduplicatedObjectsRecordedAsPending517=== RUN TestGCSweepSkipsPendingObjects518=== PAUSE TestGCSweepSkipsPendingObjects519=== RUN TestTombstonedObjectOfferedWithoutWaiting520=== PAUSE TestTombstonedObjectOfferedWithoutWaiting521=== RUN TestGCSweepDeliversEachKeyOnce522=== PAUSE TestGCSweepDeliversEachKeyOnce523=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== RUN TestForceGCDuringPushOffersSweptObject526=== PAUSE TestForceGCDuringPushOffersSweptObject527=== RUN TestFailedS3DeleteKeepsTombstone528=== PAUSE TestFailedS3DeleteKeepsTombstone529=== RUN TestSweepSkipsRowsLockedByPush530=== PAUSE TestSweepSkipsRowsLockedByPush531=== RUN TestRegisterCompletedObjectNeedsPendingRow532=== PAUSE TestRegisterCompletedObjectNeedsPendingRow533=== RUN TestGetExistingObjectsLocksRows534=== PAUSE TestGetExistingObjectsLocksRows535=== RUN TestSweepRechecksPendingAfterLocking536=== PAUSE TestSweepRechecksPendingAfterLocking537=== RUN TestPushWaitsForSweepHoldingRow538=== PAUSE TestPushWaitsForSweepHoldingRow539=== RUN TestCommitRacingPendingCleanupKeepsObjects540=== PAUSE TestCommitRacingPendingCleanupKeepsObjects541=== RUN TestGCEndsOnShutdown542=== PAUSE TestGCEndsOnShutdown543=== RUN TestGCTaskStore_StartNew544=== PAUSE TestGCTaskStore_StartNew545=== RUN TestGCTaskStore_DeduplicateSameParams546=== PAUSE TestGCTaskStore_DeduplicateSameParams547=== RUN TestGCTaskStore_ConflictDifferentParams548=== PAUSE TestGCTaskStore_ConflictDifferentParams549=== RUN TestGCTaskStore_GetEmpty550=== PAUSE TestGCTaskStore_GetEmpty551=== RUN TestGCTaskStore_GetReturnsLatest552=== PAUSE TestGCTaskStore_GetReturnsLatest553=== RUN TestGCTaskStore_CompletedAllowsNewTask554=== PAUSE TestGCTaskStore_CompletedAllowsNewTask555=== RUN TestGCTaskStore_PhaseUpdates556=== PAUSE TestGCTaskStore_PhaseUpdates557=== RUN TestGCTaskStore_Fail558=== PAUSE TestGCTaskStore_Fail559=== RUN TestGracefulShutdownDrainsInflight560=== PAUSE TestGracefulShutdownDrainsInflight561=== RUN TestService_healthCheckHandler562=== PAUSE TestService_healthCheckHandler563=== RUN TestService_readinessHandler564=== PAUSE TestService_readinessHandler565=== RUN TestGenerateLandingPage566=== PAUSE TestGenerateLandingPage567=== RUN TestCacheConfigHandlerMaxNarSize568=== PAUSE TestCacheConfigHandlerMaxNarSize569=== RUN TestCreatePendingClosureRejectsOversizedNAR570=== PAUSE TestCreatePendingClosureRejectsOversizedNAR571=== RUN TestNARDeduplicationMetadataUploadBug572=== PAUSE TestNARDeduplicationMetadataUploadBug573=== RUN TestMetricsInventory574=== PAUSE TestMetricsInventory575=== RUN TestService_NativeMTLS576=== PAUSE TestService_NativeMTLS577=== RUN TestServerTLSConfig578=== PAUSE TestServerTLSConfig579=== RUN TestMultipartCleanup580=== PAUSE TestMultipartCleanup581=== RUN TestObjectStatsTrigger582=== PAUSE TestObjectStatsTrigger583=== RUN TestOrphanedObjectsGC584=== PAUSE TestOrphanedObjectsGC585=== RUN TestOrphanedObjectsGCStressTest586=== PAUSE TestOrphanedObjectsGCStressTest587=== RUN TestCreatePin_ReservedPins588=== PAUSE TestCreatePin_ReservedPins589=== RUN TestPresentReportsOnlyClosureRoots590=== PAUSE TestPresentReportsOnlyClosureRoots591=== RUN TestPresentNotReportedWhileGCDeletesClosure592=== PAUSE TestPresentNotReportedWhileGCDeletesClosure593=== RUN TestParseSingleRange594=== PAUSE TestParseSingleRange595=== RUN TestProxyHeadersOnlyTrustedOnSocket596=== PAUSE TestProxyHeadersOnlyTrustedOnSocket597=== RUN TestIsValidCachePath598=== PAUSE TestIsValidCachePath599=== RUN TestReadProxyNarinfo600=== PAUSE TestReadProxyNarinfo601=== RUN TestReadProxyNarinfoAlreadyDecompressed602=== PAUSE TestReadProxyNarinfoAlreadyDecompressed603=== RUN TestReadProxyNarStreaming604=== PAUSE TestReadProxyNarStreaming605=== RUN TestReadProxy404606=== PAUSE TestReadProxy404607=== RUN TestReadProxyInvalidPath608=== PAUSE TestReadProxyInvalidPath609=== RUN TestReadProxyHead610=== PAUSE TestReadProxyHead611=== RUN TestReadProxyConditionalGet612=== PAUSE TestReadProxyConditionalGet613=== RUN TestReadProxyRootRedirectsToIndexHTML614=== PAUSE TestReadProxyRootRedirectsToIndexHTML615=== RUN TestReadProxyDisabled616=== PAUSE TestReadProxyDisabled617=== RUN TestReadRedirectNar618=== PAUSE TestReadRedirectNar619=== RUN TestReadRedirectKeepsNarinfoProxied620=== PAUSE TestReadRedirectKeepsNarinfoProxied621=== RUN TestReadProxyRangeRequest622=== PAUSE TestReadProxyRangeRequest623=== RUN TestReadRedirectUsesPublicS3URL624=== PAUSE TestReadRedirectUsesPublicS3URL625=== RUN TestPush_OverlappingRootsStoreOneRowPerKey626=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey627=== RUN TestPush_CompleteCommitsEveryRoot628=== PAUSE TestPush_CompleteCommitsEveryRoot629=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit630=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit631=== RUN TestPush_RejectsBadRequests632=== PAUSE TestPush_RejectsBadRequests633=== RUN TestPush_SignsNarinfosOfItsPendingObjects634=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects635=== RUN TestRedundantMultipartUpload636=== PAUSE TestRedundantMultipartUpload637=== RUN TestCompleteMultipartUpload_ErrorButObjectExists638=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists639=== RUN TestCompletedNarNotReofferedAcrossClosures640=== PAUSE TestCompletedNarNotReofferedAcrossClosures641=== RUN TestPresignedUploadRegisteredBeforeCommit642=== PAUSE TestPresignedUploadRegisteredBeforeCommit643=== RUN TestService_Rustfstest644=== PAUSE TestService_Rustfstest645=== RUN TestParseSize646=== PAUSE TestParseSize647=== RUN TestSkippedUploadsHandler648=== PAUSE TestSkippedUploadsHandler649=== RUN TestSystemdListenerNotActivated650--- PASS: TestSystemdListenerNotActivated (0.00s)651=== RUN TestWatchdogBeatsWhenHealthy652--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)653=== RUN TestWatchdogSkipsWhenUnhealthy6542026/10/01 09:40:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/01 09:40:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:40:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"664--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)665=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle666=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle667=== RUN TestProxyWriteTimeout668=== PAUSE TestProxyWriteTimeout669=== RUN TestIsValidUploadKey670=== PAUSE TestIsValidUploadKey671=== RUN TestUploadHandlersRejectInvalidKeys672=== PAUSE TestUploadHandlersRejectInvalidKeys673=== RUN TestUploadHandlersRejectOversizedBody674=== PAUSE TestUploadHandlersRejectOversizedBody675=== RUN TestService_cleanupPendingClosuresHandler676=== PAUSE TestService_cleanupPendingClosuresHandler677=== RUN TestService_createPendingClosureHandler678=== PAUSE TestService_createPendingClosureHandler679=== RUN TestService_verifyS3Integrity680=== PAUSE TestService_verifyS3Integrity681=== RUN TestCompleteMultipartUnregistered682=== PAUSE TestCompleteMultipartUnregistered683=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT684=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT685=== CONT TestService_AuthMiddleware686=== CONT TestCacheConfigHandlerMaxNarSize687=== CONT TestReadRedirectKeepsNarinfoProxied688=== CONT TestParseSingleRange689=== RUN TestParseSingleRange/none690=== PAUSE TestParseSingleRange/none691=== CONT TestGCSweepSkipsPendingObjects692=== CONT TestGenerateLandingPage693--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)694=== CONT TestGCTaskStore_PhaseUpdates695--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)696=== CONT TestGCTaskStore_CompletedAllowsNewTask697--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)698=== CONT TestGCTaskStore_GetReturnsLatest699--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)700=== CONT TestGCTaskStore_GetEmpty701--- PASS: TestGCTaskStore_GetEmpty (0.00s)702=== CONT TestService_readinessHandler703=== CONT TestService_healthCheckHandler704=== CONT TestGracefulShutdownDrainsInflight705=== CONT TestGCTaskStore_Fail706--- PASS: TestGCTaskStore_Fail (0.00s)707=== CONT TestGCTaskStore_DeduplicateSameParams708=== RUN TestParseSingleRange/unknown_unit709=== PAUSE TestParseSingleRange/unknown_unit710=== CONT TestGCTaskStore_ConflictDifferentParams711=== CONT TestGCEndsOnShutdown712--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)713--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)714=== CONT TestGCTaskStore_StartNew715--- PASS: TestGCTaskStore_StartNew (0.00s)716=== CONT TestCommitRacingPendingCleanupKeepsObjects717=== RUN TestParseSingleRange/multi-range_ignored718=== PAUSE TestParseSingleRange/multi-range_ignored719=== RUN TestParseSingleRange/malformed_no_dash720=== PAUSE TestParseSingleRange/malformed_no_dash721=== RUN TestParseSingleRange/malformed_both_empty722=== PAUSE TestParseSingleRange/malformed_both_empty723=== RUN TestParseSingleRange/malformed_end_before_start724=== PAUSE TestParseSingleRange/malformed_end_before_start725=== RUN TestParseSingleRange/closed726=== PAUSE TestParseSingleRange/closed727=== RUN TestParseSingleRange/open-ended728=== PAUSE TestParseSingleRange/open-ended729=== RUN TestParseSingleRange/end_clamped_to_size730=== PAUSE TestParseSingleRange/end_clamped_to_size7312026/10/01 09:40:05 INFO Starting HTTP server address=127.0.0.1:49620732=== RUN TestParseSingleRange/suffix733=== PAUSE TestParseSingleRange/suffix734=== RUN TestParseSingleRange/suffix_exceeds_size735=== PAUSE TestParseSingleRange/suffix_exceeds_size736=== RUN TestParseSingleRange/single_byte737=== PAUSE TestParseSingleRange/single_byte738=== RUN TestParseSingleRange/start_past_EOF739=== PAUSE TestParseSingleRange/start_past_EOF740=== RUN TestParseSingleRange/start_far_past_EOF741=== PAUSE TestParseSingleRange/start_far_past_EOF742=== CONT TestPushWaitsForSweepHoldingRow7432026/10/01 09:40:05 INFO Shutdown signal received, draining in-flight requests timeout=10s744--- PASS: TestGenerateLandingPage (0.01s)745=== CONT TestSweepRechecksPendingAfterLocking746--- PASS: TestGracefulShutdownDrainsInflight (0.08s)747=== CONT TestGetExistingObjectsLocksRows7482026-10-01 09:40:05.431 UTC [52556] ERROR: relation "goose_db_version" does not exist at character 367492026-10-01 09:40:05.431 UTC [52556] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026/10/01 09:40:05 OK 20241026095416_initial_model.sql (15.34ms)7512026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)7522026/10/01 09:40:05 OK 20251218171726_add_pins.sql (2.54ms)7532026-10-01 09:40:05.461 UTC [52557] ERROR: relation "goose_db_version" does not exist at character 367542026-10-01 09:40:05.461 UTC [52557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7552026-10-01 09:40:05.461 UTC [52558] ERROR: relation "goose_db_version" does not exist at character 367562026-10-01 09:40:05.461 UTC [52558] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7572026-10-01 09:40:05.463 UTC [52559] ERROR: relation "goose_db_version" does not exist at character 367582026-10-01 09:40:05.463 UTC [52559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7592026/10/01 09:40:05 OK 20260628120000_add_object_size_and_stats.sql (2.42ms)7602026-10-01 09:40:05.464 UTC [52560] ERROR: relation "goose_db_version" does not exist at character 367612026-10-01 09:40:05.464 UTC [52560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7622026/10/01 09:40:05 OK 20260905000000_add_claims.sql (3.2ms)7632026/10/01 09:40:05 OK 20260920000000_drop_claims.sql (1.61ms)7642026/10/01 09:40:05 OK 20260923120000_add_pushes.sql (1.57ms)7652026/10/01 09:40:05 goose: successfully migrated database to version: 202609231200007662026/10/01 09:40:05 OK 1_commit_pending_closure.sql (2.01ms)7672026/10/01 09:40:05 OK 2_object_stats_trigger.sql (830.79µs)7682026/10/01 09:40:05 OK 3_commit_push.sql (425.58µs)7692026/10/01 09:40:05 goose: up to current file version: 37702026/10/01 09:40:05 OK 20241026095416_initial_model.sql (8.9ms)7712026/10/01 09:40:05 OK 20241026095416_initial_model.sql (9.87ms)7722026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)7732026/10/01 09:40:05 OK 20241026095416_initial_model.sql (8.48ms)7742026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (8.28ms)7752026/10/01 09:40:05 OK 20241026095416_initial_model.sql (17.56ms)7762026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (8.07ms)7772026/10/01 09:40:05 OK 20251218171726_add_pins.sql (9.66ms)7782026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (8.73ms)7792026/10/01 09:40:05 OK 20251218171726_add_pins.sql (18.23ms)7802026/10/01 09:40:05 OK 20251218171726_add_pins.sql (17.62ms)7812026/10/01 09:40:05 OK 20260628120000_add_object_size_and_stats.sql (16.72ms)7822026/10/01 09:40:05 OK 20251218171726_add_pins.sql (8.94ms)7832026/10/01 09:40:05 OK 20260628120000_add_object_size_and_stats.sql (10.55ms)7842026/10/01 09:40:05 OK 20260628120000_add_object_size_and_stats.sql (10.75ms)7852026/10/01 09:40:05 OK 20260628120000_add_object_size_and_stats.sql (19.18ms)7862026/10/01 09:40:05 OK 20260905000000_add_claims.sql (20.97ms)7872026/10/01 09:40:05 OK 20260905000000_add_claims.sql (13.21ms)7882026/10/01 09:40:05 OK 20260905000000_add_claims.sql (5.88ms)7892026/10/01 09:40:05 OK 20260905000000_add_claims.sql (14.5ms)7902026/10/01 09:40:05 OK 20260920000000_drop_claims.sql (19.65ms)7912026/10/01 09:40:05 OK 20260920000000_drop_claims.sql (16.02ms)7922026/10/01 09:40:05 OK 20260920000000_drop_claims.sql (17.25ms)7932026/10/01 09:40:05 OK 20260920000000_drop_claims.sql (17.46ms)7942026/10/01 09:40:05 OK 20260923120000_add_pushes.sql (8.12ms)7952026/10/01 09:40:05 goose: successfully migrated database to version: 202609231200007962026/10/01 09:40:05 OK 20260923120000_add_pushes.sql (7.76ms)7972026/10/01 09:40:05 goose: successfully migrated database to version: 202609231200007982026/10/01 09:40:05 OK 20260923120000_add_pushes.sql (7.81ms)7992026/10/01 09:40:05 goose: successfully migrated database to version: 202609231200008002026/10/01 09:40:05 OK 20260923120000_add_pushes.sql (6.82ms)8012026/10/01 09:40:05 goose: successfully migrated database to version: 202609231200008022026/10/01 09:40:05 OK 1_commit_pending_closure.sql (1.92ms)8032026/10/01 09:40:05 OK 1_commit_pending_closure.sql (1.95ms)8042026/10/01 09:40:05 OK 1_commit_pending_closure.sql (1.93ms)8052026/10/01 09:40:05 OK 1_commit_pending_closure.sql (1.77ms)8062026/10/01 09:40:05 OK 2_object_stats_trigger.sql (557.17µs)8072026/10/01 09:40:05 OK 2_object_stats_trigger.sql (512.25µs)8082026/10/01 09:40:05 OK 2_object_stats_trigger.sql (493.5µs)8092026/10/01 09:40:05 OK 3_commit_push.sql (374.33µs)8102026/10/01 09:40:05 goose: up to current file version: 38112026/10/01 09:40:05 OK 2_object_stats_trigger.sql (483.46µs)8122026/10/01 09:40:05 OK 3_commit_push.sql (375.42µs)8132026/10/01 09:40:05 goose: up to current file version: 38142026/10/01 09:40:05 OK 3_commit_push.sql (404.17µs)8152026/10/01 09:40:05 goose: up to current file version: 38162026/10/01 09:40:05 OK 3_commit_push.sql (376.08µs)8172026/10/01 09:40:05 goose: up to current file version: 38182026/10/01 09:40:05 WARN readiness check failed error="closed pool"819--- PASS: TestService_readinessHandler (0.48s)820=== CONT TestRegisterCompletedObjectNeedsPendingRow8212026-10-01 09:40:05.781 UTC [52590] ERROR: relation "goose_db_version" does not exist at character 368222026-10-01 09:40:05.781 UTC [52590] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8232026-10-01 09:40:05.786 UTC [52589] ERROR: relation "goose_db_version" does not exist at character 368242026-10-01 09:40:05.786 UTC [52589] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026-10-01 09:40:05.786 UTC [52588] ERROR: relation "goose_db_version" does not exist at character 368262026-10-01 09:40:05.786 UTC [52588] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8272026-10-01 09:40:05.818 UTC [52591] ERROR: relation "goose_db_version" does not exist at character 368282026-10-01 09:40:05.818 UTC [52591] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8292026/10/01 09:40:05 INFO Aborted multipart uploads count=08302026/10/01 09:40:05 WARN Force mode enabled - objects will be deleted immediately without grace period8312026/10/01 09:40: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=08322026/10/01 09:40:05 INFO Vacuumed table table=pending_closures8332026/10/01 09:40:05 INFO Vacuumed table table=pending_objects8342026/10/01 09:40:05 INFO Vacuumed table table=multipart_uploads8352026/10/01 09:40:05 INFO Vacuumed table table=closures8362026/10/01 09:40:05 OK 20241026095416_initial_model.sql (94.28ms)8372026/10/01 09:40:05 OK 20241026095416_initial_model.sql (116.32ms)8382026/10/01 09:40:05 OK 20241026095416_initial_model.sql (61.01ms)8392026/10/01 09:40:05 INFO Vacuumed table table=objects8402026/10/01 09:40:05 OK 20241026095416_initial_model.sql (119.41ms)8412026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (26.47ms)8422026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (26.37ms)8432026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (12.04ms)8442026/10/01 09:40:05 OK 20251210153512_drop_unused_gin_index.sql (30.06ms)845--- PASS: TestSweepRechecksPendingAfterLocking (0.81s)846=== CONT TestSweepSkipsRowsLockedByPush8472026/10/01 09:40:06 OK 20251218171726_add_pins.sql (62.58ms)8482026/10/01 09:40:06 OK 20251218171726_add_pins.sql (62.75ms)8492026/10/01 09:40:06 OK 20251218171726_add_pins.sql (59.12ms)8502026/10/01 09:40:06 OK 20251218171726_add_pins.sql (62.69ms)8512026-10-01 09:40:06.037 UTC [52607] ERROR: relation "goose_db_version" does not exist at character 368522026-10-01 09:40:06.037 UTC [52607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8532026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (21.35ms)8542026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (21.49ms)8552026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (31.45ms)8562026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (32.54ms)8572026/10/01 09:40:06 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"858--- PASS: TestService_AuthMiddleware (0.93s)859=== CONT TestFailedS3DeleteKeepsTombstone8602026/10/01 09:40:06 OK 20260905000000_add_claims.sql (49.14ms)8612026/10/01 09:40:06 OK 20260905000000_add_claims.sql (59.5ms)8622026/10/01 09:40:06 OK 20260905000000_add_claims.sql (65.92ms)8632026/10/01 09:40:06 OK 20260905000000_add_claims.sql (59.82ms)8642026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (22.94ms)8652026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (28.25ms)8662026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (34.6ms)8672026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (35.21ms)8682026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (7.76ms)8692026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200008702026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (8.52ms)8712026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200008722026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (8.5ms)8732026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200008742026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (8.51ms)8752026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200008762026/10/01 09:40:06 OK 1_commit_pending_closure.sql (2.53ms)8772026/10/01 09:40:06 OK 1_commit_pending_closure.sql (2.82ms)8782026/10/01 09:40:06 OK 1_commit_pending_closure.sql (3ms)8792026/10/01 09:40:06 OK 2_object_stats_trigger.sql (632.17µs)8802026/10/01 09:40:06 OK 1_commit_pending_closure.sql (3.17ms)8812026/10/01 09:40:06 OK 3_commit_push.sql (822.42µs)8822026/10/01 09:40:06 goose: up to current file version: 38832026/10/01 09:40:06 OK 2_object_stats_trigger.sql (1.16ms)8842026/10/01 09:40:06 OK 2_object_stats_trigger.sql (978.46µs)8852026/10/01 09:40:06 OK 2_object_stats_trigger.sql (863.75µs)8862026/10/01 09:40:06 OK 3_commit_push.sql (548.42µs)8872026/10/01 09:40:06 goose: up to current file version: 38882026/10/01 09:40:06 OK 3_commit_push.sql (625.88µs)8892026/10/01 09:40:06 goose: up to current file version: 38902026/10/01 09:40:06 OK 3_commit_push.sql (686.75µs)8912026/10/01 09:40:06 goose: up to current file version: 38922026/10/01 09:40:06 OK 20241026095416_initial_model.sql (84.23ms)8932026/10/01 09:40:06 OK 20251210153512_drop_unused_gin_index.sql (7.44ms)8942026/10/01 09:40:06 OK 20251218171726_add_pins.sql (11.39ms)8952026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (7.77ms)8962026/10/01 09:40:06 OK 20260905000000_add_claims.sql (14.44ms)8972026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (14.63ms)8982026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (8.45ms)8992026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200009002026/10/01 09:40:06 OK 1_commit_pending_closure.sql (2.33ms)9012026/10/01 09:40:06 OK 2_object_stats_trigger.sql (2.5ms)9022026/10/01 09:40:06 OK 3_commit_push.sql (622.38µs)9032026/10/01 09:40:06 goose: up to current file version: 3904--- PASS: TestGCEndsOnShutdown (1.16s)905=== CONT TestForceGCDuringPushOffersSweptObject906=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows907=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows908=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check909=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check910=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9112026-10-01 09:40:06.384 UTC [52622] ERROR: relation "goose_db_version" does not exist at character 369122026-10-01 09:40:06.384 UTC [52622] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9132026/10/01 09:40:06 OK 20241026095416_initial_model.sql (40.87ms)9142026-10-01 09:40:06.469 UTC [52624] ERROR: relation "goose_db_version" does not exist at character 369152026-10-01 09:40:06.469 UTC [52624] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9162026/10/01 09:40:06 OK 20251210153512_drop_unused_gin_index.sql (24.38ms)9172026-10-01 09:40:06.485 UTC [52625] ERROR: relation "goose_db_version" does not exist at character 369182026-10-01 09:40:06.485 UTC [52625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9192026/10/01 09:40:06 OK 20251218171726_add_pins.sql (10.2ms)9202026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (11.88ms)9212026/10/01 09:40:06 OK 20260905000000_add_claims.sql (27.64ms)9222026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (19.21ms)923--- PASS: TestReadRedirectKeepsNarinfoProxied (1.40s)924=== CONT TestGCSweepDeliversEachKeyOnce9252026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (15.1ms)9262026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200009272026/10/01 09:40:06 OK 1_commit_pending_closure.sql (1.68ms)9282026/10/01 09:40:06 OK 2_object_stats_trigger.sql (296.58µs)9292026/10/01 09:40:06 OK 3_commit_push.sql (289µs)9302026/10/01 09:40:06 goose: up to current file version: 39312026/10/01 09:40:06 OK 20241026095416_initial_model.sql (86.69ms)9322026/10/01 09:40:06 OK 20241026095416_initial_model.sql (75.53ms)9332026/10/01 09:40:06 OK 20251210153512_drop_unused_gin_index.sql (7.16ms)9342026/10/01 09:40:06 OK 20251210153512_drop_unused_gin_index.sql (16.46ms)9352026/10/01 09:40:06 OK 20251218171726_add_pins.sql (38.39ms)9362026/10/01 09:40:06 OK 20251218171726_add_pins.sql (27.48ms)9372026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (21.61ms)9382026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (22.65ms)9392026-10-01 09:40:06.673 UTC [52632] ERROR: relation "goose_db_version" does not exist at character 369402026-10-01 09:40:06.673 UTC [52632] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9412026/10/01 09:40:06 OK 20260905000000_add_claims.sql (17.52ms)9422026/10/01 09:40:06 OK 20260905000000_add_claims.sql (16.98ms)9432026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (14.87ms)9442026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (15.39ms)9452026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (6.08ms)9462026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200009472026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (6.15ms)9482026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200009492026/10/01 09:40:06 OK 1_commit_pending_closure.sql (1.6ms)9502026/10/01 09:40:06 OK 1_commit_pending_closure.sql (1.77ms)9512026/10/01 09:40:06 OK 2_object_stats_trigger.sql (526.75µs)9522026/10/01 09:40:06 OK 2_object_stats_trigger.sql (474.96µs)9532026/10/01 09:40:06 OK 3_commit_push.sql (325.63µs)9542026/10/01 09:40:06 goose: up to current file version: 39552026/10/01 09:40:06 OK 3_commit_push.sql (316.75µs)9562026/10/01 09:40:06 goose: up to current file version: 39572026/10/01 09:40:06 OK 20241026095416_initial_model.sql (39.08ms)9582026/10/01 09:40:06 OK 20251210153512_drop_unused_gin_index.sql (9.15ms)9592026/10/01 09:40:06 OK 20251218171726_add_pins.sql (3.71ms)9602026/10/01 09:40:06 OK 20260628120000_add_object_size_and_stats.sql (17.23ms)9612026/10/01 09:40:06 INFO Received uploads request method=POST path=/api/pending_closures9622026/10/01 09:40:06 OK 20260905000000_add_claims.sql (38.66ms)9632026/10/01 09:40:06 INFO Aborted multipart uploads count=09642026/10/01 09:40:06 WARN Force mode enabled - objects will be deleted immediately without grace period9652026/10/01 09:40:06 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=09662026/10/01 09:40:06 INFO Vacuumed table table=pending_closures9672026/10/01 09:40:06 OK 20260920000000_drop_claims.sql (21.84ms)9682026/10/01 09:40:06 INFO Vacuumed table table=pending_objects9692026/10/01 09:40:06 INFO Vacuumed table table=multipart_uploads9702026/10/01 09:40:06 INFO Vacuumed table table=closures9712026/10/01 09:40:06 OK 20260923120000_add_pushes.sql (10.92ms)9722026/10/01 09:40:06 goose: successfully migrated database to version: 202609231200009732026/10/01 09:40:06 OK 1_commit_pending_closure.sql (1.27ms)9742026/10/01 09:40:06 OK 2_object_stats_trigger.sql (268.96µs)9752026/10/01 09:40:06 OK 3_commit_push.sql (229.54µs)9762026/10/01 09:40:06 goose: up to current file version: 39772026/10/01 09:40:06 INFO Vacuumed table table=objects978--- PASS: TestGCSweepSkipsPendingObjects (1.70s)979=== CONT TestTombstonedObjectOfferedWithoutWaiting980--- PASS: TestService_healthCheckHandler (1.79s)981=== CONT TestCacheConfigHandler982=== RUN TestCacheConfigHandler/full_config,_no_issuer983=== PAUSE TestCacheConfigHandler/full_config,_no_issuer984=== RUN TestCacheConfigHandler/no_cache_url_configured985=== PAUSE TestCacheConfigHandler/no_cache_url_configured986=== RUN TestCacheConfigHandler/no_signing_keys987=== PAUSE TestCacheConfigHandler/no_signing_keys988=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator989=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator990=== CONT TestClientMultipleUploads9912026/10/01 09:40:07 INFO Aborted multipart uploads count=09922026/10/01 09:40:07 WARN Force mode enabled - objects will be deleted immediately without grace period9932026/10/01 09:40:07 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=09942026/10/01 09:40:07 INFO Vacuumed table table=pending_closures9952026/10/01 09:40:07 INFO Vacuumed table table=pending_objects9962026/10/01 09:40:07 INFO Vacuumed table table=multipart_uploads9972026/10/01 09:40:07 INFO Vacuumed table table=closures9982026/10/01 09:40:07 INFO Vacuumed table table=objects999--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.09s)1000=== CONT TestClientIntegration10012026/10/01 09:40:07 INFO Received uploads request method=POST path=/api/pending_closures10022026-10-01 09:40:07.350 UTC [52661] ERROR: relation "goose_db_version" does not exist at character 3610032026-10-01 09:40:07.350 UTC [52661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10042026-10-01 09:40:07.403 UTC [52664] ERROR: relation "goose_db_version" does not exist at character 3610052026-10-01 09:40:07.403 UTC [52664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10062026/10/01 09:40:07 OK 20241026095416_initial_model.sql (32.28ms)10072026/10/01 09:40:07 OK 20251210153512_drop_unused_gin_index.sql (12.25ms)10082026/10/01 09:40:07 OK 20251218171726_add_pins.sql (18.36ms)10092026/10/01 09:40:07 OK 20260628120000_add_object_size_and_stats.sql (44.85ms)10102026-10-01 09:40:07.489 UTC [52666] ERROR: relation "goose_db_version" does not exist at character 3610112026-10-01 09:40:07.489 UTC [52666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10122026/10/01 09:40:07 OK 20260905000000_add_claims.sql (17.67ms)10132026/10/01 09:40:07 OK 20241026095416_initial_model.sql (73.35ms)10142026/10/01 09:40:07 OK 20260920000000_drop_claims.sql (15.69ms)10152026/10/01 09:40:07 OK 20251210153512_drop_unused_gin_index.sql (11.97ms)10162026/10/01 09:40:07 OK 20260923120000_add_pushes.sql (21.09ms)10172026/10/01 09:40:07 goose: successfully migrated database to version: 2026092312000010182026/10/01 09:40:07 OK 20251218171726_add_pins.sql (16.68ms)10192026/10/01 09:40:07 OK 1_commit_pending_closure.sql (12.05ms)10202026/10/01 09:40:07 OK 2_object_stats_trigger.sql (1.59ms)10212026/10/01 09:40:07 OK 20241026095416_initial_model.sql (40.96ms)10222026/10/01 09:40:07 OK 20260628120000_add_object_size_and_stats.sql (6.38ms)10232026/10/01 09:40:07 OK 3_commit_push.sql (594.71µs)10242026/10/01 09:40:07 goose: up to current file version: 310252026/10/01 09:40:07 OK 20251210153512_drop_unused_gin_index.sql (8.21ms)10262026/10/01 09:40:07 OK 20251218171726_add_pins.sql (14.1ms)10272026/10/01 09:40:07 OK 20260628120000_add_object_size_and_stats.sql (13.83ms)10282026/10/01 09:40:07 OK 20260905000000_add_claims.sql (37.32ms)10292026/10/01 09:40:07 OK 20260920000000_drop_claims.sql (5.9ms)10302026/10/01 09:40:07 OK 20260905000000_add_claims.sql (9.06ms)10312026/10/01 09:40:07 OK 20260923120000_add_pushes.sql (58.81ms)10322026/10/01 09:40:07 goose: successfully migrated database to version: 202609231200001033--- PASS: TestGetExistingObjectsLocksRows (2.43s)1034=== CONT TestClientErrorHandling1035=== RUN TestClientErrorHandling/InvalidStorePath1036=== PAUSE TestClientErrorHandling/InvalidStorePath1037=== RUN TestClientErrorHandling/InvalidAuthToken1038=== PAUSE TestClientErrorHandling/InvalidAuthToken1039=== RUN TestClientErrorHandling/ServerNotAvailable1040=== PAUSE TestClientErrorHandling/ServerNotAvailable1041=== CONT TestClientCADerivations10422026/10/01 09:40:07 OK 1_commit_pending_closure.sql (7.94ms)10432026/10/01 09:40:07 OK 20260920000000_drop_claims.sql (68.87ms)10442026/10/01 09:40:07 OK 2_object_stats_trigger.sql (9.75ms)10452026/10/01 09:40:07 OK 3_commit_push.sql (4.72ms)10462026/10/01 09:40:07 goose: up to current file version: 310472026/10/01 09:40:07 OK 20260923120000_add_pushes.sql (24.02ms)10482026/10/01 09:40:07 goose: successfully migrated database to version: 2026092312000010492026-10-01 09:40:07.701 UTC [52677] ERROR: relation "goose_db_version" does not exist at character 3610502026-10-01 09:40:07.701 UTC [52677] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10512026/10/01 09:40:07 OK 1_commit_pending_closure.sql (8.19ms)10522026/10/01 09:40:07 OK 2_object_stats_trigger.sql (9.51ms)10532026/10/01 09:40:07 OK 3_commit_push.sql (6.27ms)10542026/10/01 09:40:07 goose: up to current file version: 310552026/10/01 09:40:07 OK 20241026095416_initial_model.sql (30.54ms)10562026/10/01 09:40:07 OK 20251210153512_drop_unused_gin_index.sql (11.74ms)10572026/10/01 09:40:07 OK 20251218171726_add_pins.sql (2.81ms)10582026/10/01 09:40:07 OK 20260628120000_add_object_size_and_stats.sql (10.03ms)10592026/10/01 09:40:07 OK 20260905000000_add_claims.sql (11.3ms)10602026/10/01 09:40:07 OK 20260920000000_drop_claims.sql (18.78ms)10612026/10/01 09:40:07 OK 20260923120000_add_pushes.sql (4.86ms)10622026/10/01 09:40:07 goose: successfully migrated database to version: 2026092312000010632026/10/01 09:40:07 OK 1_commit_pending_closure.sql (1.9ms)10642026/10/01 09:40:07 OK 2_object_stats_trigger.sql (457.83µs)10652026/10/01 09:40:07 OK 3_commit_push.sql (323.75µs)10662026/10/01 09:40:07 goose: up to current file version: 31067--- PASS: TestPushWaitsForSweepHoldingRow (2.67s)1068=== CONT TestCacheStatsHandler1069--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.20s)1070=== CONT TestParseSize1071--- PASS: TestParseSize (0.00s)1072=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10732026-10-01 09:40:07.999 UTC [52702] ERROR: relation "goose_db_version" does not exist at character 3610742026-10-01 09:40:07.999 UTC [52702] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10752026/10/01 09:40:08 INFO Received uploads request method=POST path=/api/pending_closures10762026/10/01 09:40:08 OK 20241026095416_initial_model.sql (95.72ms)10772026/10/01 09:40:08 OK 20251210153512_drop_unused_gin_index.sql (6.43ms)10782026/10/01 09:40:08 INFO Aborted multipart uploads count=010792026/10/01 09:40:08 WARN Force mode enabled - objects will be deleted immediately without grace period10802026/10/01 09:40:08 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10812026/10/01 09:40:08 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1082--- PASS: TestFailedS3DeleteKeepsTombstone (2.08s)1083=== CONT TestCompleteMultipartUnregistered10842026/10/01 09:40:08 OK 20251218171726_add_pins.sql (23.2ms)10852026/10/01 09:40:08 OK 20260628120000_add_object_size_and_stats.sql (12.49ms)10862026/10/01 09:40:08 OK 20260905000000_add_claims.sql (16.83ms)10872026/10/01 09:40:08 OK 20260920000000_drop_claims.sql (38.98ms)10882026/10/01 09:40:08 INFO Aborted multipart uploads count=010892026/10/01 09:40:08 OK 20260923120000_add_pushes.sql (6.72ms)10902026/10/01 09:40:08 goose: successfully migrated database to version: 2026092312000010912026/10/01 09:40:08 OK 1_commit_pending_closure.sql (1.38ms)10922026/10/01 09:40:08 OK 2_object_stats_trigger.sql (365.5µs)10932026/10/01 09:40:08 OK 3_commit_push.sql (250.67µs)10942026/10/01 09:40:08 goose: up to current file version: 310952026/10/01 09:40:08 WARN Force mode enabled - objects will be deleted immediately without grace period10962026/10/01 09:40:08 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=010972026/10/01 09:40:08 INFO Vacuumed table table=pending_closures10982026/10/01 09:40:08 INFO Vacuumed table table=pending_objects10992026/10/01 09:40:08 INFO Vacuumed table table=multipart_uploads11002026/10/01 09:40:08 INFO Vacuumed table table=closures11012026/10/01 09:40:08 INFO Vacuumed table table=objects11022026/10/01 09:40:08 INFO Aborted multipart uploads count=011032026/10/01 09:40:08 WARN Force mode enabled - objects will be deleted immediately without grace period11042026/10/01 09:40:08 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=011052026/10/01 09:40:08 INFO Vacuumed table table=pending_closures11062026/10/01 09:40:08 INFO Vacuumed table table=pending_objects11072026/10/01 09:40:08 INFO Vacuumed table table=multipart_uploads11082026/10/01 09:40:08 INFO Vacuumed table table=closures11092026/10/01 09:40:08 INFO Vacuumed table table=objects1110--- PASS: TestSweepSkipsRowsLockedByPush (2.36s)1111=== CONT TestService_verifyS3Integrity11122026/10/01 09:40:08 INFO Received uploads request method=POST path=/api/pending_closures11132026-10-01 09:40:08.505 UTC [52738] ERROR: relation "goose_db_version" does not exist at character 3611142026-10-01 09:40:08.505 UTC [52738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11152026-10-01 09:40:08.559 UTC [52740] ERROR: relation "goose_db_version" does not exist at character 3611162026-10-01 09:40:08.559 UTC [52740] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11172026/10/01 09:40:08 INFO Received uploads request method=POST path=/api/pending_closures11182026/10/01 09:40:08 OK 20241026095416_initial_model.sql (74.42ms)11192026/10/01 09:40:08 OK 20251210153512_drop_unused_gin_index.sql (4.73ms)1120--- PASS: TestTombstonedObjectOfferedWithoutWaiting (1.76s)1121=== CONT TestService_createPendingClosureHandler11222026/10/01 09:40:08 OK 20251218171726_add_pins.sql (19.98ms)11232026/10/01 09:40:08 OK 20260628120000_add_object_size_and_stats.sql (9.01ms)11242026/10/01 09:40:08 OK 20260905000000_add_claims.sql (17.07ms)11252026/10/01 09:40:08 OK 20241026095416_initial_model.sql (70.34ms)1126--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.34s)1127=== CONT TestService_cleanupPendingClosuresHandler11282026/10/01 09:40:08 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)11292026/10/01 09:40:08 OK 20260920000000_drop_claims.sql (14.28ms)11302026/10/01 09:40:08 OK 20251218171726_add_pins.sql (18.96ms)11312026/10/01 09:40:08 OK 20260923120000_add_pushes.sql (7.37ms)11322026/10/01 09:40:08 goose: successfully migrated database to version: 2026092312000011332026/10/01 09:40:08 OK 1_commit_pending_closure.sql (1.89ms)11342026/10/01 09:40:08 OK 2_object_stats_trigger.sql (509.42µs)11352026/10/01 09:40:08 OK 3_commit_push.sql (423.96µs)11362026/10/01 09:40:08 goose: up to current file version: 311372026/10/01 09:40:08 OK 20260628120000_add_object_size_and_stats.sql (14.17ms)11382026/10/01 09:40:08 OK 20260905000000_add_claims.sql (28.72ms)11392026/10/01 09:40:08 OK 20260920000000_drop_claims.sql (21.22ms)11402026/10/01 09:40:08 OK 20260923120000_add_pushes.sql (8.15ms)11412026/10/01 09:40:08 goose: successfully migrated database to version: 2026092312000011422026/10/01 09:40:08 OK 1_commit_pending_closure.sql (2.23ms)11432026/10/01 09:40:08 OK 2_object_stats_trigger.sql (547.08µs)11442026/10/01 09:40:08 OK 3_commit_push.sql (396.96µs)11452026/10/01 09:40:08 goose: up to current file version: 311462026/10/01 09:40:08 INFO Aborted multipart uploads count=011472026/10/01 09:40:08 WARN Force mode enabled - objects will be deleted immediately without grace period11482026/10/01 09:40:08 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=011492026/10/01 09:40:08 INFO Vacuumed table table=pending_closures11502026/10/01 09:40:08 INFO Vacuumed table table=pending_objects11512026/10/01 09:40:08 INFO Vacuumed table table=multipart_uploads11522026/10/01 09:40:08 INFO Vacuumed table table=closures11532026/10/01 09:40:08 INFO Vacuumed table table=objects1154--- PASS: TestGCSweepDeliversEachKeyOnce (2.31s)1155=== CONT TestUploadHandlersRejectOversizedBody1156=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1157=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1158=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1159=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1160=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1161=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1162=== CONT TestUploadHandlersRejectInvalidKeys1163=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1164=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1165=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1166=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1167=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1168=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1169=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1170=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1171=== CONT TestIsValidUploadKey1172=== RUN TestIsValidUploadKey/narinfo1173=== PAUSE TestIsValidUploadKey/narinfo1174=== RUN TestIsValidUploadKey/nar_zst1175=== PAUSE TestIsValidUploadKey/nar_zst1176=== RUN TestIsValidUploadKey/nar_xz1177=== PAUSE TestIsValidUploadKey/nar_xz1178=== RUN TestIsValidUploadKey/nar_plain1179=== PAUSE TestIsValidUploadKey/nar_plain1180=== RUN TestIsValidUploadKey/listing1181=== PAUSE TestIsValidUploadKey/listing1182=== RUN TestIsValidUploadKey/build_log1183=== PAUSE TestIsValidUploadKey/build_log1184=== RUN TestIsValidUploadKey/build_log_home-manager_file1185=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1186=== RUN TestIsValidUploadKey/build_log_plus_in_name1187=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1188=== RUN TestIsValidUploadKey/build_log_question_mark1189=== PAUSE TestIsValidUploadKey/build_log_question_mark1190=== RUN TestIsValidUploadKey/build_log_equals1191=== PAUSE TestIsValidUploadKey/build_log_equals1192=== RUN TestIsValidUploadKey/realisation1193=== PAUSE TestIsValidUploadKey/realisation1194=== RUN TestIsValidUploadKey/realisation_plus_in_output1195=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1196=== RUN TestIsValidUploadKey/nix-cache-info1197=== PAUSE TestIsValidUploadKey/nix-cache-info1198=== RUN TestIsValidUploadKey/index.html1199=== PAUSE TestIsValidUploadKey/index.html1200=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1201=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1202=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1203=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1204=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1205=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1206=== RUN TestIsValidUploadKey/traversal1207=== PAUSE TestIsValidUploadKey/traversal1208=== RUN TestIsValidUploadKey/traversal_nar1209=== PAUSE TestIsValidUploadKey/traversal_nar1210=== RUN TestIsValidUploadKey/absolute1211=== PAUSE TestIsValidUploadKey/absolute1212=== RUN TestIsValidUploadKey/empty_key1213=== PAUSE TestIsValidUploadKey/empty_key1214=== RUN TestIsValidUploadKey/unknown_type1215=== PAUSE TestIsValidUploadKey/unknown_type1216=== CONT TestProxyWriteTimeout1217=== RUN TestProxyWriteTimeout/narinfo1218=== PAUSE TestProxyWriteTimeout/narinfo1219=== RUN TestProxyWriteTimeout/1_GiB_nar1220=== PAUSE TestProxyWriteTimeout/1_GiB_nar1221=== RUN TestProxyWriteTimeout/10_GiB_nar1222=== PAUSE TestProxyWriteTimeout/10_GiB_nar1223=== RUN TestProxyWriteTimeout/unknown_size1224=== PAUSE TestProxyWriteTimeout/unknown_size1225=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1226=== NAME TestClientMultipleUploads1227 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-51549-3085653128/TestClientMultipleUploads1741432850/001/store/pcgzmlf3r3ks6safhqgc6dlhjaywnfls-test-file-0.txt12282026-10-01 09:40:09.208 UTC [52762] ERROR: relation "goose_db_version" does not exist at character 3612292026-10-01 09:40:09.208 UTC [52762] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1230 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-51549-3085653128/TestClientMultipleUploads1741432850/001/store/rpvshh0ff4jpjj3pq5rbhlq7ql72r79m-test-file-1.txt1231 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-51549-3085653128/TestClientMultipleUploads1741432850/001/store/bp5wr6g2vz87xivqav0av1yrk0fhzs8q-test-file-2.txt1232=== NAME TestClientIntegration1233 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-51549-3085653128/TestClientIntegration2829012492/002/store/f4r178d64d0zhccplcfzasj34bdbih17-test-file.txt12342026/10/01 09:40:09 OK 20241026095416_initial_model.sql (79.26ms)12352026-10-01 09:40:09.373 UTC [52776] ERROR: relation "goose_db_version" does not exist at character 3612362026-10-01 09:40:09.373 UTC [52776] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12372026/10/01 09:40:09 OK 20251210153512_drop_unused_gin_index.sql (14.75ms)12382026/10/01 09:40:09 OK 20251218171726_add_pins.sql (8.42ms)12392026/10/01 09:40:09 OK 20260628120000_add_object_size_and_stats.sql (33.94ms)12402026/10/01 09:40:09 INFO Received push request method=POST path=/api/pushes12412026/10/01 09:40:09 INFO Received push request method=POST path=/api/pushes12422026/10/01 09:40:09 OK 20260905000000_add_claims.sql (28.34ms)12432026/10/01 09:40:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12442026/10/01 09:40:09 INFO Uploading f4r178d64d0zhccplcfzasj34bdbih17-test-file.txt (152B)12452026/10/01 09:40:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12462026/10/01 09:40:09 INFO Uploading bp5wr6g2vz87xivqav0av1yrk0fhzs8q-test-file-2.txt (160B)12472026/10/01 09:40:09 INFO Uploading pcgzmlf3r3ks6safhqgc6dlhjaywnfls-test-file-0.txt (160B)12482026/10/01 09:40:09 INFO Uploading rpvshh0ff4jpjj3pq5rbhlq7ql72r79m-test-file-1.txt (160B)12492026/10/01 09:40:09 OK 20260920000000_drop_claims.sql (37.23ms)12502026/10/01 09:40:09 WARN Failed to register uploaded object key=pcgzmlf3r3ks6safhqgc6dlhjaywnfls.ls error="server returned 404: 404 page not found\n"12512026/10/01 09:40:09 WARN Failed to register uploaded object key=f4r178d64d0zhccplcfzasj34bdbih17.ls error="server returned 404: 404 page not found\n"12522026/10/01 09:40:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12532026/10/01 09:40:09 WARN Failed to register uploaded object key=bp5wr6g2vz87xivqav0av1yrk0fhzs8q.ls error="server returned 404: 404 page not found\n"12542026/10/01 09:40:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"12552026/10/01 09:40:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12562026/10/01 09:40:09 WARN Failed to register uploaded object key=rpvshh0ff4jpjj3pq5rbhlq7ql72r79m.ls error="server returned 404: 404 page not found\n"12572026/10/01 09:40:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"12582026/10/01 09:40:09 INFO Signed narinfos id=1 count=112592026/10/01 09:40:09 INFO Uploading 1 narinfos12602026/10/01 09:40:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12612026/10/01 09:40:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12622026/10/01 09:40:09 INFO Signed narinfos id=1 count=312632026/10/01 09:40:09 INFO Uploading 3 narinfos12642026/10/01 09:40:09 OK 20260923120000_add_pushes.sql (21.21ms)12652026/10/01 09:40:09 goose: successfully migrated database to version: 2026092312000012662026/10/01 09:40:09 OK 1_commit_pending_closure.sql (1.17ms)12672026/10/01 09:40:09 OK 2_object_stats_trigger.sql (261.58µs)12682026/10/01 09:40:09 OK 3_commit_push.sql (224.88µs)12692026/10/01 09:40:09 goose: up to current file version: 312702026/10/01 09:40:09 INFO Received complete push request method=POST path=/api/pushes/1/complete12712026/10/01 09:40:09 WARN Failed to register uploaded object key=f4r178d64d0zhccplcfzasj34bdbih17.narinfo error="server returned 404: 404 page not found\n"12722026/10/01 09:40:09 WARN Failed to register uploaded object key=pcgzmlf3r3ks6safhqgc6dlhjaywnfls.narinfo error="server returned 404: 404 page not found\n"12732026/10/01 09:40:09 INFO Received complete push request method=POST path=/api/pushes/1/complete12742026/10/01 09:40:09 WARN Failed to register uploaded object key=bp5wr6g2vz87xivqav0av1yrk0fhzs8q.narinfo error="server returned 404: 404 page not found\n"12752026/10/01 09:40:09 WARN Failed to register uploaded object key=rpvshh0ff4jpjj3pq5rbhlq7ql72r79m.narinfo error="server returned 404: 404 page not found\n"12762026/10/01 09:40:09 INFO Upload complete. (150ms)12772026/10/01 09:40:09 INFO Upload complete. (175ms)1278=== NAME TestClientMultipleUploads1279 client_integration_test.go:369: Uploaded 3 paths in 225.342458ms12802026/10/01 09:40:09 INFO All 1 paths already cached1281=== NAME TestClientIntegration1282 client_integration_test.go:312: Retrieved narinfo from S3:1283 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientIntegration2829012492/002/store/f4r178d64d0zhccplcfzasj34bdbih17-test-file.txt1284 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1285 Compression: zstd1286 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11287 NarSize: 1521288 References: 1289 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11290 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1291 client_integration_test.go:313: Decompressed .ls content (64 bytes):1292 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1293 client_integration_test.go:316: Testing garbage collection...12942026/10/01 09:40:09 OK 20241026095416_initial_model.sql (182.54ms)12952026/10/01 09:40:09 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)12962026/10/01 09:40:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures12972026/10/01 09:40:09 INFO Garbage collection started1298--- PASS: TestClientMultipleUploads (2.68s)1299=== CONT TestSkippedUploadsHandler13002026/10/01 09:40:09 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001301--- PASS: TestSkippedUploadsHandler (0.00s)1302=== CONT TestService_AuthMiddleware_OIDC13032026/10/01 09:40:09 OK 20251218171726_add_pins.sql (31.05ms)13042026/10/01 09:40:09 INFO Aborted multipart uploads count=013052026/10/01 09:40:09 WARN Force mode enabled - objects will be deleted immediately without grace period13062026/10/01 09:40:09 OK 20260628120000_add_object_size_and_stats.sql (20.97ms)13072026/10/01 09:40:09 INFO Received uploads request method=POST path=/api/pending_closures13082026/10/01 09:40:09 OK 20260905000000_add_claims.sql (17.7ms)13092026/10/01 09:40:09 OK 20260920000000_drop_claims.sql (14.6ms)13102026/10/01 09:40:09 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=013112026/10/01 09:40:09 OK 20260923120000_add_pushes.sql (13.74ms)13122026/10/01 09:40:09 goose: successfully migrated database to version: 2026092312000013132026/10/01 09:40:09 OK 1_commit_pending_closure.sql (1.72ms)13142026/10/01 09:40:09 OK 2_object_stats_trigger.sql (363.88µs)13152026/10/01 09:40:09 OK 3_commit_push.sql (299.88µs)13162026/10/01 09:40:09 goose: up to current file version: 313172026/10/01 09:40:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49703/oidc1318--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.88s)1319=== CONT TestService_ReadScope_PublicByDefault13202026/10/01 09:40:09 INFO Vacuumed table table=pending_closures13212026/10/01 09:40:09 INFO Vacuumed table table=pending_objects13222026/10/01 09:40:09 INFO Vacuumed table table=multipart_uploads13232026/10/01 09:40:09 INFO Vacuumed table table=closures13242026/10/01 09:40:09 INFO Vacuumed table table=objects13252026-10-01 09:40:09.787 UTC [52829] ERROR: relation "goose_db_version" does not exist at character 3613262026-10-01 09:40:09.787 UTC [52829] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13272026-10-01 09:40:09.825 UTC [52834] ERROR: relation "goose_db_version" does not exist at character 3613282026-10-01 09:40:09.825 UTC [52834] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1329=== NAME TestClientCADerivations1330 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-51549-3085653128/TestClientCADerivations3066539310/001/store/ck15fsh4k966m6nr4cjxwvlib5i4a3f9-ca-test13312026/10/01 09:40:09 OK 20241026095416_initial_model.sql (89ms)13322026/10/01 09:40:09 OK 20251210153512_drop_unused_gin_index.sql (31.84ms)1333 client_ca_test.go:139: Found 1 dependencies (including self)13342026/10/01 09:40:09 OK 20251218171726_add_pins.sql (16.55ms)13352026/10/01 09:40:09 OK 20241026095416_initial_model.sql (94.2ms)13362026/10/01 09:40:09 OK 20260628120000_add_object_size_and_stats.sql (20.1ms)13372026/10/01 09:40:09 OK 20251210153512_drop_unused_gin_index.sql (11.68ms)13382026/10/01 09:40:10 OK 20251218171726_add_pins.sql (29.67ms)1339--- PASS: TestCacheStatsHandler (2.18s)1340=== CONT TestService_RequireScope_OIDC13412026-10-01 09:40:10.008 UTC [52845] ERROR: relation "goose_db_version" does not exist at character 3613422026-10-01 09:40:10.008 UTC [52845] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13432026/10/01 09:40:10 OK 20260905000000_add_claims.sql (49.2ms)13442026/10/01 09:40:10 OK 20260920000000_drop_claims.sql (14.43ms)13452026/10/01 09:40:10 OK 20260628120000_add_object_size_and_stats.sql (22.6ms)13462026/10/01 09:40:10 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49708/oidc13472026/10/01 09:40:10 OK 20260923120000_add_pushes.sql (7.8ms)13482026/10/01 09:40:10 goose: successfully migrated database to version: 2026092312000013492026/10/01 09:40:10 OK 1_commit_pending_closure.sql (1.15ms)13502026/10/01 09:40:10 OK 2_object_stats_trigger.sql (574.29µs)13512026/10/01 09:40:10 OK 3_commit_push.sql (362.79µs)13522026/10/01 09:40:10 goose: up to current file version: 313532026/10/01 09:40:10 OK 20260905000000_add_claims.sql (22.21ms)13542026/10/01 09:40:10 OK 20260920000000_drop_claims.sql (13.58ms)13552026/10/01 09:40:10 OK 20260923120000_add_pushes.sql (7.09ms)13562026/10/01 09:40:10 goose: successfully migrated database to version: 2026092312000013572026/10/01 09:40:10 OK 1_commit_pending_closure.sql (1.05ms)13582026/10/01 09:40:10 OK 2_object_stats_trigger.sql (267.58µs)13592026/10/01 09:40:10 OK 3_commit_push.sql (197.25µs)13602026/10/01 09:40:10 goose: up to current file version: 313612026/10/01 09:40:10 INFO Received push request method=POST path=/api/pushes13622026/10/01 09:40:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13632026/10/01 09:40:10 INFO Uploading ck15fsh4k966m6nr4cjxwvlib5i4a3f9-ca-test (144B)13642026/10/01 09:40:10 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13652026/10/01 09:40:10 WARN Failed to register uploaded object key=ck15fsh4k966m6nr4cjxwvlib5i4a3f9.ls error="server returned 404: 404 page not found\n"13662026/10/01 09:40:10 WARN Failed to register uploaded object key=log/lddid27l1rhc4h92qny6kgp5d4md67la-ca-test.drv error="server returned 404: 404 page not found\n"13672026/10/01 09:40:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13682026/10/01 09:40:10 INFO Signed narinfos id=1 count=113692026/10/01 09:40:10 INFO Uploading 1 narinfos13702026/10/01 09:40:10 INFO Received complete push request method=POST path=/api/pushes/1/complete13712026/10/01 09:40:10 WARN Failed to register uploaded object key=ck15fsh4k966m6nr4cjxwvlib5i4a3f9.narinfo error="server returned 404: 404 page not found\n"13722026/10/01 09:40:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13732026/10/01 09:40:10 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1374--- PASS: TestCompleteMultipartUnregistered (1.97s)1375=== CONT TestLeadElectsOneAndHandsOver13762026/10/01 09:40:10 INFO Upload complete. (179ms)1377=== NAME TestClientCADerivations1378 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientCADerivations3066539310/001/store/ck15fsh4k966m6nr4cjxwvlib5i4a3f9-ca-test1379 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1380 Compression: zstd1381 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1382 NarSize: 1441383 References: 1384 Deriver: /nix/var/nix/builds/nix-51549-3085653128/TestClientCADerivations3066539310/001/store/lddid27l1rhc4h92qny6kgp5d4md67la-ca-test.drv1385 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1386 client_ca_test.go:185: Checking for realisation files in S3...1387 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1388 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13892026/10/01 09:40:10 OK 20241026095416_initial_model.sql (114.78ms)13902026/10/01 09:40:10 OK 20251210153512_drop_unused_gin_index.sql (19.12ms)13912026/10/01 09:40:10 OK 20251218171726_add_pins.sql (17.39ms)13922026/10/01 09:40:10 OK 20260628120000_add_object_size_and_stats.sql (23.47ms)1393 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket21?endpoint=http://localhost:49605®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-51549-3085653128/TestClientCADerivations3066539310/001/store'1394 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 113952026/10/01 09:40:10 OK 20260905000000_add_claims.sql (28.78ms)1396--- PASS: TestClientCADerivations (2.60s)1397=== CONT TestDeduplicatedObjectsRecordedAsPending13982026/10/01 09:40:10 OK 20260920000000_drop_claims.sql (15.83ms)13992026/10/01 09:40:10 OK 20260923120000_add_pushes.sql (3.05ms)14002026/10/01 09:40:10 goose: successfully migrated database to version: 2026092312000014012026/10/01 09:40:10 OK 1_commit_pending_closure.sql (1.13ms)14022026/10/01 09:40:10 OK 2_object_stats_trigger.sql (269.17µs)14032026/10/01 09:40:10 OK 3_commit_push.sql (202.96µs)14042026/10/01 09:40:10 goose: up to current file version: 314052026/10/01 09:40:10 INFO Received uploads request method=POST path=/api/pending_closures14062026/10/01 09:40:10 INFO Received uploads request method=POST path=/api/pending_closures14072026/10/01 09:40:10 INFO Received uploads request method=POST path=/api/pending_closures14082026/10/01 09:40:10 INFO Received uploads request method=POST path=/api/pending_closures14092026/10/01 09:40:10 INFO Received cleanup request method=DELETE path=/api/pending_closures14102026/10/01 09:40:10 INFO Aborted multipart uploads count=014112026/10/01 09:40:10 INFO Received uploads request method=POST path=/api/pending_closures14122026/10/01 09:40:10 INFO Received cleanup request method=DELETE path=/api/pending_closures14132026/10/01 09:40:10 INFO Aborted multipart uploads count=114142026/10/01 09:40:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14152026-10-01 09:40:10.903 UTC [52834] ERROR: Closure does not exist: id=114162026-10-01 09:40:10.903 UTC [52834] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE14172026-10-01 09:40:10.903 UTC [52834] STATEMENT: -- name: CommitPendingClosure :exec1418 SELECT commit_pending_closure($1::bigint)1419 1420--- PASS: TestService_cleanupPendingClosuresHandler (2.25s)1421=== CONT TestPushDedupSurvivesConcurrentGC14222026/10/01 09:40:11 INFO Received uploads request method=POST path=/api/pending_closures14232026-10-01 09:40:11.394 UTC [52868] ERROR: relation "goose_db_version" does not exist at character 3614242026-10-01 09:40:11.394 UTC [52868] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14252026/10/01 09:40:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14262026-10-01 09:40:11.519 UTC [52869] ERROR: relation "goose_db_version" does not exist at character 3614272026-10-01 09:40:11.519 UTC [52869] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14282026/10/01 09:40:11 OK 20241026095416_initial_model.sql (58.62ms)14292026/10/01 09:40:11 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)14302026/10/01 09:40:11 OK 20251218171726_add_pins.sql (3.24ms)14312026/10/01 09:40:11 OK 20260628120000_add_object_size_and_stats.sql (47.67ms)14322026/10/01 09:40:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01433=== NAME TestClientIntegration1434 client_integration_test.go:323: Objects in database after GC:1435 client_integration_test.go:323: Successfully deleted all objects with GC --force14362026-10-01 09:40:11.659 UTC [52870] ERROR: relation "goose_db_version" does not exist at character 3614372026-10-01 09:40:11.659 UTC [52870] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14382026/10/01 09:40:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14392026/10/01 09:40:11 OK 20260905000000_add_claims.sql (69.06ms)14402026/10/01 09:40:11 OK 20260920000000_drop_claims.sql (38.65ms)1441--- PASS: TestClientIntegration (4.46s)1442=== CONT TestGCMetrics14432026/10/01 09:40:11 OK 20241026095416_initial_model.sql (170.77ms)14442026/10/01 09:40:11 OK 20260923120000_add_pushes.sql (13.3ms)14452026/10/01 09:40:11 goose: successfully migrated database to version: 2026092312000014462026/10/01 09:40:11 OK 1_commit_pending_closure.sql (2.75ms)14472026/10/01 09:40:11 OK 2_object_stats_trigger.sql (326.54µs)14482026/10/01 09:40:11 OK 3_commit_push.sql (224.38µs)14492026/10/01 09:40:11 goose: up to current file version: 314502026/10/01 09:40:11 OK 20251210153512_drop_unused_gin_index.sql (15.75ms)14512026/10/01 09:40:11 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NjA1MTgyNzgtYzE4Yi00MGE0LWE0Y2QtMDg0Yzg5YWJmZjY5LmJmMzI5NWZiLTMxMjYtNGFiMS05NDc0LWVjMDI4MzA4NzE1Y3gxNzkwODQ3NjEwMzc4MTg2MDAw parts=1014522026/10/01 09:40:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14532026/10/01 09:40:11 OK 20251218171726_add_pins.sql (56.78ms)14542026/10/01 09:40:11 INFO Completed upload id=114552026-10-01 09:40:11.793 UTC [52873] ERROR: relation "goose_db_version" does not exist at character 3614562026-10-01 09:40:11.793 UTC [52873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14572026/10/01 09:40:11 INFO Received uploads request method=POST path=/api/pending_closures14582026/10/01 09:40:11 INFO Received uploads request method=POST path=/api/pending_closures14592026/10/01 09:40:11 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14602026/10/01 09:40:11 WARN Found objects in DB but missing from S3, will re-upload count=11461--- PASS: TestService_verifyS3Integrity (3.46s)1462=== CONT TestGCBugBareHashReferences14632026/10/01 09:40:11 OK 20260628120000_add_object_size_and_stats.sql (39.08ms)14642026/10/01 09:40:11 OK 20260905000000_add_claims.sql (53.53ms)14652026/10/01 09:40:11 OK 20260920000000_drop_claims.sql (15.81ms)14662026/10/01 09:40:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14672026/10/01 09:40:11 OK 20260923120000_add_pushes.sql (79.34ms)14682026/10/01 09:40:11 goose: successfully migrated database to version: 2026092312000014692026/10/01 09:40:11 OK 1_commit_pending_closure.sql (1.35ms)14702026/10/01 09:40:11 OK 2_object_stats_trigger.sql (300.54µs)14712026/10/01 09:40:11 OK 3_commit_push.sql (211.08µs)14722026/10/01 09:40:11 goose: up to current file version: 314732026/10/01 09:40:11 OK 20241026095416_initial_model.sql (259.03ms)14742026/10/01 09:40:12 OK 20251210153512_drop_unused_gin_index.sql (23.14ms)14752026/10/01 09:40:12 OK 20251218171726_add_pins.sql (21.2ms)14762026/10/01 09:40:12 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NjA1MTgyNzgtYzE4Yi00MGE0LWE0Y2QtMDg0Yzg5YWJmZjY5LjczMjA4MjkwLTNkYjMtNGNiMS1iYmQ5LWQ0NTdkZTgzNWVjZXgxNzkwODQ3NjEwNTUwNjI5MDAw parts=1014772026/10/01 09:40:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14782026/10/01 09:40:12 OK 20241026095416_initial_model.sql (170.39ms)1479=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1480=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1481=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1482=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1483=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1484=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1485=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1486=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1487=== CONT TestLeadEndsOnShutdown14882026-10-01 09:40:12.041 UTC [52877] ERROR: relation "goose_db_version" does not exist at character 3614892026-10-01 09:40:12.041 UTC [52877] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14902026/10/01 09:40:12 OK 20251210153512_drop_unused_gin_index.sql (15.33ms)14912026/10/01 09:40:12 INFO Completed upload id=114922026/10/01 09:40:12 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014932026/10/01 09:40:12 INFO Received uploads request method=POST path=/api/pending_closures14942026/10/01 09:40:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures14952026/10/01 09:40:12 INFO Aborted multipart uploads count=014962026/10/01 09:40:12 OK 20260628120000_add_object_size_and_stats.sql (40.43ms)14972026/10/01 09:40:12 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=014982026/10/01 09:40:12 OK 20251218171726_add_pins.sql (45.26ms)14992026/10/01 09:40:12 INFO Vacuumed table table=pending_closures15002026/10/01 09:40:12 OK 20260628120000_add_object_size_and_stats.sql (45.57ms)15012026/10/01 09:40:12 INFO Vacuumed table table=pending_objects15022026/10/01 09:40:12 OK 20260905000000_add_claims.sql (93.88ms)15032026/10/01 09:40:12 INFO Vacuumed table table=multipart_uploads15042026/10/01 09:40:12 OK 20260920000000_drop_claims.sql (46.65ms)15052026/10/01 09:40:12 INFO Vacuumed table table=closures15062026/10/01 09:40:12 OK 20260905000000_add_claims.sql (75.54ms)15072026/10/01 09:40:12 OK 20260923120000_add_pushes.sql (18.51ms)15082026/10/01 09:40:12 goose: successfully migrated database to version: 2026092312000015092026/10/01 09:40:12 INFO Vacuumed table table=objects15102026/10/01 09:40:12 OK 1_commit_pending_closure.sql (2.71ms)15112026/10/01 09:40:12 OK 2_object_stats_trigger.sql (517.71µs)15122026/10/01 09:40:12 OK 3_commit_push.sql (389.54µs)15132026/10/01 09:40:12 goose: up to current file version: 315142026/10/01 09:40:12 OK 20260920000000_drop_claims.sql (49.09ms)15152026/10/01 09:40:12 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001516--- PASS: TestService_createPendingClosureHandler (3.66s)1517=== CONT TestClientFallsBackToClosures15182026/10/01 09:40:12 OK 20260923120000_add_pushes.sql (17.23ms)15192026/10/01 09:40:12 goose: successfully migrated database to version: 2026092312000015202026/10/01 09:40:12 OK 1_commit_pending_closure.sql (1.73ms)15212026/10/01 09:40:12 OK 2_object_stats_trigger.sql (408.71µs)15222026/10/01 09:40:12 OK 3_commit_push.sql (313.63µs)15232026/10/01 09:40:12 goose: up to current file version: 31524--- PASS: TestService_ReadScope_PublicByDefault (2.61s)1525=== CONT TestResolveDBConnectionString15262026/10/01 09:40:12 OK 20241026095416_initial_model.sql (190.55ms)1527=== RUN TestResolveDBConnectionString/flag_wins1528=== PAUSE TestResolveDBConnectionString/flag_wins1529=== RUN TestResolveDBConnectionString/file_when_flag_empty1530=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1531=== RUN TestResolveDBConnectionString/missing_file_is_an_error1532=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1533=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1534=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1535=== RUN TestResolveDBConnectionString/nothing_configured1536=== PAUSE TestResolveDBConnectionString/nothing_configured1537=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock15382026/10/01 09:40:12 OK 20251210153512_drop_unused_gin_index.sql (2.56ms)15392026/10/01 09:40:12 OK 20251218171726_add_pins.sql (46.27ms)15402026/10/01 09:40:12 OK 20260628120000_add_object_size_and_stats.sql (30.81ms)15412026/10/01 09:40:12 OK 20260905000000_add_claims.sql (63.06ms)15422026/10/01 09:40:12 OK 20260920000000_drop_claims.sql (44.11ms)15432026/10/01 09:40:12 OK 20260923120000_add_pushes.sql (7.01ms)15442026/10/01 09:40:12 goose: successfully migrated database to version: 2026092312000015452026/10/01 09:40:12 OK 1_commit_pending_closure.sql (2.58ms)15462026/10/01 09:40:12 OK 2_object_stats_trigger.sql (575.17µs)15472026/10/01 09:40:12 OK 3_commit_push.sql (414.79µs)15482026/10/01 09:40:12 goose: up to current file version: 31549=== RUN TestService_RequireScope_OIDC/builder_may_write1550=== PAUSE TestService_RequireScope_OIDC/builder_may_write1551=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1552=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1553=== RUN TestService_RequireScope_OIDC/ops_may_admin1554=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1555=== RUN TestService_RequireScope_OIDC/ops_may_not_write1556=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1557=== RUN TestService_RequireScope_OIDC/reader_may_not_write1558=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1559=== RUN TestService_RequireScope_OIDC/static_token_may_admin1560=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1561=== RUN TestService_RequireScope_OIDC/static_token_may_write1562=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1563=== RUN TestService_RequireScope_OIDC/reader_may_read1564=== PAUSE TestService_RequireScope_OIDC/reader_may_read1565=== RUN TestService_RequireScope_OIDC/writer_implies_read1566=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1567=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1568=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1569=== CONT TestPinProtectsFromGC15702026-10-01 09:40:12.859 UTC [52887] ERROR: relation "goose_db_version" does not exist at character 3615712026-10-01 09:40:12.859 UTC [52887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15722026/10/01 09:40:12 INFO lead: acquired remote=192.0.2.1:123415732026/10/01 09:40:13 INFO lead: released remote=192.0.2.1:123415742026/10/01 09:40:13 INFO lead: acquired remote=192.0.2.1:123415752026/10/01 09:40:13 INFO lead: released remote=192.0.2.1:12341576--- PASS: TestLeadElectsOneAndHandsOver (3.05s)1577=== CONT TestClientPushesUseOnePush15782026/10/01 09:40:13 OK 20241026095416_initial_model.sql (252.45ms)15792026/10/01 09:40:13 OK 20251210153512_drop_unused_gin_index.sql (17.08ms)15802026/10/01 09:40:13 OK 20251218171726_add_pins.sql (40.06ms)15812026/10/01 09:40:13 INFO Received uploads request method=POST path=/api/pending_closures15822026/10/01 09:40:13 OK 20260628120000_add_object_size_and_stats.sql (30.8ms)1583--- PASS: TestDeduplicatedObjectsRecordedAsPending (3.04s)1584=== CONT TestClientSharedPathCommittedMidPush15852026/10/01 09:40:13 OK 20260905000000_add_claims.sql (46.46ms)15862026/10/01 09:40:13 OK 20260920000000_drop_claims.sql (20.72ms)15872026/10/01 09:40:13 OK 20260923120000_add_pushes.sql (2.87ms)15882026/10/01 09:40:13 goose: successfully migrated database to version: 2026092312000015892026/10/01 09:40:13 OK 1_commit_pending_closure.sql (2.82ms)15902026/10/01 09:40:13 OK 2_object_stats_trigger.sql (846.42µs)15912026/10/01 09:40:13 OK 3_commit_push.sql (263.38µs)15922026/10/01 09:40:13 goose: up to current file version: 315932026-10-01 09:40:13.526 UTC [52902] ERROR: relation "goose_db_version" does not exist at character 3615942026-10-01 09:40:13.526 UTC [52902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15952026-10-01 09:40:13.543 UTC [52903] ERROR: relation "goose_db_version" does not exist at character 3615962026-10-01 09:40:13.543 UTC [52903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15972026/10/01 09:40:13 INFO Received uploads request method=POST path=/api/pending_closures15982026/10/01 09:40:13 INFO Aborted multipart uploads count=015992026/10/01 09:40:13 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=016002026/10/01 09:40:13 OK 20241026095416_initial_model.sql (211.59ms)16012026/10/01 09:40:13 OK 20251210153512_drop_unused_gin_index.sql (9.45ms)16022026/10/01 09:40:13 OK 20241026095416_initial_model.sql (228.94ms)16032026/10/01 09:40:13 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)16042026/10/01 09:40:13 INFO Vacuumed table table=pending_closures16052026/10/01 09:40:13 INFO Vacuumed table table=pending_objects16062026/10/01 09:40:13 OK 20251218171726_add_pins.sql (36.81ms)16072026/10/01 09:40:13 INFO Vacuumed table table=multipart_uploads16082026/10/01 09:40:13 OK 20251218171726_add_pins.sql (34.83ms)16092026/10/01 09:40:13 INFO Vacuumed table table=closures16102026/10/01 09:40:13 OK 20260628120000_add_object_size_and_stats.sql (31.21ms)16112026/10/01 09:40:13 OK 20260628120000_add_object_size_and_stats.sql (24.66ms)16122026-10-01 09:40:13.887 UTC [52906] ERROR: relation "goose_db_version" does not exist at character 3616132026-10-01 09:40:13.887 UTC [52906] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16142026/10/01 09:40:13 INFO Vacuumed table table=objects16152026/10/01 09:40:13 OK 20260905000000_add_claims.sql (36.89ms)16162026/10/01 09:40:13 OK 20260905000000_add_claims.sql (36.85ms)16172026/10/01 09:40:13 INFO Aborted multipart uploads count=016182026/10/01 09:40:13 WARN Force mode enabled - objects will be deleted immediately without grace period16192026/10/01 09:40:13 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=016202026/10/01 09:40:13 INFO Vacuumed table table=pending_closures16212026/10/01 09:40:13 OK 20260920000000_drop_claims.sql (25.35ms)16222026/10/01 09:40:13 INFO Vacuumed table table=pending_objects16232026/10/01 09:40:13 INFO Vacuumed table table=multipart_uploads16242026/10/01 09:40:13 OK 20260920000000_drop_claims.sql (35.8ms)16252026/10/01 09:40:13 OK 20260923120000_add_pushes.sql (11.09ms)16262026/10/01 09:40:13 goose: successfully migrated database to version: 2026092312000016272026/10/01 09:40:13 OK 1_commit_pending_closure.sql (932.88µs)16282026/10/01 09:40:13 OK 2_object_stats_trigger.sql (195.17µs)16292026/10/01 09:40:13 OK 3_commit_push.sql (180.5µs)16302026/10/01 09:40:13 goose: up to current file version: 316312026/10/01 09:40:13 INFO Vacuumed table table=closures16322026/10/01 09:40:13 INFO Vacuumed table table=objects1633--- PASS: TestPushDedupSurvivesConcurrentGC (3.07s)1634=== CONT TestPush_SignsNarinfosOfItsPendingObjects16352026/10/01 09:40:13 OK 20260923120000_add_pushes.sql (18.23ms)16362026/10/01 09:40:13 goose: successfully migrated database to version: 2026092312000016372026/10/01 09:40:13 OK 1_commit_pending_closure.sql (1.6ms)16382026/10/01 09:40:13 OK 2_object_stats_trigger.sql (246.17µs)16392026/10/01 09:40:13 OK 3_commit_push.sql (178.5µs)16402026/10/01 09:40:13 goose: up to current file version: 316412026-10-01 09:40:14.093 UTC [52911] ERROR: relation "goose_db_version" does not exist at character 3616422026-10-01 09:40:14.093 UTC [52911] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16432026/10/01 09:40:14 WARN Rate limiter enabled after throttle name=s3-test rate=516442026/10/01 09:40:14 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1645=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1646 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101647 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001648--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.20s)1649=== CONT TestService_Rustfstest16502026/10/01 09:40:14 OK 20241026095416_initial_model.sql (164.78ms)16512026/10/01 09:40:14 OK 20251210153512_drop_unused_gin_index.sql (14.08ms)16522026/10/01 09:40:14 OK 20251218171726_add_pins.sql (27.98ms)16532026/10/01 09:40:14 OK 20260628120000_add_object_size_and_stats.sql (30.28ms)16542026/10/01 09:40:14 OK 20260905000000_add_claims.sql (38.71ms)16552026/10/01 09:40:14 OK 20260920000000_drop_claims.sql (21.82ms)16562026/10/01 09:40:14 OK 20260923120000_add_pushes.sql (2.53ms)16572026/10/01 09:40:14 goose: successfully migrated database to version: 2026092312000016582026/10/01 09:40:14 OK 1_commit_pending_closure.sql (1.1ms)16592026/10/01 09:40:14 OK 2_object_stats_trigger.sql (248.75µs)16602026/10/01 09:40:14 OK 3_commit_push.sql (192.38µs)16612026/10/01 09:40:14 goose: up to current file version: 316622026/10/01 09:40:14 OK 20241026095416_initial_model.sql (165.53ms)16632026/10/01 09:40:14 OK 20251210153512_drop_unused_gin_index.sql (8.05ms)16642026-10-01 09:40:14.352 UTC [52916] ERROR: relation "goose_db_version" does not exist at character 3616652026-10-01 09:40:14.352 UTC [52916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16662026/10/01 09:40:14 OK 20251218171726_add_pins.sql (38.65ms)16672026/10/01 09:40:14 OK 20260628120000_add_object_size_and_stats.sql (37.62ms)16682026/10/01 09:40:14 OK 20260905000000_add_claims.sql (65.4ms)16692026/10/01 09:40:14 OK 20260920000000_drop_claims.sql (28.59ms)1670--- PASS: TestGCBugBareHashReferences (2.72s)1671=== CONT TestPresignedUploadRegisteredBeforeCommit16722026/10/01 09:40:14 OK 20260923120000_add_pushes.sql (18.07ms)16732026/10/01 09:40:14 goose: successfully migrated database to version: 2026092312000016742026/10/01 09:40:14 OK 1_commit_pending_closure.sql (1.33ms)16752026/10/01 09:40:14 OK 2_object_stats_trigger.sql (264.54µs)16762026/10/01 09:40:14 OK 3_commit_push.sql (191.67µs)16772026/10/01 09:40:14 goose: up to current file version: 316782026/10/01 09:40:14 INFO Aborted multipart uploads count=016792026/10/01 09:40:14 WARN Force mode enabled - objects will be deleted immediately without grace period16802026/10/01 09:40:14 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=016812026/10/01 09:40:14 INFO Vacuumed table table=pending_closures16822026/10/01 09:40:14 INFO Vacuumed table table=pending_objects16832026/10/01 09:40:14 INFO Vacuumed table table=multipart_uploads16842026/10/01 09:40:14 INFO Vacuumed table table=closures16852026/10/01 09:40:14 INFO Vacuumed table table=objects1686--- PASS: TestGCMetrics (2.85s)1687=== CONT TestCompletedNarNotReofferedAcrossClosures16882026/10/01 09:40:14 OK 20241026095416_initial_model.sql (199.27ms)16892026-10-01 09:40:14.608 UTC [52926] ERROR: relation "goose_db_version" does not exist at character 3616902026-10-01 09:40:14.608 UTC [52926] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16912026/10/01 09:40:14 OK 20251210153512_drop_unused_gin_index.sql (3.71ms)16922026/10/01 09:40:14 OK 20251218171726_add_pins.sql (32.67ms)16932026/10/01 09:40:14 OK 20260628120000_add_object_size_and_stats.sql (31.64ms)16942026/10/01 09:40:14 OK 20260905000000_add_claims.sql (55.43ms)16952026-10-01 09:40:14.740 UTC [52928] ERROR: relation "goose_db_version" does not exist at character 3616962026-10-01 09:40:14.740 UTC [52928] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16972026/10/01 09:40:14 OK 20260920000000_drop_claims.sql (19.05ms)16982026/10/01 09:40:14 OK 20260923120000_add_pushes.sql (11.64ms)16992026/10/01 09:40:14 goose: successfully migrated database to version: 2026092312000017002026/10/01 09:40:14 OK 1_commit_pending_closure.sql (1.03ms)17012026/10/01 09:40:14 OK 2_object_stats_trigger.sql (246.71µs)17022026/10/01 09:40:14 OK 3_commit_push.sql (201.25µs)17032026/10/01 09:40:14 goose: up to current file version: 317042026/10/01 09:40:14 INFO lead: acquired remote=192.0.2.1:123417052026/10/01 09:40:14 INFO lead: released remote=192.0.2.1:12341706--- PASS: TestLeadEndsOnShutdown (2.79s)1707=== CONT TestCompleteMultipartUpload_ErrorButObjectExists17082026/10/01 09:40:14 OK 20241026095416_initial_model.sql (225.33ms)17092026/10/01 09:40:14 OK 20251210153512_drop_unused_gin_index.sql (15.16ms)17102026/10/01 09:40:14 OK 20251218171726_add_pins.sql (31.14ms)17112026/10/01 09:40:14 OK 20260628120000_add_object_size_and_stats.sql (36.69ms)17122026/10/01 09:40:14 OK 20241026095416_initial_model.sql (194.24ms)17132026/10/01 09:40:15 OK 20251210153512_drop_unused_gin_index.sql (13.9ms)17142026/10/01 09:40:15 OK 20260905000000_add_claims.sql (21.95ms)17152026/10/01 09:40:15 OK 20251218171726_add_pins.sql (5.18ms)17162026/10/01 09:40:15 OK 20260920000000_drop_claims.sql (44.46ms)17172026/10/01 09:40:15 OK 20260628120000_add_object_size_and_stats.sql (82.05ms)17182026/10/01 09:40:15 OK 20260923120000_add_pushes.sql (41.24ms)17192026/10/01 09:40:15 goose: successfully migrated database to version: 2026092312000017202026/10/01 09:40:15 OK 1_commit_pending_closure.sql (3.68ms)17212026/10/01 09:40:15 OK 2_object_stats_trigger.sql (528.5µs)17222026/10/01 09:40:15 OK 3_commit_push.sql (423.25µs)17232026/10/01 09:40:15 goose: up to current file version: 317242026/10/01 09:40:15 OK 20260905000000_add_claims.sql (36.7ms)17252026/10/01 09:40:15 OK 20260920000000_drop_claims.sql (36.54ms)17262026-10-01 09:40:15.172 UTC [52931] ERROR: relation "goose_db_version" does not exist at character 3617272026-10-01 09:40:15.172 UTC [52931] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17282026/10/01 09:40:15 OK 20260923120000_add_pushes.sql (7.42ms)17292026/10/01 09:40:15 goose: successfully migrated database to version: 2026092312000017302026/10/01 09:40:15 OK 1_commit_pending_closure.sql (3.75ms)17312026/10/01 09:40:15 OK 2_object_stats_trigger.sql (508.13µs)17322026/10/01 09:40:15 OK 3_commit_push.sql (405.67µs)17332026/10/01 09:40:15 goose: up to current file version: 317342026/10/01 09:40:15 OK 20241026095416_initial_model.sql (126.43ms)17352026/10/01 09:40:15 OK 20251210153512_drop_unused_gin_index.sql (6.2ms)17362026/10/01 09:40:15 OK 20251218171726_add_pins.sql (19.43ms)17372026/10/01 09:40:15 OK 20260628120000_add_object_size_and_stats.sql (43.55ms)17382026/10/01 09:40:15 OK 20260905000000_add_claims.sql (61.32ms)17392026/10/01 09:40:15 OK 20260920000000_drop_claims.sql (15.55ms)17402026/10/01 09:40:15 OK 20260923120000_add_pushes.sql (3.85ms)17412026/10/01 09:40:15 goose: successfully migrated database to version: 2026092312000017422026/10/01 09:40:15 OK 1_commit_pending_closure.sql (2.63ms)17432026/10/01 09:40:15 OK 2_object_stats_trigger.sql (636.75µs)17442026/10/01 09:40:15 OK 3_commit_push.sql (3.58ms)17452026/10/01 09:40:15 goose: up to current file version: 317462026-10-01 09:40:15.585 UTC [52950] ERROR: relation "goose_db_version" does not exist at character 3617472026-10-01 09:40:15.585 UTC [52950] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17482026/10/01 09:40:15 INFO Received uploads request method=POST path=/api/pending_closures17492026/10/01 09:40:15 INFO Received uploads request method=POST path=/api/pending_closures17502026/10/01 09:40:15 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17512026/10/01 09:40:15 INFO Uploading qn9fgpa011mgmmi786x9mds4gm27dn4y-b (248B)17522026/10/01 09:40:15 INFO Uploading jcjls8qiqkf62xsljd67zmhnp81ppxnh-shared-dep (136B)17532026/10/01 09:40:15 WARN Failed to register uploaded object key=kp1kvk1wbvslc035mrbwc40pzq41afdk.ls error="server returned 404: 404 page not found\n"17542026-10-01 09:40:15.701 UTC [52974] ERROR: relation "goose_db_version" does not exist at character 3617552026-10-01 09:40:15.701 UTC [52974] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17562026/10/01 09:40:15 WARN Failed to register uploaded object key=jcjls8qiqkf62xsljd67zmhnp81ppxnh.ls error="server returned 404: 404 page not found\n"17572026/10/01 09:40:15 WARN Failed to register uploaded object key=nar/154h8xgd1l96p58iia3b64ax8smvlsjs3if0v4cb3j3r02kbai8d.nar.zst error="server returned 404: 404 page not found\n"17582026/10/01 09:40:15 WARN Failed to register uploaded object key=qn9fgpa011mgmmi786x9mds4gm27dn4y.ls error="server returned 404: 404 page not found\n"17592026/10/01 09:40:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17602026/10/01 09:40:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17612026/10/01 09:40:15 INFO Signed narinfos id=1 count=217622026/10/01 09:40:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17632026/10/01 09:40:15 INFO Signed narinfos id=2 count=217642026/10/01 09:40:15 INFO Uploading 4 narinfos17652026/10/01 09:40:15 WARN Failed to register uploaded object key=kp1kvk1wbvslc035mrbwc40pzq41afdk.narinfo error="server returned 404: 404 page not found\n"17662026/10/01 09:40:15 WARN Failed to register uploaded object key=jcjls8qiqkf62xsljd67zmhnp81ppxnh.narinfo error="server returned 404: 404 page not found\n"17672026/10/01 09:40:15 WARN Failed to register uploaded object key=qn9fgpa011mgmmi786x9mds4gm27dn4y.narinfo error="server returned 404: 404 page not found\n"17682026/10/01 09:40:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17692026/10/01 09:40:15 WARN Failed to register uploaded object key=jcjls8qiqkf62xsljd67zmhnp81ppxnh.narinfo error="server returned 404: 404 page not found\n"17702026/10/01 09:40:15 INFO Completed upload id=117712026/10/01 09:40:15 OK 20241026095416_initial_model.sql (169.91ms)17722026/10/01 09:40:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17732026/10/01 09:40:15 INFO Completed upload id=217742026/10/01 09:40:15 INFO Upload complete. (223ms)1775=== NAME TestClientFallsBackToClosures1776 client_pushes_test.go:112: Retrieved narinfo from S3:1777 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientFallsBackToClosures1753040160/001/store/jcjls8qiqkf62xsljd67zmhnp81ppxnh-shared-dep1778 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1779 Compression: zstd1780 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821781 NarSize: 1361782 References: 1783 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1784 client_pushes_test.go:112: Retrieved narinfo from S3:1785 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientFallsBackToClosures1753040160/001/store/kp1kvk1wbvslc035mrbwc40pzq41afdk-a1786 URL: nar/154h8xgd1l96p58iia3b64ax8smvlsjs3if0v4cb3j3r02kbai8d.nar.zst1787 Compression: zstd1788 NarHash: sha256:154h8xgd1l96p58iia3b64ax8smvlsjs3if0v4cb3j3r02kbai8d1789 NarSize: 2481790 References: /nix/var/nix/builds/nix-51549-3085653128/TestClientFallsBackToClosures1753040160/001/store/jcjls8qiqkf62xsljd67zmhnp81ppxnh-shared-dep1791 CA: text:sha256:0js2jmidwg5dhh5c9vmrcp81jda2x48jdm861a9hmf1xb44maa5b1792 client_pushes_test.go:112: Retrieved narinfo from S3:1793 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientFallsBackToClosures1753040160/001/store/qn9fgpa011mgmmi786x9mds4gm27dn4y-b1794 URL: nar/154h8xgd1l96p58iia3b64ax8smvlsjs3if0v4cb3j3r02kbai8d.nar.zst1795 Compression: zstd1796 NarHash: sha256:154h8xgd1l96p58iia3b64ax8smvlsjs3if0v4cb3j3r02kbai8d1797 NarSize: 2481798 References: /nix/var/nix/builds/nix-51549-3085653128/TestClientFallsBackToClosures1753040160/001/store/jcjls8qiqkf62xsljd67zmhnp81ppxnh-shared-dep1799 CA: text:sha256:0js2jmidwg5dhh5c9vmrcp81jda2x48jdm861a9hmf1xb44maa5b18002026/10/01 09:40:15 OK 20251210153512_drop_unused_gin_index.sql (9.53ms)18012026/10/01 09:40:15 OK 20251218171726_add_pins.sql (22.19ms)18022026/10/01 09:40:15 OK 20260628120000_add_object_size_and_stats.sql (41.8ms)1803--- PASS: TestClientFallsBackToClosures (3.59s)1804=== CONT TestRedundantMultipartUpload18052026/10/01 09:40:15 OK 20260905000000_add_claims.sql (64.43ms)18062026/10/01 09:40:15 OK 20260920000000_drop_claims.sql (22.02ms)18072026/10/01 09:40:15 OK 20260923120000_add_pushes.sql (15.57ms)18082026/10/01 09:40:15 goose: successfully migrated database to version: 2026092312000018092026/10/01 09:40:15 OK 20241026095416_initial_model.sql (176.63ms)18102026/10/01 09:40:15 OK 1_commit_pending_closure.sql (1.01ms)18112026/10/01 09:40:15 OK 2_object_stats_trigger.sql (245.13µs)18122026/10/01 09:40:15 OK 3_commit_push.sql (182.42µs)18132026/10/01 09:40:15 goose: up to current file version: 318142026/10/01 09:40:15 OK 20251210153512_drop_unused_gin_index.sql (21.29ms)18152026/10/01 09:40:16 OK 20251218171726_add_pins.sql (28.94ms)1816=== NAME TestPinProtectsFromGC1817 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-51549-3085653128/TestPinProtectsFromGC2384335321/001/store/4229hd7rbcfcjg74ba24584flrcrfxyh-pinned-file.txt1818 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-51549-3085653128/TestPinProtectsFromGC2384335321/001/store/g8a3kwij4p3rv87b21w1m9r279fmiya0-unpinned-file.txt18192026/10/01 09:40:16 OK 20260628120000_add_object_size_and_stats.sql (18.8ms)18202026/10/01 09:40:16 OK 20260905000000_add_claims.sql (39.4ms)18212026/10/01 09:40:16 OK 20260920000000_drop_claims.sql (30.66ms)18222026-10-01 09:40:16.099 UTC [53016] ERROR: relation "goose_db_version" does not exist at character 3618232026-10-01 09:40:16.099 UTC [53016] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18242026/10/01 09:40:16 OK 20260923120000_add_pushes.sql (12.29ms)18252026/10/01 09:40:16 goose: successfully migrated database to version: 2026092312000018262026/10/01 09:40:16 OK 1_commit_pending_closure.sql (1.76ms)18272026/10/01 09:40:16 OK 2_object_stats_trigger.sql (401.42µs)18282026/10/01 09:40:16 OK 3_commit_push.sql (372.83µs)18292026/10/01 09:40:16 goose: up to current file version: 318302026/10/01 09:40:16 INFO Received push request method=POST path=/api/pushes18312026/10/01 09:40:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18322026/10/01 09:40:16 INFO Uploading 4229hd7rbcfcjg74ba24584flrcrfxyh-pinned-file.txt (128B)18332026/10/01 09:40:16 WARN Failed to register uploaded object key=4229hd7rbcfcjg74ba24584flrcrfxyh.ls error="server returned 404: 404 page not found\n"18342026/10/01 09:40:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18352026/10/01 09:40:16 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"18362026/10/01 09:40:16 INFO Signed narinfos id=1 count=118372026/10/01 09:40:16 INFO Uploading 1 narinfos18382026/10/01 09:40:16 INFO Received complete push request method=POST path=/api/pushes/1/complete18392026/10/01 09:40:16 WARN Failed to register uploaded object key=4229hd7rbcfcjg74ba24584flrcrfxyh.narinfo error="server returned 404: 404 page not found\n"18402026/10/01 09:40:16 INFO Upload complete. (164ms)18412026/10/01 09:40:16 OK 20241026095416_initial_model.sql (149.56ms)18422026-10-01 09:40:16.278 UTC [53026] ERROR: relation "goose_db_version" does not exist at character 3618432026-10-01 09:40:16.278 UTC [53026] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18442026/10/01 09:40:16 OK 20251210153512_drop_unused_gin_index.sql (12.82ms)18452026/10/01 09:40:16 OK 20251218171726_add_pins.sql (21.7ms)18462026-10-01 09:40:16.319 UTC [53028] ERROR: relation "goose_db_version" does not exist at character 3618472026-10-01 09:40:16.319 UTC [53028] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18482026/10/01 09:40:16 OK 20260628120000_add_object_size_and_stats.sql (18.93ms)18492026/10/01 09:40:16 INFO Received push request method=POST path=/api/pushes18502026/10/01 09:40:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18512026/10/01 09:40:16 INFO Uploading g8a3kwij4p3rv87b21w1m9r279fmiya0-unpinned-file.txt (128B)18522026/10/01 09:40:16 WARN Failed to register uploaded object key=g8a3kwij4p3rv87b21w1m9r279fmiya0.ls error="server returned 404: 404 page not found\n"18532026/10/01 09:40:16 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18542026/10/01 09:40:16 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18552026/10/01 09:40:16 INFO Signed narinfos id=2 count=118562026/10/01 09:40:16 INFO Uploading 1 narinfos18572026/10/01 09:40:16 OK 20260905000000_add_claims.sql (30.31ms)18582026/10/01 09:40:16 INFO Received complete push request method=POST path=/api/pushes/2/complete18592026/10/01 09:40:16 WARN Failed to register uploaded object key=g8a3kwij4p3rv87b21w1m9r279fmiya0.narinfo error="server returned 404: 404 page not found\n"18602026/10/01 09:40:16 INFO Upload complete. (92ms)18612026/10/01 09:40:16 OK 20260920000000_drop_claims.sql (17.33ms)18622026/10/01 09:40:16 OK 20260923120000_add_pushes.sql (10.76ms)18632026/10/01 09:40:16 goose: successfully migrated database to version: 2026092312000018642026/10/01 09:40:16 OK 1_commit_pending_closure.sql (1.56ms)18652026/10/01 09:40:16 OK 2_object_stats_trigger.sql (316.04µs)18662026/10/01 09:40:16 OK 3_commit_push.sql (203.83µs)18672026/10/01 09:40:16 goose: up to current file version: 318682026/10/01 09:40:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures18692026/10/01 09:40:16 INFO Garbage collection started18702026/10/01 09:40:16 INFO Aborted multipart uploads count=018712026/10/01 09:40:16 WARN Force mode enabled - objects will be deleted immediately without grace period18722026/10/01 09:40:16 OK 20241026095416_initial_model.sql (125.18ms)18732026/10/01 09:40:16 OK 20251210153512_drop_unused_gin_index.sql (8.31ms)18742026/10/01 09:40:16 OK 20241026095416_initial_model.sql (114.06ms)18752026/10/01 09:40:16 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=018762026/10/01 09:40:16 OK 20251218171726_add_pins.sql (11.07ms)18772026/10/01 09:40:16 OK 20251210153512_drop_unused_gin_index.sql (10.11ms)18782026/10/01 09:40:16 INFO Vacuumed table table=pending_closures1879--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (4.19s)1880=== CONT TestReadProxy40418812026/10/01 09:40:16 INFO Vacuumed table table=pending_objects18822026/10/01 09:40:16 INFO Vacuumed table table=multipart_uploads18832026/10/01 09:40:16 OK 20260628120000_add_object_size_and_stats.sql (46.84ms)18842026/10/01 09:40:16 OK 20251218171726_add_pins.sql (46.07ms)18852026/10/01 09:40:16 INFO Received push request method=POST path=/api/pushes18862026/10/01 09:40:16 INFO Vacuumed table table=closures18872026/10/01 09:40:16 OK 20260905000000_add_claims.sql (26.27ms)18882026/10/01 09:40:16 OK 20260628120000_add_object_size_and_stats.sql (25.74ms)18892026/10/01 09:40:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18902026/10/01 09:40:16 INFO Uploading dfb36pfw6ks033gzwgn9w9x8mp75y6xw-shared-dep (136B)18912026/10/01 09:40:16 INFO Uploading sxmdabdwax0zgkn7z760g4vkgawwxn0y-b (248B)18922026/10/01 09:40:16 INFO Vacuumed table table=objects18932026/10/01 09:40:16 WARN Failed to register uploaded object key=80y0km5csg5a9x87sm8nqxnyq5k4kx6d.ls error="server returned 404: 404 page not found\n"18942026/10/01 09:40:16 WARN Failed to register uploaded object key=nar/00al5q1i9dysc4bm978a7gn83hwq1f89l9y9d32lhx5xa2xdp0zi.nar.zst error="server returned 404: 404 page not found\n"18952026/10/01 09:40:16 WARN Failed to register uploaded object key=sxmdabdwax0zgkn7z760g4vkgawwxn0y.ls error="server returned 404: 404 page not found\n"18962026/10/01 09:40:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18972026/10/01 09:40:16 OK 20260920000000_drop_claims.sql (24.06ms)18982026/10/01 09:40:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18992026/10/01 09:40:16 WARN Failed to register uploaded object key=dfb36pfw6ks033gzwgn9w9x8mp75y6xw.ls error="server returned 404: 404 page not found\n"19002026/10/01 09:40:16 INFO Signed narinfos id=1 count=319012026/10/01 09:40:16 INFO Uploading 3 narinfos19022026/10/01 09:40:16 OK 20260923120000_add_pushes.sql (10.94ms)19032026/10/01 09:40:16 goose: successfully migrated database to version: 2026092312000019042026/10/01 09:40:16 WARN Failed to register uploaded object key=80y0km5csg5a9x87sm8nqxnyq5k4kx6d.narinfo error="server returned 404: 404 page not found\n"19052026/10/01 09:40:16 OK 1_commit_pending_closure.sql (1.11ms)19062026/10/01 09:40:16 WARN Failed to register uploaded object key=dfb36pfw6ks033gzwgn9w9x8mp75y6xw.narinfo error="server returned 404: 404 page not found\n"19072026/10/01 09:40:16 OK 2_object_stats_trigger.sql (255.96µs)19082026/10/01 09:40:16 OK 3_commit_push.sql (174.13µs)19092026/10/01 09:40:16 goose: up to current file version: 319102026/10/01 09:40:16 OK 20260905000000_add_claims.sql (43.85ms)19112026/10/01 09:40:16 INFO Received complete push request method=POST path=/api/pushes/1/complete19122026/10/01 09:40:16 WARN Failed to register uploaded object key=sxmdabdwax0zgkn7z760g4vkgawwxn0y.narinfo error="server returned 404: 404 page not found\n"19132026/10/01 09:40:16 INFO Upload complete. (146ms)1914=== NAME TestClientPushesUseOnePush1915 client_pushes_test.go:97: Retrieved narinfo from S3:1916 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientPushesUseOnePush2145089762/001/store/dfb36pfw6ks033gzwgn9w9x8mp75y6xw-shared-dep1917 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1918 Compression: zstd1919 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821920 NarSize: 1361921 References: 1922 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1923 client_pushes_test.go:97: Retrieved narinfo from S3:1924 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientPushesUseOnePush2145089762/001/store/80y0km5csg5a9x87sm8nqxnyq5k4kx6d-a1925 URL: nar/00al5q1i9dysc4bm978a7gn83hwq1f89l9y9d32lhx5xa2xdp0zi.nar.zst1926 Compression: zstd1927 NarHash: sha256:00al5q1i9dysc4bm978a7gn83hwq1f89l9y9d32lhx5xa2xdp0zi1928 NarSize: 2481929 References: /nix/var/nix/builds/nix-51549-3085653128/TestClientPushesUseOnePush2145089762/001/store/dfb36pfw6ks033gzwgn9w9x8mp75y6xw-shared-dep1930 CA: text:sha256:0zlhwmmvxq5nflam8x4w50qdz8jzmivbbh7ah90n9ahfxm4ypf4g1931 client_pushes_test.go:97: Retrieved narinfo from S3:1932 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientPushesUseOnePush2145089762/001/store/sxmdabdwax0zgkn7z760g4vkgawwxn0y-b1933 URL: nar/00al5q1i9dysc4bm978a7gn83hwq1f89l9y9d32lhx5xa2xdp0zi.nar.zst1934 Compression: zstd1935 NarHash: sha256:00al5q1i9dysc4bm978a7gn83hwq1f89l9y9d32lhx5xa2xdp0zi1936 NarSize: 2481937 References: /nix/var/nix/builds/nix-51549-3085653128/TestClientPushesUseOnePush2145089762/001/store/dfb36pfw6ks033gzwgn9w9x8mp75y6xw-shared-dep1938 CA: text:sha256:0zlhwmmvxq5nflam8x4w50qdz8jzmivbbh7ah90n9ahfxm4ypf4g19392026/10/01 09:40:16 INFO Received push request method=POST path=/api/pushes19402026/10/01 09:40:16 OK 20260920000000_drop_claims.sql (30.06ms)19412026/10/01 09:40:16 OK 20260923120000_add_pushes.sql (8.8ms)19422026/10/01 09:40:16 goose: successfully migrated database to version: 2026092312000019432026/10/01 09:40:16 OK 1_commit_pending_closure.sql (889.46µs)19442026/10/01 09:40:16 OK 2_object_stats_trigger.sql (244.75µs)19452026/10/01 09:40:16 OK 3_commit_push.sql (182.67µs)19462026/10/01 09:40:16 goose: up to current file version: 31947--- PASS: TestClientPushesUseOnePush (3.50s)1948=== CONT TestReadRedirectNar19492026/10/01 09:40:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19502026/10/01 09:40:16 INFO Signed narinfos id=1 count=11951--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.72s)1952=== CONT TestReadProxyDisabled19532026/10/01 09:40:16 INFO Received push request method=POST path=/api/pushes19542026/10/01 09:40:16 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)19552026/10/01 09:40:16 INFO Uploading fxnnfhldnbj3iwf7xaw56vbmsn25wanh-shared-dep (136B)19562026/10/01 09:40:16 INFO Uploading h93zc9aaqv7k1456il0bsarvz86x7qr1-top (256B)19572026/10/01 09:40:16 WARN Failed to register uploaded object key=h93zc9aaqv7k1456il0bsarvz86x7qr1.ls error="server returned 404: 404 page not found\n"19582026/10/01 09:40:16 WARN Failed to register uploaded object key=fxnnfhldnbj3iwf7xaw56vbmsn25wanh.ls error="server returned 404: 404 page not found\n"19592026/10/01 09:40:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19602026/10/01 09:40:16 WARN Failed to register uploaded object key=nar/1ylsh85kc4cwk96qp0in8j7ndlj8ji35m5iyw49vxqmn10pki0rf.nar.zst error="server returned 404: 404 page not found\n"19612026/10/01 09:40:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19622026/10/01 09:40:16 INFO Signed narinfos id=1 count=219632026/10/01 09:40:16 INFO Uploading 2 narinfos19642026/10/01 09:40:16 WARN Failed to register uploaded object key=fxnnfhldnbj3iwf7xaw56vbmsn25wanh.narinfo error="server returned 404: 404 page not found\n"19652026/10/01 09:40:16 INFO Received complete push request method=POST path=/api/pushes/1/complete19662026/10/01 09:40:16 WARN Failed to register uploaded object key=h93zc9aaqv7k1456il0bsarvz86x7qr1.narinfo error="server returned 404: 404 page not found\n"19672026/10/01 09:40:16 INFO Upload complete. (141ms)1968=== NAME TestClientSharedPathCommittedMidPush1969 client_integration_test.go:680: Retrieved narinfo from S3:1970 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientSharedPathCommittedMidPush2322265472/001/store/fxnnfhldnbj3iwf7xaw56vbmsn25wanh-shared-dep1971 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1972 Compression: zstd1973 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821974 NarSize: 1361975 References: 1976 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1977 client_integration_test.go:680: Retrieved narinfo from S3:1978 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestClientSharedPathCommittedMidPush2322265472/001/store/h93zc9aaqv7k1456il0bsarvz86x7qr1-top1979 URL: nar/1ylsh85kc4cwk96qp0in8j7ndlj8ji35m5iyw49vxqmn10pki0rf.nar.zst1980 Compression: zstd1981 NarHash: sha256:1ylsh85kc4cwk96qp0in8j7ndlj8ji35m5iyw49vxqmn10pki0rf1982 NarSize: 2561983 References: /nix/var/nix/builds/nix-51549-3085653128/TestClientSharedPathCommittedMidPush2322265472/001/store/fxnnfhldnbj3iwf7xaw56vbmsn25wanh-shared-dep1984 CA: text:sha256:0yp7jv4pqbnf3v51h18yr4x38hgy845052a8vsfwsf472id74f8d1985--- PASS: TestClientSharedPathCommittedMidPush (3.57s)1986=== CONT TestReadProxyRootRedirectsToIndexHTML19872026-10-01 09:40:16.909 UTC [53065] ERROR: relation "goose_db_version" does not exist at character 3619882026-10-01 09:40:16.909 UTC [53065] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1989--- PASS: TestService_Rustfstest (2.82s)1990=== CONT TestReadProxyConditionalGet19912026/10/01 09:40:17 OK 20241026095416_initial_model.sql (57.71ms)19922026/10/01 09:40:17 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)19932026/10/01 09:40:17 OK 20251218171726_add_pins.sql (21.06ms)19942026/10/01 09:40:17 OK 20260628120000_add_object_size_and_stats.sql (29.86ms)19952026/10/01 09:40:17 OK 20260905000000_add_claims.sql (47.61ms)19962026/10/01 09:40:17 OK 20260920000000_drop_claims.sql (35.38ms)19972026/10/01 09:40:17 OK 20260923120000_add_pushes.sql (2.92ms)19982026/10/01 09:40:17 goose: successfully migrated database to version: 2026092312000019992026/10/01 09:40:17 OK 1_commit_pending_closure.sql (1.17ms)20002026/10/01 09:40:17 OK 2_object_stats_trigger.sql (355.92µs)20012026/10/01 09:40:17 OK 3_commit_push.sql (186.21µs)20022026/10/01 09:40:17 goose: up to current file version: 320032026/10/01 09:40:17 INFO Received uploads request method=POST path=/api/pending_closures20042026/10/01 09:40:17 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst20052026/10/01 09:40:17 INFO Received uploads request method=POST path=/api/pending_closures2006--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.72s)2007=== CONT TestReadProxyHead20082026/10/01 09:40:17 INFO Received uploads request method=POST path=/api/pending_closures20092026-10-01 09:40:17.614 UTC [53073] ERROR: relation "goose_db_version" does not exist at character 3620102026-10-01 09:40:17.614 UTC [53073] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20112026/10/01 09:40:17 INFO Received uploads request method=POST path=/api/pending_closures20122026-10-01 09:40:17.821 UTC [53074] ERROR: relation "goose_db_version" does not exist at character 3620132026-10-01 09:40:17.821 UTC [53074] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20142026/10/01 09:40:17 OK 20241026095416_initial_model.sql (190.21ms)20152026/10/01 09:40:17 OK 20251210153512_drop_unused_gin_index.sql (14.89ms)20162026/10/01 09:40:17 OK 20251218171726_add_pins.sql (52.39ms)20172026/10/01 09:40:17 OK 20260628120000_add_object_size_and_stats.sql (38.59ms)20182026/10/01 09:40:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20192026/10/01 09:40:17 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjA1MTgyNzgtYzE4Yi00MGE0LWE0Y2QtMDg0Yzg5YWJmZjY5LmFkYWFhMjZkLTdlNzMtNGMzMy04ZDY2LWRhNzYwZDM2OTYzOXgxNzkwODQ3NjE3NzA0NTA3MDAw20202026/10/01 09:40:17 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjA1MTgyNzgtYzE4Yi00MGE0LWE0Y2QtMDg0Yzg5YWJmZjY5LmFkYWFhMjZkLTdlNzMtNGMzMy04ZDY2LWRhNzYwZDM2OTYzOXgxNzkwODQ3NjE3NzA0NTA3MDAw parts=12021--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.14s)2022=== CONT TestReadProxyInvalidPath20232026/10/01 09:40:18 INFO Received uploads request method=POST path=/api/pending_closures20242026/10/01 09:40:18 OK 20260905000000_add_claims.sql (94.24ms)20252026/10/01 09:40:18 OK 20260920000000_drop_claims.sql (65.65ms)20262026/10/01 09:40:18 INFO Received uploads request method=POST path=/api/pending_closures20272026/10/01 09:40:18 OK 20260923120000_add_pushes.sql (12.69ms)20282026/10/01 09:40:18 goose: successfully migrated database to version: 2026092312000020292026/10/01 09:40:18 OK 1_commit_pending_closure.sql (10.81ms)20302026/10/01 09:40:18 OK 20241026095416_initial_model.sql (208.55ms)20312026/10/01 09:40:18 OK 2_object_stats_trigger.sql (1.66ms)20322026/10/01 09:40:18 OK 3_commit_push.sql (1.37ms)20332026/10/01 09:40:18 goose: up to current file version: 320342026/10/01 09:40:18 OK 20251210153512_drop_unused_gin_index.sql (15.09ms)20352026/10/01 09:40:18 OK 20251218171726_add_pins.sql (66.89ms)20362026-10-01 09:40:18.240 UTC [53077] ERROR: relation "goose_db_version" does not exist at character 3620372026-10-01 09:40:18.240 UTC [53077] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20382026-10-01 09:40:18.241 UTC [53078] ERROR: relation "goose_db_version" does not exist at character 3620392026-10-01 09:40:18.241 UTC [53078] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20402026/10/01 09:40:18 OK 20260628120000_add_object_size_and_stats.sql (28.82ms)20412026/10/01 09:40:18 OK 20260905000000_add_claims.sql (48.26ms)20422026/10/01 09:40:18 OK 20260920000000_drop_claims.sql (35.65ms)20432026/10/01 09:40:18 OK 20260923120000_add_pushes.sql (19.17ms)20442026/10/01 09:40:18 goose: successfully migrated database to version: 2026092312000020452026/10/01 09:40:18 OK 1_commit_pending_closure.sql (1.42ms)20462026/10/01 09:40:18 OK 2_object_stats_trigger.sql (566.33µs)20472026/10/01 09:40:18 OK 3_commit_push.sql (418µs)20482026/10/01 09:40:18 goose: up to current file version: 320492026-10-01 09:40:18.379 UTC [53079] ERROR: relation "goose_db_version" does not exist at character 3620502026-10-01 09:40:18.379 UTC [53079] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20512026/10/01 09:40:18 OK 20241026095416_initial_model.sql (102.39ms)20522026/10/01 09:40:18 OK 20251210153512_drop_unused_gin_index.sql (10.97ms)20532026/10/01 09:40:18 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020542026/10/01 09:40:18 INFO Received create pin request method=POST path=/api/pins/myapp20552026/10/01 09:40:18 OK 20251218171726_add_pins.sql (28.84ms)20562026/10/01 09:40:18 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-51549-3085653128/TestPinProtectsFromGC2384335321/001/store/4229hd7rbcfcjg74ba24584flrcrfxyh-pinned-file.txt narinfo_key=4229hd7rbcfcjg74ba24584flrcrfxyh.narinfo20572026/10/01 09:40:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures20582026/10/01 09:40:18 INFO Garbage collection started20592026/10/01 09:40:18 INFO Aborted multipart uploads count=020602026/10/01 09:40:18 WARN Force mode enabled - objects will be deleted immediately without grace period20612026/10/01 09:40:18 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=020622026/10/01 09:40:18 INFO Vacuumed table table=pending_closures20632026/10/01 09:40:18 INFO Vacuumed table table=pending_objects20642026/10/01 09:40:18 INFO Vacuumed table table=multipart_uploads20652026/10/01 09:40:18 INFO Vacuumed table table=closures20662026/10/01 09:40:18 INFO Vacuumed table table=objects20672026/10/01 09:40:18 OK 20260628120000_add_object_size_and_stats.sql (35.09ms)20682026/10/01 09:40:18 OK 20241026095416_initial_model.sql (182.38ms)2069--- PASS: TestReadProxy404 (1.97s)2070=== CONT TestObjectStatsTrigger20712026/10/01 09:40:18 OK 20251210153512_drop_unused_gin_index.sql (10.54ms)20722026/10/01 09:40:18 OK 20260905000000_add_claims.sql (47.77ms)20732026/10/01 09:40:18 OK 20251218171726_add_pins.sql (43.63ms)20742026/10/01 09:40:18 OK 20260920000000_drop_claims.sql (58.69ms)20752026/10/01 09:40:18 OK 20260628120000_add_object_size_and_stats.sql (57.11ms)20762026/10/01 09:40:18 OK 20241026095416_initial_model.sql (156.15ms)20772026/10/01 09:40:18 OK 20260923120000_add_pushes.sql (31.14ms)20782026/10/01 09:40:18 goose: successfully migrated database to version: 2026092312000020792026/10/01 09:40:18 OK 1_commit_pending_closure.sql (1.04ms)20802026/10/01 09:40:18 OK 2_object_stats_trigger.sql (261.5µs)20812026/10/01 09:40:18 OK 3_commit_push.sql (178.96µs)20822026/10/01 09:40:18 goose: up to current file version: 320832026/10/01 09:40:18 OK 20251210153512_drop_unused_gin_index.sql (15.82ms)20842026/10/01 09:40:18 OK 20251218171726_add_pins.sql (26.13ms)20852026/10/01 09:40:18 OK 20260905000000_add_claims.sql (59.67ms)20862026/10/01 09:40:18 OK 20260920000000_drop_claims.sql (62.13ms)20872026/10/01 09:40:18 OK 20260628120000_add_object_size_and_stats.sql (77.59ms)20882026/10/01 09:40:18 OK 20260923120000_add_pushes.sql (23.65ms)20892026/10/01 09:40:18 goose: successfully migrated database to version: 2026092312000020902026/10/01 09:40:18 OK 1_commit_pending_closure.sql (970µs)20912026/10/01 09:40:18 OK 2_object_stats_trigger.sql (233.79µs)20922026/10/01 09:40:18 OK 3_commit_push.sql (190.08µs)20932026/10/01 09:40:18 goose: up to current file version: 320942026/10/01 09:40:18 OK 20260905000000_add_claims.sql (58.51ms)20952026/10/01 09:40:18 OK 20260920000000_drop_claims.sql (65.17ms)2096--- PASS: TestReadProxyDisabled (2.19s)2097=== CONT TestPresentNotReportedWhileGCDeletesClosure20982026/10/01 09:40:18 OK 20260923120000_add_pushes.sql (32.54ms)20992026/10/01 09:40:18 goose: successfully migrated database to version: 2026092312000021002026/10/01 09:40:18 OK 1_commit_pending_closure.sql (1.29ms)21012026/10/01 09:40:18 OK 2_object_stats_trigger.sql (600.96µs)21022026/10/01 09:40:18 OK 3_commit_push.sql (336.46µs)21032026/10/01 09:40:18 goose: up to current file version: 321042026-10-01 09:40:19.089 UTC [53084] ERROR: relation "goose_db_version" does not exist at character 3621052026-10-01 09:40:19.089 UTC [53084] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2106--- PASS: TestReadProxyConditionalGet (2.36s)2107=== CONT TestPresentReportsOnlyClosureRoots21082026/10/01 09:40:19 OK 20241026095416_initial_model.sql (245.99ms)21092026/10/01 09:40:19 OK 20251210153512_drop_unused_gin_index.sql (28.77ms)21102026/10/01 09:40:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21112026/10/01 09:40:19 OK 20251218171726_add_pins.sql (80.68ms)21122026/10/01 09:40:19 OK 20260628120000_add_object_size_and_stats.sql (18.33ms)21132026/10/01 09:40:19 OK 20260905000000_add_claims.sql (39.38ms)21142026/10/01 09:40:19 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NjA1MTgyNzgtYzE4Yi00MGE0LWE0Y2QtMDg0Yzg5YWJmZjY5LmZmZTQ1MTMzLTRmODMtNDAyMS1iODA4LWYyMjI1NTIzNzliZngxNzkwODQ3NjE3NDM4ODE3MDAw parts=1221152026/10/01 09:40:19 INFO Received uploads request method=POST path=/api/pending_closures2116--- PASS: TestCompletedNarNotReofferedAcrossClosures (5.10s)2117=== CONT TestCreatePin_ReservedPins21182026/10/01 09:40:19 OK 20260920000000_drop_claims.sql (73.64ms)21192026-10-01 09:40:19.671 UTC [53088] ERROR: relation "goose_db_version" does not exist at character 3621202026-10-01 09:40:19.671 UTC [53088] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21212026/10/01 09:40:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49857/oidc21222026/10/01 09:40:19 OK 20260923120000_add_pushes.sql (30.85ms)21232026/10/01 09:40:19 goose: successfully migrated database to version: 2026092312000021242026/10/01 09:40:19 OK 1_commit_pending_closure.sql (2.39ms)21252026/10/01 09:40:19 OK 2_object_stats_trigger.sql (616.79µs)21262026/10/01 09:40:19 OK 3_commit_push.sql (451µs)21272026/10/01 09:40:19 goose: up to current file version: 32128--- PASS: TestReadRedirectNar (3.08s)2129=== CONT TestOrphanedObjectsGCStressTest21302026/10/01 09:40:19 OK 20241026095416_initial_model.sql (214.41ms)21312026/10/01 09:40:19 OK 20251210153512_drop_unused_gin_index.sql (6.25ms)21322026-10-01 09:40:19.968 UTC [53093] ERROR: relation "goose_db_version" does not exist at character 3621332026-10-01 09:40:19.968 UTC [53093] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21342026/10/01 09:40:19 OK 20251218171726_add_pins.sql (34.93ms)21352026/10/01 09:40:20 OK 20260628120000_add_object_size_and_stats.sql (31.97ms)21362026/10/01 09:40:20 OK 20260905000000_add_claims.sql (51.77ms)2137--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.24s)2138=== CONT TestOrphanedObjectsGC21392026/10/01 09:40:20 OK 20260920000000_drop_claims.sql (66.91ms)21402026/10/01 09:40:20 OK 20260923120000_add_pushes.sql (15.57ms)21412026/10/01 09:40:20 goose: successfully migrated database to version: 2026092312000021422026/10/01 09:40:20 OK 1_commit_pending_closure.sql (1.12ms)21432026/10/01 09:40:20 OK 2_object_stats_trigger.sql (280.33µs)21442026/10/01 09:40:20 OK 3_commit_push.sql (238.83µs)21452026/10/01 09:40:20 goose: up to current file version: 321462026/10/01 09:40:20 OK 20241026095416_initial_model.sql (148.63ms)21472026/10/01 09:40:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21482026/10/01 09:40:20 OK 20251210153512_drop_unused_gin_index.sql (45.34ms)21492026/10/01 09:40:20 OK 20251218171726_add_pins.sql (37.13ms)21502026/10/01 09:40:20 OK 20260628120000_add_object_size_and_stats.sql (45.39ms)21512026/10/01 09:40:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NjA1MTgyNzgtYzE4Yi00MGE0LWE0Y2QtMDg0Yzg5YWJmZjY5LmRjZDhjMDFlLTBlY2YtNDdhYy05ZWEzLTc0OWVjMmRkYTRjZXgxNzkwODQ3NjE4MDg3MTE5MDAw parts=122152--- PASS: TestRedundantMultipartUpload (4.47s)2153=== CONT TestPush_CompleteCommitsEveryRoot21542026/10/01 09:40:20 OK 20260905000000_add_claims.sql (51.37ms)21552026/10/01 09:40:20 OK 20260920000000_drop_claims.sql (38.08ms)21562026/10/01 09:40:20 OK 20260923120000_add_pushes.sql (16.53ms)21572026/10/01 09:40:20 goose: successfully migrated database to version: 2026092312000021582026/10/01 09:40:20 OK 1_commit_pending_closure.sql (3.89ms)21592026/10/01 09:40:20 OK 2_object_stats_trigger.sql (4.65ms)21602026/10/01 09:40:20 OK 3_commit_push.sql (1.48ms)21612026/10/01 09:40:20 goose: up to current file version: 32162=== NAME TestPinProtectsFromGC2163 client_integration_test.go:840: Pin successfully protected closure from garbage collection2164--- PASS: TestReadProxyHead (3.25s)2165=== CONT TestPush_RejectsBadRequests2166--- PASS: TestPinProtectsFromGC (7.88s)2167=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit21682026-10-01 09:40:20.531 UTC [53098] ERROR: relation "goose_db_version" does not exist at character 3621692026-10-01 09:40:20.531 UTC [53098] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21702026/10/01 09:40:20 OK 20241026095416_initial_model.sql (87.29ms)21712026-10-01 09:40:20.681 UTC [53103] ERROR: relation "goose_db_version" does not exist at character 3621722026-10-01 09:40:20.681 UTC [53103] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21732026/10/01 09:40:20 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)21742026/10/01 09:40:20 OK 20251218171726_add_pins.sql (29.83ms)21752026/10/01 09:40:20 OK 20260628120000_add_object_size_and_stats.sql (38.32ms)2176--- PASS: TestReadProxyInvalidPath (2.78s)2177=== CONT TestReadProxyNarinfo21782026/10/01 09:40:20 OK 20260905000000_add_claims.sql (67.73ms)21792026/10/01 09:40:20 OK 20241026095416_initial_model.sql (82.72ms)21802026/10/01 09:40:20 OK 20260920000000_drop_claims.sql (7.3ms)21812026/10/01 09:40:20 OK 20251210153512_drop_unused_gin_index.sql (4.39ms)21822026/10/01 09:40:20 OK 20260923120000_add_pushes.sql (6.58ms)21832026/10/01 09:40:20 goose: successfully migrated database to version: 2026092312000021842026/10/01 09:40:20 OK 1_commit_pending_closure.sql (1.92ms)21852026/10/01 09:40:20 OK 2_object_stats_trigger.sql (1.44ms)21862026/10/01 09:40:20 OK 3_commit_push.sql (196.08µs)21872026/10/01 09:40:20 goose: up to current file version: 321882026/10/01 09:40:20 OK 20251218171726_add_pins.sql (20.63ms)21892026/10/01 09:40:20 OK 20260628120000_add_object_size_and_stats.sql (24.97ms)21902026/10/01 09:40:20 OK 20260905000000_add_claims.sql (39.66ms)21912026/10/01 09:40:20 OK 20260920000000_drop_claims.sql (9.74ms)21922026/10/01 09:40:20 OK 20260923120000_add_pushes.sql (8.47ms)21932026/10/01 09:40:20 goose: successfully migrated database to version: 2026092312000021942026/10/01 09:40:20 OK 1_commit_pending_closure.sql (1.54ms)21952026/10/01 09:40:20 OK 2_object_stats_trigger.sql (538.63µs)21962026/10/01 09:40:20 OK 3_commit_push.sql (409.42µs)21972026/10/01 09:40:20 goose: up to current file version: 321982026-10-01 09:40:21.006 UTC [53108] ERROR: relation "goose_db_version" does not exist at character 3621992026-10-01 09:40:21.006 UTC [53108] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22002026-10-01 09:40:21.077 UTC [53110] ERROR: relation "goose_db_version" does not exist at character 3622012026-10-01 09:40:21.077 UTC [53110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2202--- PASS: TestObjectStatsTrigger (2.59s)2203=== CONT TestReadProxyNarStreaming22042026/10/01 09:40:21 OK 20241026095416_initial_model.sql (49.73ms)22052026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (6.91ms)22062026/10/01 09:40:21 OK 20251218171726_add_pins.sql (20.59ms)22072026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (14.49ms)22082026/10/01 09:40:21 OK 20260905000000_add_claims.sql (35.21ms)22092026/10/01 09:40:21 OK 20241026095416_initial_model.sql (88.69ms)22102026-10-01 09:40:21.212 UTC [53118] ERROR: relation "goose_db_version" does not exist at character 3622112026-10-01 09:40:21.212 UTC [53118] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22122026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)22132026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (36.05ms)22142026/10/01 09:40:21 OK 20251218171726_add_pins.sql (29.52ms)22152026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (9.14ms)22162026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022172026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.08ms)22182026/10/01 09:40:21 OK 2_object_stats_trigger.sql (544µs)22192026/10/01 09:40:21 OK 3_commit_push.sql (439.5µs)22202026/10/01 09:40:21 goose: up to current file version: 322212026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (19.63ms)22222026/10/01 09:40:21 OK 20260905000000_add_claims.sql (20.19ms)22232026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (30.82ms)22242026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (21.05ms)22252026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022262026/10/01 09:40:21 OK 20241026095416_initial_model.sql (80.32ms)22272026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.6ms)22282026/10/01 09:40:21 OK 2_object_stats_trigger.sql (789.54µs)22292026/10/01 09:40:21 OK 3_commit_push.sql (231.46µs)22302026/10/01 09:40:21 goose: up to current file version: 322312026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)22322026/10/01 09:40:21 OK 20251218171726_add_pins.sql (15.87ms)22332026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (10.35ms)22342026/10/01 09:40:21 OK 20260905000000_add_claims.sql (10.74ms)22352026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (19.81ms)22362026-10-01 09:40:21.414 UTC [53123] ERROR: relation "goose_db_version" does not exist at character 3622372026-10-01 09:40:21.414 UTC [53123] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22382026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (17.84ms)22392026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022402026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.62ms)22412026/10/01 09:40:21 OK 2_object_stats_trigger.sql (483.96µs)22422026/10/01 09:40:21 OK 3_commit_push.sql (422.25µs)22432026/10/01 09:40:21 goose: up to current file version: 322442026-10-01 09:40:21.478 UTC [53126] ERROR: relation "goose_db_version" does not exist at character 3622452026-10-01 09:40:21.478 UTC [53126] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22462026-10-01 09:40:21.481 UTC [53125] ERROR: relation "goose_db_version" does not exist at character 3622472026-10-01 09:40:21.481 UTC [53125] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22482026-10-01 09:40:21.543 UTC [53127] ERROR: relation "goose_db_version" does not exist at character 3622492026-10-01 09:40:21.543 UTC [53127] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22502026/10/01 09:40:21 OK 20241026095416_initial_model.sql (93.24ms)22512026/10/01 09:40:21 OK 20241026095416_initial_model.sql (41.71ms)22522026/10/01 09:40:21 OK 20241026095416_initial_model.sql (35.78ms)22532026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (20.92ms)22542026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (20.91ms)22552026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (20.96ms)2256--- PASS: TestPresentReportsOnlyClosureRoots (2.35s)2257=== CONT TestReadProxyNarinfoAlreadyDecompressed22582026/10/01 09:40:21 OK 20251218171726_add_pins.sql (24.12ms)22592026/10/01 09:40:21 OK 20241026095416_initial_model.sql (40.01ms)22602026/10/01 09:40:21 OK 20251218171726_add_pins.sql (30.88ms)22612026/10/01 09:40:21 OK 20251218171726_add_pins.sql (37.7ms)22622026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (19.58ms)22632026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (25.88ms)22642026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (22.86ms)22652026/10/01 09:40:21 OK 20260905000000_add_claims.sql (16.8ms)22662026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (30.36ms)22672026/10/01 09:40:21 OK 20251218171726_add_pins.sql (5ms)22682026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (4.14ms)22692026/10/01 09:40:21 OK 20260905000000_add_claims.sql (5.08ms)22702026/10/01 09:40:21 OK 20260905000000_add_claims.sql (6.03ms)22712026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (16.55ms)22722026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (20.01ms)22732026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022742026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (18.49ms)22752026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (18.83ms)22762026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.32ms)22772026/10/01 09:40:21 OK 2_object_stats_trigger.sql (607.63µs)22782026/10/01 09:40:21 OK 3_commit_push.sql (476.29µs)22792026/10/01 09:40:21 goose: up to current file version: 322802026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (7.6ms)22812026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022822026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (9.02ms)22832026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022842026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.2ms)22852026/10/01 09:40:21 OK 2_object_stats_trigger.sql (504.75µs)22862026/10/01 09:40:21 OK 3_commit_push.sql (457.08µs)22872026/10/01 09:40:21 goose: up to current file version: 322882026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.01ms)22892026/10/01 09:40:21 OK 2_object_stats_trigger.sql (555.13µs)22902026/10/01 09:40:21 OK 3_commit_push.sql (458.04µs)22912026/10/01 09:40:21 goose: up to current file version: 322922026/10/01 09:40:21 OK 20260905000000_add_claims.sql (26.46ms)22932026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (6.49ms)22942026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (1.11ms)22952026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000022962026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.69ms)22972026/10/01 09:40:21 OK 2_object_stats_trigger.sql (652.21µs)22982026/10/01 09:40:21 OK 3_commit_push.sql (413.83µs)22992026/10/01 09:40:21 goose: up to current file version: 323002026-10-01 09:40:21.724 UTC [53133] ERROR: relation "goose_db_version" does not exist at character 3623012026-10-01 09:40:21.724 UTC [53133] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23022026/10/01 09:40:21 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux23032026/10/01 09:40:21 WARN Refused reserved pin name=worker-x86_64-linux23042026/10/01 09:40:21 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux23052026/10/01 09:40:21 INFO Received create pin request method=POST path=/api/pins/my-app23062026/10/01 09:40:21 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2307--- PASS: TestCreatePin_ReservedPins (2.14s)2308=== CONT TestService_AuthMiddleware_MTLSBoundSubjects23092026/10/01 09:40:21 OK 20241026095416_initial_model.sql (53.92ms)2310--- PASS: TestPresentNotReportedWhileGCDeletesClosure (2.93s)2311=== CONT TestService_ReadAuthMiddleware23122026/10/01 09:40:21 OK 20251210153512_drop_unused_gin_index.sql (19.42ms)23132026/10/01 09:40:21 OK 20251218171726_add_pins.sql (20ms)23142026/10/01 09:40:21 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)23152026/10/01 09:40:21 OK 20260905000000_add_claims.sql (33.02ms)23162026/10/01 09:40:21 OK 20260920000000_drop_claims.sql (7.36ms)23172026/10/01 09:40:21 OK 20260923120000_add_pushes.sql (5.32ms)23182026/10/01 09:40:21 goose: successfully migrated database to version: 2026092312000023192026/10/01 09:40:21 OK 1_commit_pending_closure.sql (2.07ms)23202026/10/01 09:40:21 OK 2_object_stats_trigger.sql (526.25µs)23212026/10/01 09:40:21 OK 3_commit_push.sql (411.21µs)23222026/10/01 09:40:21 goose: up to current file version: 323232026-10-01 09:40:22.222 UTC [53143] ERROR: relation "goose_db_version" does not exist at character 3623242026-10-01 09:40:22.222 UTC [53143] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23252026-10-01 09:40:22.291 UTC [53146] ERROR: relation "goose_db_version" does not exist at character 3623262026-10-01 09:40:22.291 UTC [53146] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23272026/10/01 09:40:22 OK 20241026095416_initial_model.sql (106.26ms)23282026/10/01 09:40:22 OK 20251210153512_drop_unused_gin_index.sql (17.46ms)23292026-10-01 09:40:22.393 UTC [53147] ERROR: relation "goose_db_version" does not exist at character 3623302026-10-01 09:40:22.393 UTC [53147] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23312026/10/01 09:40:22 OK 20251218171726_add_pins.sql (12.45ms)23322026/10/01 09:40:22 OK 20260628120000_add_object_size_and_stats.sql (9.07ms)23332026/10/01 09:40:22 OK 20241026095416_initial_model.sql (74.24ms)23342026/10/01 09:40:22 OK 20251210153512_drop_unused_gin_index.sql (7.36ms)23352026/10/01 09:40:22 OK 20260905000000_add_claims.sql (9.64ms)23362026/10/01 09:40:22 OK 20251218171726_add_pins.sql (12.21ms)23372026/10/01 09:40:22 OK 20260920000000_drop_claims.sql (11.7ms)23382026/10/01 09:40:22 OK 20260923120000_add_pushes.sql (8.36ms)23392026/10/01 09:40:22 goose: successfully migrated database to version: 2026092312000023402026/10/01 09:40:22 OK 20260628120000_add_object_size_and_stats.sql (9.83ms)23412026/10/01 09:40:22 OK 1_commit_pending_closure.sql (1.29ms)23422026/10/01 09:40:22 OK 2_object_stats_trigger.sql (304.54µs)23432026/10/01 09:40:22 OK 3_commit_push.sql (408.13µs)23442026/10/01 09:40:22 goose: up to current file version: 323452026/10/01 09:40:22 OK 20260905000000_add_claims.sql (19.72ms)23462026/10/01 09:40:22 INFO Received push request method=POST path=/api/pushes23472026/10/01 09:40:22 OK 20260920000000_drop_claims.sql (6.35ms)23482026/10/01 09:40:22 OK 20241026095416_initial_model.sql (54.95ms)23492026/10/01 09:40:22 OK 20251210153512_drop_unused_gin_index.sql (6.46ms)23502026/10/01 09:40:22 OK 20260923120000_add_pushes.sql (7.25ms)23512026/10/01 09:40:22 goose: successfully migrated database to version: 2026092312000023522026/10/01 09:40:22 OK 1_commit_pending_closure.sql (2.02ms)23532026/10/01 09:40:22 OK 2_object_stats_trigger.sql (551.38µs)23542026/10/01 09:40:22 OK 3_commit_push.sql (417.88µs)23552026/10/01 09:40:22 goose: up to current file version: 323562026/10/01 09:40:22 OK 20251218171726_add_pins.sql (24.15ms)23572026/10/01 09:40:22 INFO Received complete push request method=POST path=/api/pushes/1/complete23582026/10/01 09:40:22 OK 20260628120000_add_object_size_and_stats.sql (18.76ms)23592026/10/01 09:40:22 INFO Received push request method=POST path=/api/pushes23602026/10/01 09:40:22 OK 20260905000000_add_claims.sql (39.96ms)23612026/10/01 09:40:22 OK 20260920000000_drop_claims.sql (7.36ms)23622026/10/01 09:40:22 OK 20260923120000_add_pushes.sql (4.71ms)23632026/10/01 09:40:22 goose: successfully migrated database to version: 2026092312000023642026/10/01 09:40:22 OK 1_commit_pending_closure.sql (2.17ms)23652026/10/01 09:40:22 OK 2_object_stats_trigger.sql (890.46µs)23662026/10/01 09:40:22 OK 3_commit_push.sql (735.88µs)23672026/10/01 09:40:22 goose: up to current file version: 323682026/10/01 09:40:22 INFO Aborted multipart uploads count=023692026/10/01 09:40:22 WARN Force mode enabled - objects will be deleted immediately without grace period23702026/10/01 09:40:22 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=023712026/10/01 09:40:22 INFO Vacuumed table table=pending_closures23722026/10/01 09:40:22 INFO Vacuumed table table=pending_objects23732026/10/01 09:40:22 INFO Vacuumed table table=multipart_uploads23742026/10/01 09:40:22 INFO Vacuumed table table=closures2375=== RUN TestPush_RejectsBadRequests/no_roots23762026/10/01 09:40:22 INFO Vacuumed table table=objects2377=== PAUSE TestPush_RejectsBadRequests/no_roots2378=== RUN TestPush_RejectsBadRequests/no_objects2379=== PAUSE TestPush_RejectsBadRequests/no_objects2380=== RUN TestPush_RejectsBadRequests/bad_root2381=== PAUSE TestPush_RejectsBadRequests/bad_root2382=== RUN TestPush_RejectsBadRequests/root_not_in_objects2383=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2384=== CONT TestService_AuthMiddleware_MTLSProxyHeader23852026/10/01 09:40:22 INFO Received complete push request method=POST path=/api/pushes/2/complete2386--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.17s)2387=== CONT TestProxyHeadersOnlyTrustedOnSocket2388=== NAME TestOrphanedObjectsGC2389 orphaned_objects_gc_test.go:290: GC Test Summary:2390 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2391 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2392 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2393 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2394 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2395--- PASS: TestOrphanedObjectsGC (2.68s)2396=== CONT TestIsValidCachePath2397=== RUN TestIsValidCachePath/narinfo2398=== PAUSE TestIsValidCachePath/narinfo2399=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2400=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2401=== RUN TestIsValidCachePath/nar_zst2402=== PAUSE TestIsValidCachePath/nar_zst2403=== RUN TestIsValidCachePath/nar_xz2404=== PAUSE TestIsValidCachePath/nar_xz2405=== RUN TestIsValidCachePath/nar_bz22406=== PAUSE TestIsValidCachePath/nar_bz22407=== RUN TestIsValidCachePath/nar_uncompressed2408=== PAUSE TestIsValidCachePath/nar_uncompressed2409=== RUN TestIsValidCachePath/ls2410=== PAUSE TestIsValidCachePath/ls2411=== RUN TestIsValidCachePath/log2412=== PAUSE TestIsValidCachePath/log2413=== RUN TestIsValidCachePath/realisation2414=== PAUSE TestIsValidCachePath/realisation2415=== RUN TestIsValidCachePath/nix-cache-info2416=== PAUSE TestIsValidCachePath/nix-cache-info2417=== RUN TestIsValidCachePath/index.html2418=== PAUSE TestIsValidCachePath/index.html2419=== RUN TestIsValidCachePath/traversal_parent2420=== PAUSE TestIsValidCachePath/traversal_parent2421=== RUN TestIsValidCachePath/traversal_in_middle2422=== PAUSE TestIsValidCachePath/traversal_in_middle2423=== RUN TestIsValidCachePath/invalid_char_e2424=== PAUSE TestIsValidCachePath/invalid_char_e2425=== RUN TestIsValidCachePath/invalid_char_u2426=== PAUSE TestIsValidCachePath/invalid_char_u2427=== RUN TestIsValidCachePath/random_path2428=== PAUSE TestIsValidCachePath/random_path2429=== RUN TestIsValidCachePath/empty2430=== PAUSE TestIsValidCachePath/empty2431=== RUN TestIsValidCachePath/leading_slash2432=== PAUSE TestIsValidCachePath/leading_slash2433=== RUN TestIsValidCachePath/wrong_extension2434=== PAUSE TestIsValidCachePath/wrong_extension2435=== RUN TestIsValidCachePath/short_hash2436=== PAUSE TestIsValidCachePath/short_hash2437=== CONT TestService_NativeMTLS24382026/10/01 09:40:22 INFO Received push request method=POST path=/api/pushes24392026/10/01 09:40:22 INFO Received complete push request method=POST path=/api/pushes/1/complete2440--- PASS: TestPush_CompleteCommitsEveryRoot (2.69s)2441=== CONT TestMultipartCleanup2442--- PASS: TestReadProxyNarinfo (2.46s)2443=== CONT TestServerTLSConfig2444=== RUN TestServerTLSConfig/no_client_CA2445=== PAUSE TestServerTLSConfig/no_client_CA2446=== RUN TestServerTLSConfig/missing_CA_file2447=== PAUSE TestServerTLSConfig/missing_CA_file2448=== RUN TestServerTLSConfig/not_a_PEM_file2449=== PAUSE TestServerTLSConfig/not_a_PEM_file2450=== CONT TestNARDeduplicationMetadataUploadBug2451--- PASS: TestReadProxyNarStreaming (2.38s)2452=== CONT TestMetricsInventory24532026-10-01 09:40:23.698 UTC [53226] ERROR: relation "goose_db_version" does not exist at character 3624542026-10-01 09:40:23.698 UTC [53226] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24552026-10-01 09:40:23.730 UTC [53227] ERROR: relation "goose_db_version" does not exist at character 3624562026-10-01 09:40:23.730 UTC [53227] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2457--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.11s)2458=== CONT TestCreatePendingClosureRejectsOversizedNAR24592026/10/01 09:40:23 INFO Received uploads request method=POST path=/api/pending_closures2460--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2461=== CONT TestReadRedirectUsesPublicS3URL24622026-10-01 09:40:23.828 UTC [53231] ERROR: relation "goose_db_version" does not exist at character 3624632026-10-01 09:40:23.828 UTC [53231] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24642026/10/01 09:40:23 OK 20241026095416_initial_model.sql (157.19ms)24652026/10/01 09:40:23 OK 20241026095416_initial_model.sql (141.86ms)24662026/10/01 09:40:23 OK 20251210153512_drop_unused_gin_index.sql (8.12ms)24672026/10/01 09:40:23 OK 20251210153512_drop_unused_gin_index.sql (16.2ms)24682026/10/01 09:40:23 OK 20251218171726_add_pins.sql (34.32ms)24692026/10/01 09:40:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"24702026/10/01 09:40:24 WARN mTLS auth: bound subjects configured but subject DN unavailable24712026/10/01 09:40:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2472--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.21s)2473=== CONT TestPush_OverlappingRootsStoreOneRowPerKey24742026/10/01 09:40:24 OK 20251218171726_add_pins.sql (35.26ms)24752026/10/01 09:40:24 OK 20260628120000_add_object_size_and_stats.sql (29.81ms)24762026/10/01 09:40:24 OK 20260628120000_add_object_size_and_stats.sql (28.52ms)24772026/10/01 09:40:24 OK 20241026095416_initial_model.sql (174.65ms)24782026/10/01 09:40:24 OK 20251210153512_drop_unused_gin_index.sql (37.59ms)24792026/10/01 09:40:24 OK 20260905000000_add_claims.sql (53.36ms)24802026/10/01 09:40:24 OK 20260905000000_add_claims.sql (69.57ms)24812026/10/01 09:40:24 OK 20251218171726_add_pins.sql (36.08ms)24822026/10/01 09:40:24 OK 20260920000000_drop_claims.sql (32.33ms)24832026/10/01 09:40:24 OK 20260920000000_drop_claims.sql (32.61ms)24842026/10/01 09:40:24 OK 20260923120000_add_pushes.sql (22.22ms)24852026/10/01 09:40:24 goose: successfully migrated database to version: 2026092312000024862026/10/01 09:40:24 OK 20260923120000_add_pushes.sql (22.39ms)24872026/10/01 09:40:24 goose: successfully migrated database to version: 2026092312000024882026/10/01 09:40:24 OK 20260628120000_add_object_size_and_stats.sql (29.26ms)24892026/10/01 09:40:24 OK 1_commit_pending_closure.sql (1.54ms)24902026/10/01 09:40:24 OK 1_commit_pending_closure.sql (1.44ms)24912026/10/01 09:40:24 OK 2_object_stats_trigger.sql (245.54µs)24922026/10/01 09:40:24 OK 2_object_stats_trigger.sql (420.75µs)24932026/10/01 09:40:24 OK 3_commit_push.sql (500.83µs)24942026/10/01 09:40:24 goose: up to current file version: 324952026/10/01 09:40:24 OK 3_commit_push.sql (357.08µs)24962026/10/01 09:40:24 goose: up to current file version: 324972026/10/01 09:40:24 OK 20260905000000_add_claims.sql (59.29ms)24982026/10/01 09:40:24 OK 20260920000000_drop_claims.sql (38.9ms)24992026/10/01 09:40:24 OK 20260923120000_add_pushes.sql (20.79ms)25002026/10/01 09:40:24 goose: successfully migrated database to version: 2026092312000025012026/10/01 09:40:24 OK 1_commit_pending_closure.sql (1.78ms)25022026/10/01 09:40:24 OK 2_object_stats_trigger.sql (300.71µs)25032026/10/01 09:40:24 OK 3_commit_push.sql (227.5µs)25042026/10/01 09:40:24 goose: up to current file version: 32505--- PASS: TestService_ReadAuthMiddleware (2.48s)2506=== CONT TestReadProxyRangeRequest2507--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.97s)2508=== CONT TestClientWithDependencies25092026-10-01 09:40:24.985 UTC [53291] ERROR: relation "goose_db_version" does not exist at character 3625102026-10-01 09:40:24.985 UTC [53291] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25112026/10/01 09:40:25 INFO Starting HTTP server address=/nix/var/nix/builds/nix-51549-3085653128/TestProxyHeadersOnlyTrustedOnSocket1925265566/001/proxy.sock25122026/10/01 09:40:25 INFO Starting HTTP server address=127.0.0.1:5001725132026/10/01 09:40:25 WARN mTLS auth: subject not in bound subjects subject="CN=someone"25142026/10/01 09:40:25 INFO Shutdown signal received, draining in-flight requests timeout=10s2515--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.45s)2516=== CONT TestParseSingleRange/none2517=== CONT TestParseSingleRange/malformed_both_empty2518=== CONT TestParseSingleRange/closed2519=== CONT TestParseSingleRange/malformed_end_before_start2520=== CONT TestParseSingleRange/multi-range_ignored2521=== CONT TestParseSingleRange/malformed_no_dash2522=== CONT TestParseSingleRange/single_byte2523=== CONT TestParseSingleRange/start_far_past_EOF2524=== CONT TestParseSingleRange/start_past_EOF2525=== CONT TestParseSingleRange/unknown_unit2526=== CONT TestParseSingleRange/suffix2527=== CONT TestParseSingleRange/end_clamped_to_size2528=== CONT TestParseSingleRange/suffix_exceeds_size2529=== CONT TestParseSingleRange/open-ended2530--- PASS: TestParseSingleRange (0.00s)2531 --- PASS: TestParseSingleRange/none (0.00s)2532 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2533 --- PASS: TestParseSingleRange/closed (0.00s)2534 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2535 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2536 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2537 --- PASS: TestParseSingleRange/single_byte (0.00s)2538 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2539 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2540 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2541 --- PASS: TestParseSingleRange/suffix (0.00s)2542 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2543 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2544 --- PASS: TestParseSingleRange/open-ended (0.00s)2545=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows25462026/10/01 09:40:25 OK 20241026095416_initial_model.sql (399.79ms)25472026/10/01 09:40:25 OK 20251210153512_drop_unused_gin_index.sql (19.58ms)25482026/10/01 09:40:25 WARN mTLS auth: subject not in bound subjects subject="CN=reader"25492026/10/01 09:40:25 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2550--- PASS: TestService_NativeMTLS (2.77s)2551=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check25522026/10/01 09:40:25 OK 20251218171726_add_pins.sql (71.49ms)25532026/10/01 09:40:25 OK 20260628120000_add_object_size_and_stats.sql (48.01ms)25542026/10/01 09:40:25 OK 20260905000000_add_claims.sql (55.21ms)25552026/10/01 09:40:25 OK 20260920000000_drop_claims.sql (30.64ms)25562026/10/01 09:40:25 OK 20260923120000_add_pushes.sql (67.57ms)25572026/10/01 09:40:25 goose: successfully migrated database to version: 2026092312000025582026/10/01 09:40:25 OK 1_commit_pending_closure.sql (4.61ms)25592026/10/01 09:40:25 OK 2_object_stats_trigger.sql (938.08µs)25602026/10/01 09:40:25 OK 3_commit_push.sql (868.46µs)25612026/10/01 09:40:25 goose: up to current file version: 325622026-10-01 09:40:26.143 UTC [53296] ERROR: relation "goose_db_version" does not exist at character 3625632026-10-01 09:40:26.143 UTC [53296] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25642026/10/01 09:40:26 INFO Received uploads request method=POST path=/api/pending_closures25652026/10/01 09:40:26 INFO Received cleanup request method=DELETE path=/api/pending_closures25662026/10/01 09:40:26 OK 20241026095416_initial_model.sql (301.17ms)25672026/10/01 09:40:26 INFO Aborted multipart uploads count=125682026/10/01 09:40:26 OK 20251210153512_drop_unused_gin_index.sql (9.67ms)2569--- PASS: TestMultipartCleanup (3.52s)2570=== CONT TestCacheConfigHandler/full_config,_no_issuer2571=== CONT TestCacheConfigHandler/no_signing_keys2572=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2573=== CONT TestCacheConfigHandler/no_cache_url_configured2574--- PASS: TestCacheConfigHandler (0.00s)2575 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2576 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2577 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2578 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2579=== CONT TestClientErrorHandling/InvalidStorePath25802026/10/01 09:40:26 OK 20251218171726_add_pins.sql (37.26ms)25812026-10-01 09:40:26.596 UTC [53297] ERROR: relation "goose_db_version" does not exist at character 3625822026-10-01 09:40:26.596 UTC [53297] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25832026/10/01 09:40:26 OK 20260628120000_add_object_size_and_stats.sql (52.1ms)25842026/10/01 09:40:26 OK 20260905000000_add_claims.sql (69.72ms)25852026/10/01 09:40:26 OK 20260920000000_drop_claims.sql (51.61ms)25862026/10/01 09:40:26 OK 20260923120000_add_pushes.sql (20.68ms)25872026/10/01 09:40:26 goose: successfully migrated database to version: 2026092312000025882026/10/01 09:40:26 OK 1_commit_pending_closure.sql (4.5ms)25892026/10/01 09:40:26 OK 2_object_stats_trigger.sql (2.96ms)25902026/10/01 09:40:26 OK 3_commit_push.sql (819.88µs)25912026/10/01 09:40:26 goose: up to current file version: 325922026/10/01 09:40:26 OK 20241026095416_initial_model.sql (243.28ms)25932026/10/01 09:40:26 OK 20251210153512_drop_unused_gin_index.sql (18.67ms)25942026/10/01 09:40:26 OK 20251218171726_add_pins.sql (53.16ms)25952026/10/01 09:40:27 OK 20260628120000_add_object_size_and_stats.sql (87.36ms)25962026/10/01 09:40:27 OK 20260905000000_add_claims.sql (107.15ms)25972026-10-01 09:40:27.195 UTC [53300] ERROR: relation "goose_db_version" does not exist at character 3625982026-10-01 09:40:27.195 UTC [53300] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25992026/10/01 09:40:27 OK 20260920000000_drop_claims.sql (88.52ms)26002026/10/01 09:40:27 OK 20260923120000_add_pushes.sql (10.79ms)26012026/10/01 09:40:27 goose: successfully migrated database to version: 2026092312000026022026/10/01 09:40:27 OK 1_commit_pending_closure.sql (4.99ms)26032026/10/01 09:40:27 OK 2_object_stats_trigger.sql (837.83µs)26042026/10/01 09:40:27 OK 3_commit_push.sql (577.25µs)26052026/10/01 09:40:27 goose: up to current file version: 326062026/10/01 09:40:27 OK 20241026095416_initial_model.sql (281.71ms)26072026/10/01 09:40:27 OK 20251210153512_drop_unused_gin_index.sql (15.72ms)26082026/10/01 09:40:27 OK 20251218171726_add_pins.sql (49.66ms)26092026-10-01 09:40:27.644 UTC [53303] ERROR: relation "goose_db_version" does not exist at character 3626102026-10-01 09:40:27.644 UTC [53303] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2611=== NAME TestNARDeduplicationMetadataUploadBug2612 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-51549-3085653128/TestNARDeduplicationMetadataUploadBug3516475291/001/store/qdvpk37gs8pmw1dyjzp7yz5pyychch97-file1.txt26132026/10/01 09:40:27 OK 20260628120000_add_object_size_and_stats.sql (52.96ms)2614=== CONT TestClientErrorHandling/ServerNotAvailable2615--- PASS: TestMetricsInventory (4.28s)26162026/10/01 09:40:27 OK 20260905000000_add_claims.sql (61.14ms)26172026-10-01 09:40:27.782 UTC [53305] ERROR: relation "goose_db_version" does not exist at character 3626182026-10-01 09:40:27.782 UTC [53305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26192026/10/01 09:40:27 OK 20260920000000_drop_claims.sql (30.52ms)26202026/10/01 09:40:27 OK 20260923120000_add_pushes.sql (5.88ms)26212026/10/01 09:40:27 goose: successfully migrated database to version: 2026092312000026222026/10/01 09:40:27 OK 1_commit_pending_closure.sql (873.63µs)26232026/10/01 09:40:27 OK 2_object_stats_trigger.sql (231.75µs)26242026/10/01 09:40:27 OK 3_commit_push.sql (207.25µs)26252026/10/01 09:40:27 goose: up to current file version: 326262026/10/01 09:40:27 INFO Received push request method=POST path=/api/pushes26272026/10/01 09:40:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26282026/10/01 09:40:27 INFO Uploading qdvpk37gs8pmw1dyjzp7yz5pyychch97-file1.txt (160B)26292026/10/01 09:40:27 WARN Failed to register uploaded object key=qdvpk37gs8pmw1dyjzp7yz5pyychch97.ls error="server returned 404: 404 page not found\n"26302026/10/01 09:40:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26312026/10/01 09:40:27 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"26322026/10/01 09:40:27 INFO Signed narinfos id=1 count=126332026/10/01 09:40:27 INFO Uploading 1 narinfos26342026/10/01 09:40:27 INFO Received complete push request method=POST path=/api/pushes/1/complete26352026/10/01 09:40:27 WARN Failed to register uploaded object key=qdvpk37gs8pmw1dyjzp7yz5pyychch97.narinfo error="server returned 404: 404 page not found\n"26362026/10/01 09:40:28 INFO Upload complete. (303ms)2637=== NAME TestNARDeduplicationMetadataUploadBug2638 metadata_upload_test.go:54: Retrieved narinfo from S3:2639 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestNARDeduplicationMetadataUploadBug3516475291/001/store/qdvpk37gs8pmw1dyjzp7yz5pyychch97-file1.txt2640 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2641 Compression: zstd2642 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2643 NarSize: 1602644 References: 2645 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2646 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2647 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2648 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}26492026/10/01 09:40:28 OK 20241026095416_initial_model.sql (339.99ms)26502026/10/01 09:40:28 OK 20251210153512_drop_unused_gin_index.sql (17.08ms)26512026/10/01 09:40:28 OK 20251218171726_add_pins.sql (36.22ms)26522026/10/01 09:40:28 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/present26532026/10/01 09:40:28 OK 20241026095416_initial_model.sql (302.7ms)26542026/10/01 09:40:28 OK 20260628120000_add_object_size_and_stats.sql (44.9ms)26552026/10/01 09:40:28 OK 20251210153512_drop_unused_gin_index.sql (15.03ms)2656--- PASS: TestReadRedirectUsesPublicS3URL (4.46s)2657=== CONT TestClientErrorHandling/InvalidAuthToken26582026/10/01 09:40:28 OK 20251218171726_add_pins.sql (37.34ms)26592026-10-01 09:40:28.209 UTC [53311] ERROR: relation "goose_db_version" does not exist at character 3626602026-10-01 09:40:28.209 UTC [53311] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2661=== NAME TestNARDeduplicationMetadataUploadBug2662 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-51549-3085653128/TestNARDeduplicationMetadataUploadBug3516475291/001/store/sb93ix2597hw6yqdk9vx0pv5ryfa8znr-file2.txt26632026/10/01 09:40:28 OK 20260905000000_add_claims.sql (53.98ms)26642026/10/01 09:40:28 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=182.987495ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26652026/10/01 09:40:28 OK 20260628120000_add_object_size_and_stats.sql (22.39ms)26662026/10/01 09:40:28 OK 20260920000000_drop_claims.sql (27.95ms)26672026/10/01 09:40:28 OK 20260923120000_add_pushes.sql (16.26ms)26682026/10/01 09:40:28 goose: successfully migrated database to version: 2026092312000026692026/10/01 09:40:28 OK 1_commit_pending_closure.sql (997.21µs)26702026/10/01 09:40:28 OK 2_object_stats_trigger.sql (242.5µs)26712026/10/01 09:40:28 OK 3_commit_push.sql (182.63µs)26722026/10/01 09:40:28 goose: up to current file version: 326732026/10/01 09:40:28 OK 20260905000000_add_claims.sql (57.09ms)26742026/10/01 09:40:28 INFO Received push request method=POST path=/api/pushes26752026/10/01 09:40:28 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)26762026/10/01 09:40:28 OK 20260920000000_drop_claims.sql (52.16ms)26772026/10/01 09:40:28 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign26782026/10/01 09:40:28 INFO Signed narinfos id=2 count=126792026/10/01 09:40:28 INFO Uploading 1 narinfos26802026/10/01 09:40:28 WARN Failed to register uploaded object key=sb93ix2597hw6yqdk9vx0pv5ryfa8znr.ls error="server returned 404: 404 page not found\n"26812026/10/01 09:40:28 OK 20260923120000_add_pushes.sql (9.86ms)26822026/10/01 09:40:28 goose: successfully migrated database to version: 2026092312000026832026/10/01 09:40:28 OK 1_commit_pending_closure.sql (958.46µs)26842026/10/01 09:40:28 OK 2_object_stats_trigger.sql (205.92µs)26852026/10/01 09:40:28 OK 3_commit_push.sql (171.88µs)26862026/10/01 09:40:28 goose: up to current file version: 326872026/10/01 09:40:28 INFO Received complete push request method=POST path=/api/pushes/2/complete26882026/10/01 09:40:28 WARN Failed to register uploaded object key=sb93ix2597hw6yqdk9vx0pv5ryfa8znr.narinfo error="server returned 404: 404 page not found\n"26892026/10/01 09:40:28 INFO Upload complete. (135ms)2690 metadata_upload_test.go:76: Retrieved narinfo from S3:2691 StorePath: /nix/var/nix/builds/nix-51549-3085653128/TestNARDeduplicationMetadataUploadBug3516475291/001/store/sb93ix2597hw6yqdk9vx0pv5ryfa8znr-file2.txt2692 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2693 Compression: zstd2694 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2695 NarSize: 1602696 References: 2697 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2698 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2699 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2700 {"version":1,"root":{"type":"regular","size":44}}27012026/10/01 09:40:28 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=422.223187ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27022026-10-01 09:40:28.461 UTC [53324] ERROR: relation "goose_db_version" does not exist at character 3627032026-10-01 09:40:28.461 UTC [53324] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27042026/10/01 09:40:28 OK 20241026095416_initial_model.sql (232.74ms)27052026/10/01 09:40:28 OK 20251210153512_drop_unused_gin_index.sql (18.83ms)2706--- PASS: TestNARDeduplicationMetadataUploadBug (5.29s)2707=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts27082026/10/01 09:40:28 INFO Received request for more parts method=POST path=/27092026/10/01 09:40:28 OK 20251218171726_add_pins.sql (30.4ms)2710=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart27112026/10/01 09:40:28 INFO Received complete multipart upload request method=POST path=/2712=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure27132026/10/01 09:40:28 INFO Received uploads request method=POST path=/27142026/10/01 09:40:28 OK 20260628120000_add_object_size_and_stats.sql (52.57ms)27152026/10/01 09:40:28 INFO Received push request method=POST path=/api/pushes27162026/10/01 09:40:28 OK 20260905000000_add_claims.sql (75.75ms)2717--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.70s)2718=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info27192026/10/01 09:40:28 INFO Received uploads request method=POST path=/2720=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key27212026/10/01 09:40:28 INFO Received request for more parts method=POST path=/2722=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key27232026/10/01 09:40:28 INFO Received complete multipart upload request method=POST path=/2724=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal27252026/10/01 09:40:28 INFO Received uploads request method=POST path=/2726--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2727 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2728 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2729 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2730 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2731=== CONT TestIsValidUploadKey/narinfo2732=== CONT TestIsValidUploadKey/realisation_plus_in_output2733=== CONT TestIsValidUploadKey/unknown_type2734=== CONT TestIsValidUploadKey/empty_key2735=== CONT TestIsValidUploadKey/absolute2736=== CONT TestIsValidUploadKey/traversal_nar2737=== CONT TestIsValidUploadKey/traversal2738=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2739=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2740=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2741=== CONT TestIsValidUploadKey/index.html2742=== CONT TestIsValidUploadKey/nix-cache-info2743=== CONT TestIsValidUploadKey/build_log_home-manager_file2744=== CONT TestIsValidUploadKey/realisation2745=== CONT TestIsValidUploadKey/build_log_equals2746=== CONT TestIsValidUploadKey/build_log_question_mark2747=== CONT TestIsValidUploadKey/build_log_plus_in_name2748=== CONT TestIsValidUploadKey/nar_plain2749=== CONT TestIsValidUploadKey/build_log2750=== CONT TestIsValidUploadKey/listing2751=== CONT TestIsValidUploadKey/nar_xz2752=== CONT TestIsValidUploadKey/nar_zst2753--- PASS: TestIsValidUploadKey (0.00s)2754 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2755 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2756 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2757 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2758 --- PASS: TestIsValidUploadKey/absolute (0.00s)2759 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2760 --- PASS: TestIsValidUploadKey/traversal (0.00s)2761 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2762 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2763 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2764 --- PASS: TestIsValidUploadKey/index.html (0.00s)2765 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2766 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2767 --- PASS: TestIsValidUploadKey/realisation (0.00s)2768 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2769 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2770 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2771 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2772 --- PASS: TestIsValidUploadKey/build_log (0.00s)2773 --- PASS: TestIsValidUploadKey/listing (0.00s)2774 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2775 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2776=== CONT TestProxyWriteTimeout/narinfo2777=== CONT TestProxyWriteTimeout/unknown_size2778=== CONT TestProxyWriteTimeout/10_GiB_nar2779=== CONT TestProxyWriteTimeout/1_GiB_nar2780--- PASS: TestProxyWriteTimeout (0.00s)2781 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2782 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2783 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2784 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2785=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2786=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected27872026/10/01 09:40:28 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]2788=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2789=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected27902026/10/01 09:40:28 WARN Authentication failed token_preview=eyJhbGciOi...PYQt5YNfzQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2791=== CONT TestResolveDBConnectionString/flag_wins2792=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2793=== CONT TestResolveDBConnectionString/nothing_configured2794=== CONT TestResolveDBConnectionString/missing_file_is_an_error2795=== CONT TestResolveDBConnectionString/file_when_flag_empty2796=== CONT TestService_RequireScope_OIDC/builder_may_write2797=== CONT TestService_RequireScope_OIDC/static_token_may_admin2798=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2799=== CONT TestService_RequireScope_OIDC/writer_implies_read2800=== CONT TestService_RequireScope_OIDC/reader_may_read2801=== CONT TestService_RequireScope_OIDC/static_token_may_write2802=== CONT TestService_RequireScope_OIDC/ops_may_not_write2803=== CONT TestService_RequireScope_OIDC/reader_may_not_write2804=== CONT TestService_RequireScope_OIDC/ops_may_admin2805=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2806=== CONT TestPush_RejectsBadRequests/no_roots28072026/10/01 09:40:28 INFO Received push request method=POST path=/api/pushes2808=== CONT TestPush_RejectsBadRequests/bad_root28092026/10/01 09:40:28 INFO Received push request method=POST path=/api/pushes2810=== CONT TestPush_RejectsBadRequests/root_not_in_objects28112026/10/01 09:40:28 INFO Received push request method=POST path=/api/pushes2812=== CONT TestPush_RejectsBadRequests/no_objects28132026/10/01 09:40:28 INFO Received push request method=POST path=/api/pushes2814=== CONT TestIsValidCachePath/narinfo2815=== CONT TestIsValidCachePath/index.html2816=== CONT TestIsValidCachePath/short_hash2817--- PASS: TestPush_RejectsBadRequests (2.20s)2818 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2819 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2820 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2821 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2822=== CONT TestIsValidCachePath/wrong_extension2823=== CONT TestIsValidCachePath/leading_slash2824=== CONT TestIsValidCachePath/empty2825=== CONT TestIsValidCachePath/random_path2826=== CONT TestIsValidCachePath/invalid_char_u2827=== CONT TestIsValidCachePath/invalid_char_e2828=== CONT TestIsValidCachePath/traversal_in_middle2829=== CONT TestIsValidCachePath/traversal_parent2830=== CONT TestIsValidCachePath/nar_uncompressed2831=== CONT TestIsValidCachePath/nix-cache-info2832=== CONT TestIsValidCachePath/realisation2833=== CONT TestIsValidCachePath/log2834=== CONT TestIsValidCachePath/ls2835=== CONT TestIsValidCachePath/nar_xz2836=== CONT TestIsValidCachePath/nar_bz22837=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2838=== CONT TestIsValidCachePath/nar_zst2839--- PASS: TestIsValidCachePath (0.00s)2840 --- PASS: TestIsValidCachePath/narinfo (0.00s)2841 --- PASS: TestIsValidCachePath/index.html (0.00s)2842 --- PASS: TestIsValidCachePath/short_hash (0.00s)2843 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2844 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2845 --- PASS: TestIsValidCachePath/empty (0.00s)2846 --- PASS: TestIsValidCachePath/random_path (0.00s)2847 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2848 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2849 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2850 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2851 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2852 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2853 --- PASS: TestIsValidCachePath/realisation (0.00s)2854 --- PASS: TestIsValidCachePath/log (0.00s)2855 --- PASS: TestIsValidCachePath/ls (0.00s)2856 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2857 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2858 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2859 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2860=== CONT TestServerTLSConfig/no_client_CA2861=== CONT TestServerTLSConfig/missing_CA_file2862=== CONT TestServerTLSConfig/not_a_PEM_file2863--- PASS: TestResolveDBConnectionString (0.01s)2864 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2865 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2866 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2867 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2868 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2869--- PASS: TestService_AuthMiddleware_OIDC (2.42s)2870 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2871 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2872 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2873 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2874--- PASS: TestService_RequireScope_OIDC (2.64s)2875 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2876 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2877 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2878 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2879 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2880 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2881 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2882 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2883 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2884 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)28852026/10/01 09:40:28 OK 20260920000000_drop_claims.sql (66.61ms)2886--- PASS: TestServerTLSConfig (0.00s)2887 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2888 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2889 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)28902026/10/01 09:40:28 OK 20260923120000_add_pushes.sql (28.46ms)28912026/10/01 09:40:28 goose: successfully migrated database to version: 2026092312000028922026/10/01 09:40:28 OK 1_commit_pending_closure.sql (950.17µs)28932026/10/01 09:40:28 OK 2_object_stats_trigger.sql (229.29µs)28942026/10/01 09:40:28 OK 3_commit_push.sql (165.33µs)28952026/10/01 09:40:28 goose: up to current file version: 328962026-10-01 09:40:28.813 UTC [53326] ERROR: relation "goose_db_version" does not exist at character 3628972026-10-01 09:40:28.813 UTC [53326] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28982026/10/01 09:40:28 OK 20241026095416_initial_model.sql (285.27ms)2899--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2900 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2901 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2902 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)29032026/10/01 09:40:28 OK 20251210153512_drop_unused_gin_index.sql (7.6ms)29042026/10/01 09:40:28 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=801.59743ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29052026/10/01 09:40:28 OK 20251218171726_add_pins.sql (35.57ms)29062026/10/01 09:40:28 OK 20260628120000_add_object_size_and_stats.sql (67.88ms)29072026/10/01 09:40:29 OK 20260905000000_add_claims.sql (80.54ms)2908--- PASS: TestReadProxyRangeRequest (4.73s)2909=== NAME TestOrphanedObjectsGCStressTest2910 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains29112026/10/01 09:40:29 OK 20260920000000_drop_claims.sql (54.9ms)29122026/10/01 09:40:29 OK 20260923120000_add_pushes.sql (27.46ms)29132026/10/01 09:40:29 goose: successfully migrated database to version: 2026092312000029142026/10/01 09:40:29 OK 1_commit_pending_closure.sql (3.27ms)29152026/10/01 09:40:29 OK 2_object_stats_trigger.sql (646.67µs)29162026/10/01 09:40:29 OK 3_commit_push.sql (418.79µs)29172026/10/01 09:40:29 goose: up to current file version: 32918 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion29192026/10/01 09:40:29 OK 20241026095416_initial_model.sql (249.89ms)29202026/10/01 09:40:29 OK 20251210153512_drop_unused_gin_index.sql (15.75ms)29212026/10/01 09:40:29 OK 20251218171726_add_pins.sql (20.06ms)29222026/10/01 09:40:29 OK 20260628120000_add_object_size_and_stats.sql (50.99ms)29232026/10/01 09:40:29 OK 20260905000000_add_claims.sql (71.58ms)29242026/10/01 09:40:29 OK 20260920000000_drop_claims.sql (27.77ms)29252026/10/01 09:40:29 OK 20260923120000_add_pushes.sql (31.3ms)29262026/10/01 09:40:29 goose: successfully migrated database to version: 2026092312000029272026/10/01 09:40:29 OK 1_commit_pending_closure.sql (5.26ms)29282026/10/01 09:40:29 OK 2_object_stats_trigger.sql (807.46µs)29292026/10/01 09:40:29 OK 3_commit_push.sql (602.83µs)29302026/10/01 09:40:29 goose: up to current file version: 329312026-10-01 09:40:29.491 UTC [53329] ERROR: relation "goose_db_version" does not exist at character 3629322026-10-01 09:40:29.491 UTC [53329] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29332026/10/01 09:40:29 INFO Received uploads request method=POST path=/api/pending_closures29342026/10/01 09:40:29 INFO Aborted multipart uploads count=029352026/10/01 09:40:29 WARN Force mode enabled - objects will be deleted immediately without grace period29362026/10/01 09:40:29 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.479062529s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29372026/10/01 09:40:29 OK 20241026095416_initial_model.sql (107.77ms)29382026/10/01 09:40:29 OK 20251210153512_drop_unused_gin_index.sql (13.09ms)29392026/10/01 09:40:29 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=029402026/10/01 09:40:29 INFO Vacuumed table table=pending_closures29412026/10/01 09:40:29 INFO Vacuumed table table=pending_objects29422026/10/01 09:40:29 INFO Vacuumed table table=multipart_uploads29432026/10/01 09:40:29 INFO Vacuumed table table=closures29442026/10/01 09:40:29 OK 20251218171726_add_pins.sql (30.99ms)29452026/10/01 09:40:29 INFO Vacuumed table table=objects29462026/10/01 09:40:29 OK 20260628120000_add_object_size_and_stats.sql (19.39ms)29472026/10/01 09:40:29 OK 20260905000000_add_claims.sql (42.21ms)2948=== NAME TestClientWithDependencies2949 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-51549-3085653128/TestClientWithDependencies2729884084/001/store/k0rm76s3c1q1gvrjfp5dpzdfcimvd6hc-test-script29502026/10/01 09:40:29 OK 20260920000000_drop_claims.sql (38.94ms)29512026/10/01 09:40:29 OK 20260923120000_add_pushes.sql (20.42ms)29522026/10/01 09:40:29 goose: successfully migrated database to version: 2026092312000029532026/10/01 09:40:29 OK 1_commit_pending_closure.sql (1.04ms)29542026/10/01 09:40:29 OK 2_object_stats_trigger.sql (237.13µs)29552026/10/01 09:40:29 OK 3_commit_push.sql (165.58µs)29562026/10/01 09:40:29 goose: up to current file version: 32957 client_integration_test.go:615: Found 1 dependencies (including self)29582026/10/01 09:40:29 INFO Received uploads request method=POST path=/api/pending_closures29592026/10/01 09:40:29 INFO Aborted multipart uploads count=029602026/10/01 09:40:29 WARN Force mode enabled - objects will be deleted immediately without grace period29612026/10/01 09:40:29 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=029622026/10/01 09:40:29 INFO Vacuumed table table=pending_closures29632026/10/01 09:40:29 INFO Received push request method=POST path=/api/pushes29642026/10/01 09:40:29 INFO Vacuumed table table=pending_objects29652026/10/01 09:40:29 INFO Vacuumed table table=multipart_uploads29662026/10/01 09:40:29 INFO Vacuumed table table=closures29672026/10/01 09:40:29 INFO Vacuumed table table=objects29682026/10/01 09:40:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)29692026/10/01 09:40:29 INFO Uploading k0rm76s3c1q1gvrjfp5dpzdfcimvd6hc-test-script (136B)29702026/10/01 09:40:29 WARN Failed to register uploaded object key=k0rm76s3c1q1gvrjfp5dpzdfcimvd6hc.ls error="server returned 404: 404 page not found\n"29712026/10/01 09:40:29 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"29722026/10/01 09:40:29 WARN Failed to register uploaded object key=log/5kzc79y8z90k6bz50jbllr78pc3q7sy7-test-script.drv error="server returned 404: 404 page not found\n"29732026/10/01 09:40:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29742026/10/01 09:40:29 INFO Signed narinfos id=1 count=129752026/10/01 09:40:29 INFO Uploading 1 narinfos2976--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2977 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (4.65s)2978 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (4.44s)29792026/10/01 09:40:30 INFO Received complete push request method=POST path=/api/pushes/1/complete29802026/10/01 09:40:30 WARN Failed to register uploaded object key=k0rm76s3c1q1gvrjfp5dpzdfcimvd6hc.narinfo error="server returned 404: 404 page not found\n"29812026/10/01 09:40:30 INFO Upload complete. (150ms)2982=== NAME TestClientWithDependencies2983 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-51549-3085653128/TestClientWithDependencies2729884084/001/store) requires matching store prefix2984--- PASS: TestClientWithDependencies (5.44s)29852026-10-01 09:40:30.203 UTC [53344] ERROR: relation "goose_db_version" does not exist at character 3629862026-10-01 09:40:30.203 UTC [53344] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29872026/10/01 09:40:30 OK 20241026095416_initial_model.sql (4.62ms)29882026/10/01 09:40:30 OK 20251210153512_drop_unused_gin_index.sql (472.96µs)29892026/10/01 09:40:30 OK 20251218171726_add_pins.sql (864.13µs)29902026/10/01 09:40:30 OK 20260628120000_add_object_size_and_stats.sql (1.07ms)29912026/10/01 09:40:30 OK 20260905000000_add_claims.sql (1.35ms)29922026/10/01 09:40:30 OK 20260920000000_drop_claims.sql (1.01ms)29932026/10/01 09:40:30 OK 20260923120000_add_pushes.sql (818.08µs)29942026/10/01 09:40:30 goose: successfully migrated database to version: 2026092312000029952026/10/01 09:40:30 OK 1_commit_pending_closure.sql (1.03ms)29962026/10/01 09:40:30 OK 2_object_stats_trigger.sql (276.54µs)29972026/10/01 09:40:30 OK 3_commit_push.sql (250.71µs)29982026/10/01 09:40:30 goose: up to current file version: 329992026/10/01 09:40:30 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30002026/10/01 09:40:30 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"3001=== NAME TestOrphanedObjectsGCStressTest3002 orphaned_objects_gc_test.go:509: Stress test completed successfully:3003 orphaned_objects_gc_test.go:510: - Active objects preserved: 203004 orphaned_objects_gc_test.go:511: - Objects deleted: 2103005 orphaned_objects_gc_test.go:512: - Total GC'd: 2103006--- PASS: TestOrphanedObjectsGCStressTest (11.06s)30072026/10/01 09:40:31 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-config30082026/10/01 09:40:31 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.577005ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30092026/10/01 09:40:31 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=398.859244ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30102026/10/01 09:40:31 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=845.885898ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30112026/10/01 09:40:32 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.660505069s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30122026/10/01 09:40:34 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"30132026/10/01 09:40:34 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-config30142026/10/01 09:40:34 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=212.873835ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30152026/10/01 09:40:34 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=435.612856ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30162026/10/01 09:40:35 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=877.057748ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30172026/10/01 09:40:36 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.64625231s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30182026/10/01 09:40:37 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_closures30192026/10/01 09:40:37 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.001376ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30202026/10/01 09:40:38 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=362.344937ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30212026/10/01 09:40:38 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=749.680818ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30222026/10/01 09:40:39 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.743501929s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3023--- PASS: TestClientErrorHandling (0.00s)3024 --- PASS: TestClientErrorHandling/InvalidStorePath (3.64s)3025 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.53s)3026 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.28s)3027PASS3028{"timestamp":"2026-10-01T09:40:41.013818Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49739","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}30292026-10-01 09:40:45.957 UTC [52392] LOG: received smart shutdown request30302026-10-01 09:40:45.966 UTC [52392] LOG: background worker "logical replication launcher" (PID 52404) exited with exit code 130312026-10-01 09:40:46.036 UTC [52399] LOG: shutting down30322026-10-01 09:40:46.042 UTC [52399] LOG: checkpoint starting: shutdown immediate30332026/10/01 09:40:51 ERROR failed to kill rustfs error="no such process"30342026/10/01 09:40:55 INFO killed rustfs30352026/10/01 09:40:55 ERROR failed to wait for rustfs error="signal: killed"30362026-10-01 09:40:56.273 UTC [52399] PANIC: could not fsync file "base/22530/23165": No such file or directory3037Running OIDC tests...3038=== RUN TestAudienceForIssuer3039=== PAUSE TestAudienceForIssuer3040=== RUN TestGlobMatch3041=== PAUSE TestGlobMatch3042=== RUN TestValidateToken_ValidToken3043=== PAUSE TestValidateToken_ValidToken3044=== RUN TestValidateToken_WrongAudience3045=== PAUSE TestValidateToken_WrongAudience3046=== RUN TestValidateToken_Expired3047=== PAUSE TestValidateToken_Expired3048=== RUN TestValidateToken_BoundClaimsMismatch3049=== PAUSE TestValidateToken_BoundClaimsMismatch3050=== RUN TestValidateToken_BoundSubjectMismatch3051=== PAUSE TestValidateToken_BoundSubjectMismatch3052=== RUN TestValidateToken_MultipleProviders3053=== PAUSE TestValidateToken_MultipleProviders3054=== RUN TestValidateToken_NoMatchingProvider3055=== PAUSE TestValidateToken_NoMatchingProvider3056=== RUN TestValidateToken_KubernetesServiceAccount3057=== PAUSE TestValidateToken_KubernetesServiceAccount3058=== RUN TestNewValidator_KubernetesRequiresCA3059=== PAUSE TestNewValidator_KubernetesRequiresCA3060=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3061=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3062=== RUN TestPins_ReservedForMatchingRule3063=== PAUSE TestPins_ReservedForMatchingRule3064=== RUN TestPins_TopLevelShorthand3065=== PAUSE TestPins_TopLevelShorthand3066=== RUN TestPins_ConfigValidation3067=== PAUSE TestPins_ConfigValidation3068=== RUN TestScopes_LegacyProviderDefaultsToWrite3069=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3070=== RUN TestScopes_Rules3071=== PAUSE TestScopes_Rules3072=== RUN TestScopes_ConfigValidation3073=== PAUSE TestScopes_ConfigValidation3074=== CONT TestAudienceForIssuer3075--- PASS: TestAudienceForIssuer (0.00s)3076=== CONT TestValidateToken_NoMatchingProvider3077=== CONT TestPins_ConfigValidation3078=== CONT TestValidateToken_KubernetesServiceAccount3079=== CONT TestPins_ReservedForMatchingRule3080=== CONT TestScopes_ConfigValidation3081=== CONT TestValidateToken_Expired3082=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3083=== CONT TestValidateToken_BoundSubjectMismatch3084=== CONT TestValidateToken_MultipleProviders3085=== CONT TestValidateToken_ValidToken3086--- PASS: TestScopes_ConfigValidation (0.01s)3087=== CONT TestValidateToken_WrongAudience3088--- PASS: TestPins_ConfigValidation (0.01s)3089=== CONT TestValidateToken_BoundClaimsMismatch30902026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50628/oidc3091--- PASS: TestValidateToken_Expired (0.03s)3092=== CONT TestNewValidator_KubernetesRequiresCA30932026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50630/oidc3094--- PASS: TestValidateToken_ValidToken (0.04s)3095=== CONT TestPins_TopLevelShorthand30962026/10/01 09:41:07 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12330972026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50632/oidc3098--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)3099=== CONT TestScopes_Rules3100--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.06s)3101=== CONT TestGlobMatch3102=== RUN TestGlobMatch/foo_foo3103=== PAUSE TestGlobMatch/foo_foo3104=== RUN TestGlobMatch/foo_bar3105=== PAUSE TestGlobMatch/foo_bar3106=== RUN TestGlobMatch/*_3107=== PAUSE TestGlobMatch/*_3108=== RUN TestGlobMatch/*_anything3109=== PAUSE TestGlobMatch/*_anything3110=== RUN TestGlobMatch/foo*_foo3111=== PAUSE TestGlobMatch/foo*_foo3112=== RUN TestGlobMatch/foo*_foobar3113=== PAUSE TestGlobMatch/foo*_foobar3114=== RUN TestGlobMatch/foo*_bar3115=== PAUSE TestGlobMatch/foo*_bar3116=== RUN TestGlobMatch/*bar_bar3117=== PAUSE TestGlobMatch/*bar_bar3118=== RUN TestGlobMatch/*bar_foobar3119=== PAUSE TestGlobMatch/*bar_foobar3120=== RUN TestGlobMatch/*bar_foo3121=== PAUSE TestGlobMatch/*bar_foo3122=== RUN TestGlobMatch/foo*bar_foobar3123=== PAUSE TestGlobMatch/foo*bar_foobar3124=== RUN TestGlobMatch/foo*bar_foo123bar3125=== PAUSE TestGlobMatch/foo*bar_foo123bar3126=== RUN TestGlobMatch/foo*bar_foobarbaz3127=== PAUSE TestGlobMatch/foo*bar_foobarbaz3128=== RUN TestGlobMatch/*/*_foo/bar3129=== PAUSE TestGlobMatch/*/*_foo/bar3130=== RUN TestGlobMatch/*/*_foo3131=== PAUSE TestGlobMatch/*/*_foo3132=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3133=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3134=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03135=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03136=== RUN TestGlobMatch/refs/*/main_refs/heads/main3137=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3138=== RUN TestGlobMatch/fo?_foo3139=== PAUSE TestGlobMatch/fo?_foo3140=== RUN TestGlobMatch/fo?_fo3141=== PAUSE TestGlobMatch/fo?_fo3142=== RUN TestGlobMatch/fo?_fooo3143=== PAUSE TestGlobMatch/fo?_fooo3144=== RUN TestGlobMatch/?oo_foo3145=== PAUSE TestGlobMatch/?oo_foo3146=== RUN TestGlobMatch/?oo_boo3147=== PAUSE TestGlobMatch/?oo_boo3148=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3149=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3150=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3151=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3152=== CONT TestScopes_LegacyProviderDefaultsToWrite31532026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50636/oidc3154--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)3155=== CONT TestGlobMatch/foo_foo3156=== CONT TestGlobMatch/*/*_foo/bar3157=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3158=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3159=== CONT TestGlobMatch/?oo_boo3160=== CONT TestGlobMatch/?oo_foo3161=== CONT TestGlobMatch/fo?_fooo3162=== CONT TestGlobMatch/fo?_fo3163=== CONT TestGlobMatch/fo?_foo3164=== CONT TestGlobMatch/refs/*/main_refs/heads/main3165=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03166=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3167=== CONT TestGlobMatch/*/*_foo3168=== CONT TestGlobMatch/*bar_bar3169=== CONT TestGlobMatch/foo*bar_foobarbaz3170=== CONT TestGlobMatch/foo*bar_foo123bar3171=== CONT TestGlobMatch/foo*bar_foobar3172=== CONT TestGlobMatch/*bar_foo3173=== CONT TestGlobMatch/*bar_foobar3174=== CONT TestGlobMatch/foo*_foo3175=== CONT TestGlobMatch/foo*_bar3176=== CONT TestGlobMatch/foo*_foobar3177=== CONT TestGlobMatch/*_anything3178=== CONT TestGlobMatch/*_3179=== CONT TestGlobMatch/foo_bar3180--- PASS: TestGlobMatch (0.00s)3181 --- PASS: TestGlobMatch/foo_foo (0.00s)3182 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3183 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3184 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3185 --- PASS: TestGlobMatch/?oo_boo (0.00s)3186 --- PASS: TestGlobMatch/?oo_foo (0.00s)3187 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3188 --- PASS: TestGlobMatch/fo?_fo (0.00s)3189 --- PASS: TestGlobMatch/fo?_foo (0.00s)3190 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3191 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3192 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3193 --- PASS: TestGlobMatch/*/*_foo (0.00s)3194 --- PASS: TestGlobMatch/*bar_bar (0.00s)3195 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3196 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3197 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3198 --- PASS: TestGlobMatch/*bar_foo (0.00s)3199 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3200 --- PASS: TestGlobMatch/foo*_foo (0.00s)3201 --- PASS: TestGlobMatch/foo*_bar (0.00s)3202 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3203 --- PASS: TestGlobMatch/*_anything (0.00s)3204 --- PASS: TestGlobMatch/*_ (0.00s)3205 --- PASS: TestGlobMatch/foo_bar (0.00s)32062026/10/01 09:41:07 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5063832072026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50640/oidc32082026/10/01 09:41:07 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50627/oidc32092026/10/01 09:41:07 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:50642/oidc3210--- PASS: TestValidateToken_WrongAudience (0.07s)3211--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)3212--- PASS: TestValidateToken_MultipleProviders (0.07s)32132026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50645/oidc32142026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50646/oidc3215--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.03s)3216--- PASS: TestPins_ReservedForMatchingRule (0.09s)32172026/10/01 09:41:07 http: TLS handshake error from 127.0.0.1:50650: read tcp 127.0.0.1:50649->127.0.0.1:50650: use of closed network connection3218--- PASS: TestNewValidator_KubernetesRequiresCA (0.06s)32192026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50652/oidc3220--- PASS: TestScopes_Rules (0.05s)32212026/10/01 09:41:07 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50651/oidc3222--- PASS: TestValidateToken_NoMatchingProvider (0.11s)32232026/10/01 09:41:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50656/oidc3224--- PASS: TestPins_TopLevelShorthand (0.09s)3225PASS3226Running hook tests...3227=== RUN TestSendPathsEmpty3228=== PAUSE TestSendPathsEmpty3229=== RUN TestQueueEnqueueAndFetch3230=== PAUSE TestQueueEnqueueAndFetch3231=== RUN TestQueueDeduplication3232=== PAUSE TestQueueDeduplication3233=== RUN TestQueueRemove3234=== PAUSE TestQueueRemove3235=== RUN TestQueueFetchBatchLimit3236=== PAUSE TestQueueFetchBatchLimit3237=== RUN TestQueueRetryMovesToBack3238=== PAUSE TestQueueRetryMovesToBack3239=== RUN TestQueueFetchRemoveLifecycle3240=== PAUSE TestQueueFetchRemoveLifecycle3241=== RUN TestQueueConcurrentWriters3242=== PAUSE TestQueueConcurrentWriters3243=== RUN TestQueueRemoveLargeClosure3244=== PAUSE TestQueueRemoveLargeClosure3245=== RUN TestServerClientIntegration3246=== PAUSE TestServerClientIntegration3247=== RUN TestServerQueueError3248=== PAUSE TestServerQueueError3249=== RUN TestGetListenerSocketActivation3250 server_test.go:210: === RUN TestGetListenerSocketActivation3251 --- PASS: TestGetListenerSocketActivation (0.00s)3252 PASS3253 3254--- PASS: TestGetListenerSocketActivation (0.02s)3255=== RUN TestDrainIsolatesPoisonPath3256=== PAUSE TestDrainIsolatesPoisonPath3257=== RUN TestRunNotBlockedByPoisonHead3258=== PAUSE TestRunNotBlockedByPoisonHead3259=== RUN TestDrainGivesUpWhenServerDown3260=== PAUSE TestDrainGivesUpWhenServerDown3261=== RUN TestFailedPathPrunedByLaterClosure3262=== PAUSE TestFailedPathPrunedByLaterClosure3263=== RUN TestWorkerUploadsAndRemoves3264=== PAUSE TestWorkerUploadsAndRemoves3265=== RUN TestWorkerSkipsGCdPaths3266=== PAUSE TestWorkerSkipsGCdPaths3267=== RUN TestWorkerPrunesClosureDeps3268=== PAUSE TestWorkerPrunesClosureDeps3269=== RUN TestDrainTimeout3270=== PAUSE TestDrainTimeout3271=== CONT TestSendPathsEmpty3272=== CONT TestServerQueueError3273=== CONT TestWorkerUploadsAndRemoves3274--- PASS: TestSendPathsEmpty (0.00s)3275=== CONT TestQueueFetchBatchLimit3276=== CONT TestQueueRemove3277=== CONT TestQueueDeduplication3278=== CONT TestQueueEnqueueAndFetch3279=== CONT TestDrainGivesUpWhenServerDown3280=== CONT TestFailedPathPrunedByLaterClosure3281=== CONT TestRunNotBlockedByPoisonHead3282=== CONT TestWorkerPrunesClosureDeps32832026/10/01 09:41:07 ERROR Failed to queue paths error="permission denied" count=13284=== CONT TestDrainTimeout3285--- PASS: TestServerQueueError (0.01s)32862026/10/01 09:41:07 INFO Upload queue status pending=232872026/10/01 09:41:07 INFO Uploading batch count=132882026/10/01 09:41:07 INFO Upload queue status pending=332892026/10/01 09:41:07 INFO Uploading batch count=232902026/10/01 09:41:07 INFO Upload queue status pending=232912026/10/01 09:41:07 INFO Uploading batch count=132922026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=132932026/10/01 09:41:07 INFO Uploading batch count=132942026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=132952026/10/01 09:41:07 INFO Uploading batch count=23296--- PASS: TestQueueEnqueueAndFetch (0.03s)3297=== CONT TestQueueRemoveLargeClosure32982026/10/01 09:41:07 INFO Uploading batch count=232992026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=233002026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainGivesUpWhenServerDown328359273/002/a3301--- PASS: TestQueueRemove (0.03s)3302=== CONT TestServerClientIntegration33032026/10/01 09:41:07 INFO Uploading batch count=133042026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainGivesUpWhenServerDown328359273/002/b33052026/10/01 09:41:07 INFO Uploading batch count=13306--- PASS: TestQueueFetchBatchLimit (0.03s)3307=== CONT TestQueueConcurrentWriters33082026/10/01 09:41:07 INFO Uploading batch count=233092026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=233102026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainGivesUpWhenServerDown328359273/002/c3311--- PASS: TestQueueDeduplication (0.03s)3312=== CONT TestQueueFetchRemoveLifecycle33132026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainGivesUpWhenServerDown328359273/002/d33142026/10/01 09:41:07 INFO Uploading batch count=23315--- PASS: TestServerClientIntegration (0.00s)3316=== CONT TestDrainIsolatesPoisonPath33172026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=233182026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainGivesUpWhenServerDown328359273/002/e33192026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainGivesUpWhenServerDown328359273/002/f33202026/10/01 09:41:07 ERROR Drain finished with paths left in queue remaining=103321--- PASS: TestFailedPathPrunedByLaterClosure (0.04s)3322=== CONT TestWorkerSkipsGCdPaths3323--- PASS: TestWorkerUploadsAndRemoves (0.07s)3324=== CONT TestQueueRetryMovesToBack3325--- PASS: TestDrainGivesUpWhenServerDown (0.07s)3326--- PASS: TestWorkerPrunesClosureDeps (0.07s)33272026/10/01 09:41:07 INFO Upload queue status pending=233282026/10/01 09:41:07 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-51549-3085653128/TestWorkerSkipsGCdPaths2563265437/002/nonexistent33292026/10/01 09:41:07 INFO Uploading batch count=433302026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=43331--- PASS: TestQueueFetchRemoveLifecycle (0.04s)33322026/10/01 09:41:07 INFO Uploading batch count=133332026/10/01 09:41:07 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-51549-3085653128/TestDrainIsolatesPoisonPath1257399009/002/bbb33342026/10/01 09:41:07 INFO Uploading batch count=133352026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=133362026/10/01 09:41:07 INFO Uploading batch count=133372026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=133382026/10/01 09:41:07 INFO Uploading batch count=133392026/10/01 09:41:07 ERROR Upload failed error="upload failed" count=133402026/10/01 09:41:07 ERROR Drain finished with paths left in queue remaining=13341--- PASS: TestQueueRetryMovesToBack (0.02s)3342--- PASS: TestDrainIsolatesPoisonPath (0.05s)3343--- PASS: TestWorkerSkipsGCdPaths (0.05s)3344--- PASS: TestQueueRemoveLargeClosure (0.09s)33452026/10/01 09:41:08 ERROR Upload failed error="context deadline exceeded" count=233462026/10/01 09:41:08 ERROR Drain finished with paths left in queue remaining=43347--- PASS: TestDrainTimeout (0.24s)3348--- PASS: TestQueueConcurrentWriters (0.50s)33492026/10/01 09:41:08 INFO Uploading batch count=133502026/10/01 09:41:08 INFO Uploading batch count=133512026/10/01 09:41:08 INFO Uploading batch count=133522026/10/01 09:41:08 ERROR Upload failed error="upload failed" count=133532026/10/01 09:41:08 INFO Uploading batch count=133542026/10/01 09:41:08 ERROR Upload failed error="upload failed" count=133552026/10/01 09:41:08 INFO Uploading batch count=133562026/10/01 09:41:08 ERROR Upload failed error="upload failed" count=133572026/10/01 09:41:08 INFO Uploading batch count=133582026/10/01 09:41:08 ERROR Upload failed error="upload failed" count=133592026/10/01 09:41:08 ERROR Drain finished with paths left in queue remaining=13360--- PASS: TestRunNotBlockedByPoisonHead (1.05s)3361PASS