niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #302
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96=== CONT TestEncodeNixBase32WithRealHash97--- PASS: TestEncodeNixBase32WithRealHash (0.00s)98=== CONT TestConvertHashToNix3299=== RUN TestConvertHashToNix32/SRI_format_to_Nix32100--- PASS: TestShellSplit (0.00s)101=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32102=== CONT TestResolveStorePath103=== RUN TestConvertHashToNix32/already_Nix32_format104=== PAUSE TestConvertHashToNix32/already_Nix32_format105=== RUN TestConvertHashToNix32/invalid_format106=== PAUSE TestConvertHashToNix32/invalid_format107=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess108=== CONT TestSetClientTLSErrors109=== CONT TestRateLimiterFeedback110=== RUN TestRateLimiterFeedback/429_enables_limiter111=== PAUSE TestRateLimiterFeedback/429_enables_limiter112=== RUN TestRateLimiterFeedback/503_enables_limiter113=== PAUSE TestRateLimiterFeedback/503_enables_limiter114=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter115=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter116=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter117=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter118=== CONT TestPathInfoCACompatibility119=== RUN TestPathInfoCACompatibility/null_ca_field120=== PAUSE TestPathInfoCACompatibility/null_ca_field121=== RUN TestPathInfoCACompatibility/old_string_format_-_text122=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text123=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive124=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive125=== RUN TestPathInfoCACompatibility/new_structured_format_-_text126=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text127=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method128=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method129=== CONT TestScriptTokenEmptyCommand130--- PASS: TestScriptTokenEmptyCommand (0.00s)131=== CONT TestScriptTokenBadJSON1322026/10/01 08:28:14 WARN Rate limiter enabled after throttle name=server-test rate=5133=== CONT TestScriptTokenScriptFails134=== CONT TestParsePathInfoJSONMultiplePaths135=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths136=== CONT TestGetStorePathHash137=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths138=== CONT TestDoWithRetry_BodyReplayedViaGetBody139=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths140=== CONT TestParsePathInfoJSON141=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths142=== CONT TestScriptTokenEmptyToken143=== RUN TestParsePathInfoJSON/Nix_format144=== PAUSE TestParsePathInfoJSON/Nix_format145=== RUN TestParsePathInfoJSON/Lix_format146=== PAUSE TestParsePathInfoJSON/Lix_format147=== RUN TestParsePathInfoJSON/empty_input148=== PAUSE TestParsePathInfoJSON/empty_input149=== RUN TestParsePathInfoJSON/whitespace_only150=== PAUSE TestParsePathInfoJSON/whitespace_only151=== RUN TestGetStorePathHash/valid_store_path152=== PAUSE TestGetStorePathHash/valid_store_path153=== RUN TestGetStorePathHash/basename_without_hyphen_should_error154=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error155=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error156=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error157=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error158=== RUN TestParsePathInfoJSON/invalid_JSON159=== CONT TestScriptTokenCachesUntilRefresh160--- PASS: TestResolveStorePath (0.00s)161=== PAUSE TestParsePathInfoJSON/invalid_JSON162=== CONT TestScriptTokenNoExpiryRerunsEveryCall163=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error164=== CONT TestFileTokenEmpty165=== RUN TestSetClientTLSErrors/missing_cert_file166=== PAUSE TestSetClientTLSErrors/missing_cert_file167=== RUN TestSetClientTLSErrors/missing_key_file168=== PAUSE TestSetClientTLSErrors/missing_key_file169=== RUN TestSetClientTLSErrors/missing_ca_file170=== PAUSE TestSetClientTLSErrors/missing_ca_file171=== RUN TestSetClientTLSErrors/invalid_ca_file172=== PAUSE TestSetClientTLSErrors/invalid_ca_file173--- PASS: TestDoServerRequestAttachesToken (0.01s)174=== CONT TestFileTokenMissing175--- PASS: TestScriptTokenScriptFails (0.01s)176=== CONT TestFileTokenReadsAndCaches1772026/10/01 08:28:14 WARN Rate limiter enabled after throttle name=server-test rate=51782026/10/01 08:28:14 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:60346179=== CONT TestStaticToken180--- PASS: TestStaticToken (0.00s)181=== CONT TestStreamPushRequestLine182--- PASS: TestFileTokenEmpty (0.00s)183=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1842026/10/01 08:28:14 WARN Rate limiter backed off name=server-test rate=51852026/10/01 08:28:14 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:603461862026/10/01 08:28:14 ERROR Upload failed error=boom count=1187--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)188=== CONT TestSetClientTLS189--- PASS: TestFileTokenMissing (0.00s)190=== CONT TestClientSignaturesByStorePath191--- PASS: TestClientSignaturesByStorePath (0.00s)192=== CONT TestStreamPushReportsSignatures1932026/10/01 08:28:14 ERROR Upload failed error=boom count=1194--- PASS: TestStreamPushReportsSignatures (0.00s)195=== CONT TestPathInfoHashCompatibility196=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)197=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)198=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon199=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon200=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI201=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI202=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512203=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512204=== CONT TestUploadMultipart_SupersededByPeer205=== RUN TestUploadMultipart_SupersededByPeer/exists206=== PAUSE TestUploadMultipart_SupersededByPeer/exists207=== RUN TestUploadMultipart_SupersededByPeer/missing208=== PAUSE TestUploadMultipart_SupersededByPeer/missing209=== CONT TestStreamPushBatchesUnderLoad210--- PASS: TestFileTokenReadsAndCaches (0.00s)211=== CONT TestEncodeNixBase32212=== RUN TestEncodeNixBase32/test_string_hash213=== PAUSE TestEncodeNixBase32/test_string_hash214=== RUN TestEncodeNixBase32/empty_input215=== PAUSE TestEncodeNixBase32/empty_input216=== CONT TestStreamPushGivesUpOnDeadServer2172026/10/01 08:28:14 ERROR Upload failed error="connection refused" count=202182026/10/01 08:28:14 ERROR Server seems unavailable, giving up on batch untried=17219--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)220=== CONT TestDumpPathWriterError221--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)222=== CONT TestStreamPushIsolatesFailures2232026/10/01 08:28:14 ERROR Upload failed error="bad path" count=3224--- PASS: TestStreamPushIsolatesFailures (0.00s)225=== CONT TestDumpPathSingleFile226=== RUN TestSetClientTLS/rejects_connection_without_client_cert227=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert228=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA229=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA230=== RUN TestSetClientTLS/preserves_debug_logging_transport231=== PAUSE TestSetClientTLS/preserves_debug_logging_transport232=== CONT TestDumpPathMatchesNix233--- PASS: TestScriptTokenBadJSON (0.01s)234=== CONT TestFilterOversizedClosures235=== RUN TestFilterOversizedClosures/no_limit_keeps_everything236=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything237=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped238=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped239=== RUN TestFilterOversizedClosures/all_closures_skipped240=== PAUSE TestFilterOversizedClosures/all_closures_skipped241=== CONT TestCaseHackSuffix242--- PASS: TestScriptTokenEmptyToken (0.01s)243=== CONT TestPartSizeForNAR244=== RUN TestPartSizeForNAR/zero_stays_at_minimum245=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum246=== RUN TestPartSizeForNAR/small_stays_at_minimum247=== PAUSE TestPartSizeForNAR/small_stays_at_minimum248=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum249=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum250=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts251=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts252=== RUN TestPartSizeForNAR/1_TiB253=== PAUSE TestPartSizeForNAR/1_TiB254=== RUN TestPartSizeForNAR/5_TiB_S3_max_object255=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object256=== RUN TestPartSizeForNAR/capped_at_5_GiB257=== PAUSE TestPartSizeForNAR/capped_at_5_GiB258=== CONT TestUploadMultipart_PartsInParallel259--- PASS: TestStreamPushRequestLine (0.01s)260=== CONT TestStreamPushReportsEveryPath261--- PASS: TestStreamPushReportsEveryPath (0.00s)262=== CONT TestShellSplitErrors263--- PASS: TestShellSplitErrors (0.00s)264=== CONT TestRegisterUploadedObjectReusesConnections265--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)266=== CONT TestConvertHashToNix32/SRI_format_to_Nix32267=== CONT TestConvertHashToNix32/invalid_format268=== CONT TestConvertHashToNix32/already_Nix32_format269--- PASS: TestConvertHashToNix32 (0.00s)270 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)271 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)272 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)273=== CONT TestRateLimiterFeedback/429_enables_limiter2742026/10/01 08:28:14 WARN Rate limiter enabled after throttle name=server-test rate=52752026/10/01 08:28:14 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:60421276--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)277=== CONT TestPathInfoCACompatibility/null_ca_field278=== CONT TestRateLimiterFeedback/503_enables_limiter2792026/10/01 08:28:14 WARN Rate limiter backed off name=server-test rate=5280=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2812026/10/01 08:28:14 WARN Rate limiter enabled after throttle name=server-test rate=52822026/10/01 08:28:14 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:604232832026/10/01 08:28:14 WARN Rate limiter backed off name=server-test rate=5284=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter285=== CONT TestPathInfoCACompatibility/new_structured_format_-_text286=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method287=== CONT TestPathInfoCACompatibility/old_string_format_-_text288=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths289=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths290--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)291 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)292 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)293=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive294--- PASS: TestPathInfoCACompatibility (0.00s)295 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)296 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)297 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)298 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)299 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)300=== CONT TestParsePathInfoJSON/Nix_format301=== CONT TestGetStorePathHash/valid_store_path302=== CONT TestParsePathInfoJSON/whitespace_only303=== CONT TestParsePathInfoJSON/empty_input304=== CONT TestParsePathInfoJSON/Lix_format305=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error306=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error307=== CONT TestParsePathInfoJSON/invalid_JSON308--- PASS: TestParsePathInfoJSON (0.00s)309 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)310 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)311 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)312 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)313 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)314=== CONT TestGetStorePathHash/basename_without_hyphen_should_error315--- PASS: TestGetStorePathHash (0.00s)316 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)317 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)318 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)319 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)320=== CONT TestSetClientTLSErrors/missing_cert_file321=== CONT TestSetClientTLSErrors/missing_ca_file322=== CONT TestSetClientTLSErrors/invalid_ca_file323--- PASS: TestRateLimiterFeedback (0.00s)324 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)325 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)326 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)327 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)328=== CONT TestSetClientTLSErrors/missing_key_file329=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)330=== CONT TestUploadMultipart_SupersededByPeer/exists331=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512332=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI333=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon334--- PASS: TestPathInfoHashCompatibility (0.00s)335 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)336 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)337 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)338 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)339=== CONT TestUploadMultipart_SupersededByPeer/missing340--- PASS: TestSetClientTLSErrors (0.01s)341 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)342 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)343 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)344 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)345=== CONT TestEncodeNixBase32/test_string_hash346=== CONT TestEncodeNixBase32/empty_input347--- PASS: TestEncodeNixBase32 (0.00s)348 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)349 --- PASS: TestEncodeNixBase32/empty_input (0.00s)350=== CONT TestSetClientTLS/rejects_connection_without_client_cert351--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)352 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)353 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)354=== CONT TestSetClientTLS/preserves_debug_logging_transport355--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)356=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA357=== CONT TestFilterOversizedClosures/no_limit_keeps_everything358=== CONT TestFilterOversizedClosures/all_closures_skipped3592026/10/01 08:28:14 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=50360=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3612026/10/01 08:28:14 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=2000362--- PASS: TestFilterOversizedClosures (0.00s)363 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)364 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)365 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)366=== CONT TestPartSizeForNAR/zero_stays_at_minimum367=== CONT TestPartSizeForNAR/1_TiB368=== CONT TestPartSizeForNAR/capped_at_5_GiB369=== CONT TestPartSizeForNAR/5_TiB_S3_max_object370=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum371=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts372=== CONT TestPartSizeForNAR/small_stays_at_minimum373--- PASS: TestPartSizeForNAR (0.00s)374 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)376 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)377 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)378 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)379 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)380 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)381--- PASS: TestDumpPathWriterError (0.05s)3822026/10/01 08:28:14 http: TLS handshake error from 127.0.0.1:60433: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.00s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestDumpPathSingleFile (0.05s)388--- PASS: TestCaseHackSuffix (0.05s)389--- PASS: TestDumpPathMatchesNix (0.08s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestUploadMultipart_PartsInParallel (0.62s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_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-91269-3505625895/postgres3259739771/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-91269-3505625895/postgres3259739771/data -l logfile start421422/nix/var/nix/builds/nix-91269-3505625895/postgres3259739771:5432 - no response4232026-10-01 08:28:15.994 UTC [91337] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 08:28:15.994 UTC [91337] LOG: listening on Unix socket "/nix/var/nix/builds/nix-91269-3505625895/postgres3259739771/.s.PGSQL.5432"4252026-10-01 08:28:15.996 UTC [91344] LOG: database system was shut down at 2026-10-01 08:28:15 UTC4262026-10-01 08:28:15.997 UTC [91337] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-91269-3505625895/postgres3259739771:5432 - accepting connections428{"timestamp":"2026-10-01T08:28:16.208755Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"60b2c77c-66f1-4f1b-a7d0-bf420321f91f","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(11)"}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 TestResolveDBConnectionString466=== PAUSE TestResolveDBConnectionString467=== RUN TestLeadElectsOneAndHandsOver468=== PAUSE TestLeadElectsOneAndHandsOver469=== RUN TestLeadIncumbentWinsAfterRestart4702026-10-01 08:28:16.393 UTC [91378] ERROR: relation "goose_db_version" does not exist at character 364712026-10-01 08:28:16.393 UTC [91378] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4722026/10/01 08:28:16 OK 20241026095416_initial_model.sql (3.41ms)4732026/10/01 08:28:16 OK 20251210153512_drop_unused_gin_index.sql (511.88µs)4742026/10/01 08:28:16 OK 20251218171726_add_pins.sql (833.04µs)4752026/10/01 08:28:16 OK 20260628120000_add_object_size_and_stats.sql (882.33µs)4762026/10/01 08:28:16 OK 20260905000000_add_claims.sql (937.21µs)4772026/10/01 08:28:16 OK 20260920000000_drop_claims.sql (606.21µs)4782026/10/01 08:28:16 OK 20260923120000_add_pushes.sql (416.08µs)4792026/10/01 08:28:16 goose: successfully migrated database to version: 202609231200004802026/10/01 08:28:16 OK 1_commit_pending_closure.sql (887.13µs)4812026/10/01 08:28:16 OK 2_object_stats_trigger.sql (201.17µs)4822026/10/01 08:28:16 OK 3_commit_push.sql (169.25µs)4832026/10/01 08:28:16 goose: up to current file version: 34842026/10/01 08:28:16 INFO lead: acquired remote=192.0.2.1:12344852026/10/01 08:28:17 INFO lead: released remote=192.0.2.1:12344862026/10/01 08:28:17 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 08:28:17 INFO lead: released remote=192.0.2.1:1234488--- PASS: TestLeadIncumbentWinsAfterRestart (0.80s)489=== RUN TestLeadEndsOnShutdown490=== PAUSE TestLeadEndsOnShutdown491=== RUN TestGCAdvisoryLockBlocksConcurrentRun4922026-10-01 08:28:17.193 UTC [91382] ERROR: relation "goose_db_version" does not exist at character 364932026-10-01 08:28:17.193 UTC [91382] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4942026/10/01 08:28:17 OK 20241026095416_initial_model.sql (3.88ms)4952026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (435.13µs)4962026/10/01 08:28:17 OK 20251218171726_add_pins.sql (904.88µs)4972026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (955.79µs)4982026/10/01 08:28:17 OK 20260905000000_add_claims.sql (1.05ms)4992026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (655.17µs)5002026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (446.04µs)5012026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200005022026/10/01 08:28:17 OK 1_commit_pending_closure.sql (937µs)5032026/10/01 08:28:17 OK 2_object_stats_trigger.sql (213.04µs)5042026/10/01 08:28:17 OK 3_commit_push.sql (198.38µs)5052026/10/01 08:28:17 goose: up to current file version: 3506--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.16s)507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestPushDedupSurvivesConcurrentGC512=== PAUSE TestPushDedupSurvivesConcurrentGC513=== RUN TestDeduplicatedObjectsRecordedAsPending514=== PAUSE TestDeduplicatedObjectsRecordedAsPending515=== RUN TestGCSweepSkipsPendingObjects516=== PAUSE TestGCSweepSkipsPendingObjects517=== RUN TestTombstonedObjectOfferedWithoutWaiting518=== PAUSE TestTombstonedObjectOfferedWithoutWaiting519=== RUN TestGCSweepDeliversEachKeyOnce520=== PAUSE TestGCSweepDeliversEachKeyOnce521=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection522=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== RUN TestForceGCDuringPushOffersSweptObject524=== PAUSE TestForceGCDuringPushOffersSweptObject525=== RUN TestFailedS3DeleteKeepsTombstone526=== PAUSE TestFailedS3DeleteKeepsTombstone527=== RUN TestSweepSkipsRowsLockedByPush528=== PAUSE TestSweepSkipsRowsLockedByPush529=== RUN TestRegisterCompletedObjectNeedsPendingRow530=== PAUSE TestRegisterCompletedObjectNeedsPendingRow531=== RUN TestGetExistingObjectsLocksRows532=== PAUSE TestGetExistingObjectsLocksRows533=== RUN TestGCTaskStore_StartNew534=== PAUSE TestGCTaskStore_StartNew535=== RUN TestGCTaskStore_DeduplicateSameParams536=== PAUSE TestGCTaskStore_DeduplicateSameParams537=== RUN TestGCTaskStore_ConflictDifferentParams538=== PAUSE TestGCTaskStore_ConflictDifferentParams539=== RUN TestGCTaskStore_GetEmpty540=== PAUSE TestGCTaskStore_GetEmpty541=== RUN TestGCTaskStore_GetReturnsLatest542=== PAUSE TestGCTaskStore_GetReturnsLatest543=== RUN TestGCTaskStore_CompletedAllowsNewTask544=== PAUSE TestGCTaskStore_CompletedAllowsNewTask545=== RUN TestGCTaskStore_PhaseUpdates546=== PAUSE TestGCTaskStore_PhaseUpdates547=== RUN TestGCTaskStore_Fail548=== PAUSE TestGCTaskStore_Fail549=== RUN TestGracefulShutdownDrainsInflight550=== PAUSE TestGracefulShutdownDrainsInflight551=== RUN TestService_healthCheckHandler552=== PAUSE TestService_healthCheckHandler553=== RUN TestService_readinessHandler554=== PAUSE TestService_readinessHandler555=== RUN TestGenerateLandingPage556=== PAUSE TestGenerateLandingPage557=== RUN TestCacheConfigHandlerMaxNarSize558=== PAUSE TestCacheConfigHandlerMaxNarSize559=== RUN TestCreatePendingClosureRejectsOversizedNAR560=== PAUSE TestCreatePendingClosureRejectsOversizedNAR561=== RUN TestNARDeduplicationMetadataUploadBug562=== PAUSE TestNARDeduplicationMetadataUploadBug563=== RUN TestMetricsInventory564=== PAUSE TestMetricsInventory565=== RUN TestService_NativeMTLS566=== PAUSE TestService_NativeMTLS567=== RUN TestServerTLSConfig568=== PAUSE TestServerTLSConfig569=== RUN TestMultipartCleanup570=== PAUSE TestMultipartCleanup571=== RUN TestObjectStatsTrigger572=== PAUSE TestObjectStatsTrigger573=== RUN TestOrphanedObjectsGC574=== PAUSE TestOrphanedObjectsGC575=== RUN TestOrphanedObjectsGCStressTest576=== PAUSE TestOrphanedObjectsGCStressTest577=== RUN TestCreatePin_ReservedPins578=== PAUSE TestCreatePin_ReservedPins579=== RUN TestParseSingleRange580=== PAUSE TestParseSingleRange581=== RUN TestProxyHeadersOnlyTrustedOnSocket582=== PAUSE TestProxyHeadersOnlyTrustedOnSocket583=== RUN TestIsValidCachePath584=== PAUSE TestIsValidCachePath585=== RUN TestReadProxyNarinfo586=== PAUSE TestReadProxyNarinfo587=== RUN TestReadProxyNarinfoAlreadyDecompressed588=== PAUSE TestReadProxyNarinfoAlreadyDecompressed589=== RUN TestReadProxyNarStreaming590=== PAUSE TestReadProxyNarStreaming591=== RUN TestReadProxy404592=== PAUSE TestReadProxy404593=== RUN TestReadProxyInvalidPath594=== PAUSE TestReadProxyInvalidPath595=== RUN TestReadProxyHead596=== PAUSE TestReadProxyHead597=== RUN TestReadProxyConditionalGet598=== PAUSE TestReadProxyConditionalGet599=== RUN TestReadProxyRootRedirectsToIndexHTML600=== PAUSE TestReadProxyRootRedirectsToIndexHTML601=== RUN TestReadProxyDisabled602=== PAUSE TestReadProxyDisabled603=== RUN TestReadRedirectNar604=== PAUSE TestReadRedirectNar605=== RUN TestReadRedirectKeepsNarinfoProxied606=== PAUSE TestReadRedirectKeepsNarinfoProxied607=== RUN TestReadProxyRangeRequest608=== PAUSE TestReadProxyRangeRequest609=== RUN TestReadRedirectUsesPublicS3URL610=== PAUSE TestReadRedirectUsesPublicS3URL611=== RUN TestPush_OverlappingRootsStoreOneRowPerKey612=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey613=== RUN TestPush_CompleteCommitsEveryRoot614=== PAUSE TestPush_CompleteCommitsEveryRoot615=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit616=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit617=== RUN TestPush_RejectsBadRequests618=== PAUSE TestPush_RejectsBadRequests619=== RUN TestPush_SignsNarinfosOfItsPendingObjects620=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects621=== RUN TestRedundantMultipartUpload622=== PAUSE TestRedundantMultipartUpload623=== RUN TestCompleteMultipartUpload_ErrorButObjectExists624=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists625=== RUN TestCompletedNarNotReofferedAcrossClosures626=== PAUSE TestCompletedNarNotReofferedAcrossClosures627=== RUN TestPresignedUploadRegisteredBeforeCommit628=== PAUSE TestPresignedUploadRegisteredBeforeCommit629=== RUN TestService_Rustfstest630=== PAUSE TestService_Rustfstest631=== RUN TestParseSize632=== PAUSE TestParseSize633=== RUN TestSkippedUploadsHandler634=== PAUSE TestSkippedUploadsHandler635=== RUN TestSystemdListenerNotActivated636--- PASS: TestSystemdListenerNotActivated (0.00s)637=== RUN TestWatchdogBeatsWhenHealthy638--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)639=== RUN TestWatchdogSkipsWhenUnhealthy6402026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6432026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6442026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6452026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6462026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6472026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6482026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6492026/10/01 08:28:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"650--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)651=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle652=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle653=== RUN TestProxyWriteTimeout654=== PAUSE TestProxyWriteTimeout655=== RUN TestIsValidUploadKey656=== PAUSE TestIsValidUploadKey657=== RUN TestUploadHandlersRejectInvalidKeys658=== PAUSE TestUploadHandlersRejectInvalidKeys659=== RUN TestUploadHandlersRejectOversizedBody660=== PAUSE TestUploadHandlersRejectOversizedBody661=== RUN TestService_cleanupPendingClosuresHandler662=== PAUSE TestService_cleanupPendingClosuresHandler663=== RUN TestService_createPendingClosureHandler664=== PAUSE TestService_createPendingClosureHandler665=== RUN TestService_verifyS3Integrity666=== PAUSE TestService_verifyS3Integrity667=== RUN TestCompleteMultipartUnregistered668=== PAUSE TestCompleteMultipartUnregistered669=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT670=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT671=== CONT TestUploadHandlersRejectInvalidKeys672=== CONT TestService_AuthMiddleware673=== CONT TestIsValidUploadKey674=== RUN TestIsValidUploadKey/narinfo675=== CONT TestProxyWriteTimeout676=== RUN TestProxyWriteTimeout/narinfo677=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle678=== PAUSE TestProxyWriteTimeout/narinfo679=== RUN TestProxyWriteTimeout/1_GiB_nar680=== PAUSE TestProxyWriteTimeout/1_GiB_nar681=== CONT TestService_verifyS3Integrity682=== CONT TestSkippedUploadsHandler683=== CONT TestParseSize684--- PASS: TestParseSize (0.00s)685=== CONT TestCompleteMultipartUnregistered686=== CONT TestService_Rustfstest687=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT688=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info689=== PAUSE TestIsValidUploadKey/narinfo690=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info691=== RUN TestProxyWriteTimeout/10_GiB_nar692=== PAUSE TestProxyWriteTimeout/10_GiB_nar693=== RUN TestProxyWriteTimeout/unknown_size694=== PAUSE TestProxyWriteTimeout/unknown_size695=== RUN TestIsValidUploadKey/nar_zst696=== CONT TestPresignedUploadRegisteredBeforeCommit697=== PAUSE TestIsValidUploadKey/nar_zst698=== RUN TestIsValidUploadKey/nar_xz699=== PAUSE TestIsValidUploadKey/nar_xz700=== RUN TestIsValidUploadKey/nar_plain701=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal702=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal703=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key704=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key705=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key706=== PAUSE TestIsValidUploadKey/nar_plain707=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key708=== RUN TestIsValidUploadKey/listing709=== PAUSE TestIsValidUploadKey/listing710=== RUN TestIsValidUploadKey/build_log711=== PAUSE TestIsValidUploadKey/build_log712=== RUN TestIsValidUploadKey/build_log_home-manager_file713=== PAUSE TestIsValidUploadKey/build_log_home-manager_file714=== RUN TestIsValidUploadKey/build_log_plus_in_name715=== CONT TestService_cleanupPendingClosuresHandler716=== PAUSE TestIsValidUploadKey/build_log_plus_in_name717=== RUN TestIsValidUploadKey/build_log_question_mark7182026/10/01 08:28:17 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000719=== PAUSE TestIsValidUploadKey/build_log_question_mark720=== RUN TestIsValidUploadKey/build_log_equals721=== PAUSE TestIsValidUploadKey/build_log_equals722=== RUN TestIsValidUploadKey/realisation723=== PAUSE TestIsValidUploadKey/realisation724=== RUN TestIsValidUploadKey/realisation_plus_in_output725=== PAUSE TestIsValidUploadKey/realisation_plus_in_output726=== RUN TestIsValidUploadKey/nix-cache-info727=== PAUSE TestIsValidUploadKey/nix-cache-info728=== RUN TestIsValidUploadKey/index.html729=== PAUSE TestIsValidUploadKey/index.html730=== RUN TestIsValidUploadKey/narinfo_key,_nar_type731=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type732=== RUN TestIsValidUploadKey/nar_key,_narinfo_type733=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type734=== RUN TestIsValidUploadKey/listing_key,_narinfo_type735=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type736=== RUN TestIsValidUploadKey/traversal737=== PAUSE TestIsValidUploadKey/traversal738=== RUN TestIsValidUploadKey/traversal_nar739=== PAUSE TestIsValidUploadKey/traversal_nar740=== RUN TestIsValidUploadKey/absolute741=== PAUSE TestIsValidUploadKey/absolute742=== RUN TestIsValidUploadKey/empty_key743=== PAUSE TestIsValidUploadKey/empty_key744=== RUN TestIsValidUploadKey/unknown_type745=== PAUSE TestIsValidUploadKey/unknown_type746--- PASS: TestSkippedUploadsHandler (0.01s)747=== CONT TestService_createPendingClosureHandler748=== CONT TestCompletedNarNotReofferedAcrossClosures7492026-10-01 08:28:17.826 UTC [91405] ERROR: relation "goose_db_version" does not exist at character 367502026-10-01 08:28:17.826 UTC [91405] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7512026-10-01 08:28:17.828 UTC [91404] ERROR: relation "goose_db_version" does not exist at character 367522026-10-01 08:28:17.828 UTC [91404] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7532026-10-01 08:28:17.828 UTC [91406] ERROR: relation "goose_db_version" does not exist at character 367542026-10-01 08:28:17.828 UTC [91406] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7552026-10-01 08:28:17.829 UTC [91409] ERROR: relation "goose_db_version" does not exist at character 367562026-10-01 08:28:17.829 UTC [91409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7572026-10-01 08:28:17.831 UTC [91411] ERROR: relation "goose_db_version" does not exist at character 367582026-10-01 08:28:17.831 UTC [91411] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7592026-10-01 08:28:17.831 UTC [91408] ERROR: relation "goose_db_version" does not exist at character 367602026-10-01 08:28:17.831 UTC [91408] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7612026-10-01 08:28:17.831 UTC [91407] ERROR: relation "goose_db_version" does not exist at character 367622026-10-01 08:28:17.831 UTC [91407] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026-10-01 08:28:17.831 UTC [91412] ERROR: relation "goose_db_version" does not exist at character 367642026-10-01 08:28:17.831 UTC [91412] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026-10-01 08:28:17.832 UTC [91413] ERROR: relation "goose_db_version" does not exist at character 367662026-10-01 08:28:17.832 UTC [91413] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7672026-10-01 08:28:17.832 UTC [91410] ERROR: relation "goose_db_version" does not exist at character 367682026-10-01 08:28:17.832 UTC [91410] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026/10/01 08:28:17 OK 20241026095416_initial_model.sql (8.48ms)7702026/10/01 08:28:17 OK 20241026095416_initial_model.sql (8.5ms)7712026/10/01 08:28:17 OK 20241026095416_initial_model.sql (10.13ms)7722026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (673.92µs)7732026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (528.83µs)7742026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (825.63µs)7752026/10/01 08:28:17 OK 20241026095416_initial_model.sql (9.41ms)7762026/10/01 08:28:17 OK 20251218171726_add_pins.sql (2.21ms)7772026/10/01 08:28:17 OK 20251218171726_add_pins.sql (2.16ms)7782026/10/01 08:28:17 OK 20251218171726_add_pins.sql (1.9ms)7792026/10/01 08:28:17 OK 20241026095416_initial_model.sql (8.92ms)7802026/10/01 08:28:17 OK 20241026095416_initial_model.sql (9.33ms)7812026/10/01 08:28:17 OK 20241026095416_initial_model.sql (8.69ms)7822026/10/01 08:28:17 OK 20241026095416_initial_model.sql (8.68ms)7832026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)7842026/10/01 08:28:17 OK 20241026095416_initial_model.sql (9.15ms)7852026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (622.83µs)7862026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (638.13µs)7872026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (598.79µs)7882026/10/01 08:28:17 OK 20241026095416_initial_model.sql (9.85ms)7892026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.62ms)7902026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (922.67µs)7912026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (850.17µs)7922026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.59ms)7932026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (2.12ms)7942026/10/01 08:28:17 OK 20251210153512_drop_unused_gin_index.sql (891.58µs)7952026/10/01 08:28:17 OK 20251218171726_add_pins.sql (1.8ms)7962026/10/01 08:28:17 OK 20251218171726_add_pins.sql (2.05ms)7972026/10/01 08:28:17 OK 20251218171726_add_pins.sql (2.19ms)7982026/10/01 08:28:17 OK 20251218171726_add_pins.sql (2.04ms)7992026/10/01 08:28:17 OK 20251218171726_add_pins.sql (1.82ms)8002026/10/01 08:28:17 OK 20260905000000_add_claims.sql (1.95ms)8012026/10/01 08:28:17 OK 20251218171726_add_pins.sql (1.42ms)8022026/10/01 08:28:17 OK 20251218171726_add_pins.sql (2.09ms)8032026/10/01 08:28:17 OK 20260905000000_add_claims.sql (2.45ms)8042026/10/01 08:28:17 OK 20260905000000_add_claims.sql (2.18ms)8052026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (2.06ms)8062026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.46ms)8072026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.33ms)8082026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.61ms)8092026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.79ms)8102026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.39ms)8112026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.19ms)8122026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (1.59ms)8132026/10/01 08:28:17 OK 20260628120000_add_object_size_and_stats.sql (2.13ms)8142026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (956µs)8152026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008162026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.61ms)8172026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (703.38µs)8182026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008192026/10/01 08:28:17 OK 20260905000000_add_claims.sql (1.9ms)8202026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (1.29ms)8212026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008222026/10/01 08:28:17 OK 20260905000000_add_claims.sql (2.4ms)8232026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.55ms)8242026/10/01 08:28:17 OK 20260905000000_add_claims.sql (2.6ms)8252026/10/01 08:28:17 OK 20260905000000_add_claims.sql (2.4ms)8262026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.98ms)8272026/10/01 08:28:17 OK 20260905000000_add_claims.sql (2.3ms)8282026/10/01 08:28:17 OK 2_object_stats_trigger.sql (380.75µs)8292026/10/01 08:28:17 OK 20260905000000_add_claims.sql (3.62ms)8302026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (856.83µs)8312026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.63ms)8322026/10/01 08:28:17 OK 20260905000000_add_claims.sql (3.15ms)8332026/10/01 08:28:17 OK 2_object_stats_trigger.sql (589.33µs)8342026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (836.5µs)8352026/10/01 08:28:17 OK 3_commit_push.sql (505.96µs)8362026/10/01 08:28:17 goose: up to current file version: 38372026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (880.38µs)8382026/10/01 08:28:17 OK 3_commit_push.sql (430.25µs)8392026/10/01 08:28:17 goose: up to current file version: 38402026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.21ms)8412026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.8ms)8422026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (773.38µs)8432026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008442026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.06ms)8452026/10/01 08:28:17 OK 2_object_stats_trigger.sql (428.21µs)8462026/10/01 08:28:17 OK 20260920000000_drop_claims.sql (1.22ms)8472026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (627.92µs)8482026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008492026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (899.54µs)8502026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008512026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (1.18ms)8522026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008532026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (1.44ms)8542026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008552026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (582.42µs)8562026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008572026/10/01 08:28:17 OK 3_commit_push.sql (321.29µs)8582026/10/01 08:28:17 goose: up to current file version: 38592026/10/01 08:28:17 OK 20260923120000_add_pushes.sql (634.54µs)8602026/10/01 08:28:17 goose: successfully migrated database to version: 202609231200008612026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.43ms)8622026/10/01 08:28:17 OK 1_commit_pending_closure.sql (990.96µs)8632026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.01ms)8642026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.15ms)8652026/10/01 08:28:17 OK 2_object_stats_trigger.sql (327.58µs)8662026/10/01 08:28:17 OK 2_object_stats_trigger.sql (497µs)8672026/10/01 08:28:17 OK 2_object_stats_trigger.sql (291.5µs)8682026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.32ms)8692026/10/01 08:28:17 OK 1_commit_pending_closure.sql (977.71µs)8702026/10/01 08:28:17 OK 1_commit_pending_closure.sql (1.57ms)8712026/10/01 08:28:17 OK 3_commit_push.sql (256.08µs)8722026/10/01 08:28:17 goose: up to current file version: 38732026/10/01 08:28:17 OK 2_object_stats_trigger.sql (198.71µs)8742026/10/01 08:28:17 OK 2_object_stats_trigger.sql (462.75µs)8752026/10/01 08:28:17 OK 3_commit_push.sql (374.5µs)8762026/10/01 08:28:17 goose: up to current file version: 38772026/10/01 08:28:17 OK 3_commit_push.sql (411.71µs)8782026/10/01 08:28:17 goose: up to current file version: 38792026/10/01 08:28:17 OK 2_object_stats_trigger.sql (309.21µs)8802026/10/01 08:28:17 OK 3_commit_push.sql (206.71µs)8812026/10/01 08:28:17 goose: up to current file version: 38822026/10/01 08:28:17 OK 2_object_stats_trigger.sql (278.71µs)8832026/10/01 08:28:17 OK 3_commit_push.sql (192.08µs)8842026/10/01 08:28:17 goose: up to current file version: 38852026/10/01 08:28:17 OK 3_commit_push.sql (149.13µs)8862026/10/01 08:28:17 goose: up to current file version: 38872026/10/01 08:28:17 OK 3_commit_push.sql (135.67µs)8882026/10/01 08:28:17 goose: up to current file version: 38892026/10/01 08:28:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8902026/10/01 08:28:17 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst891--- PASS: TestCompleteMultipartUnregistered (0.44s)892=== CONT TestCompleteMultipartUpload_ErrorButObjectExists8932026/10/01 08:28:18 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"894--- PASS: TestService_AuthMiddleware (0.58s)895=== CONT TestUploadHandlersRejectOversizedBody896=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts897=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts898=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure899=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure900=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart901=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart902=== CONT TestRedundantMultipartUpload9032026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures9042026/10/01 08:28:18 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9052026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures906--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.84s)907=== CONT TestGCTaskStore_CompletedAllowsNewTask908--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)909=== CONT TestLeadEndsOnShutdown9102026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures9112026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures9122026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures9132026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures9142026/10/01 08:28:18 INFO Received cleanup request method=DELETE path=/api/pending_closures9152026/10/01 08:28:18 INFO Aborted multipart uploads count=09162026/10/01 08:28:18 INFO Received uploads request method=POST path=/api/pending_closures9172026/10/01 08:28:18 INFO Received cleanup request method=DELETE path=/api/pending_closures9182026/10/01 08:28:18 INFO Aborted multipart uploads count=19192026/10/01 08:28:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9202026-10-01 08:28:18.970 UTC [91412] ERROR: Closure does not exist: id=19212026-10-01 08:28:18.970 UTC [91412] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE9222026-10-01 08:28:18.970 UTC [91412] STATEMENT: -- name: CommitPendingClosure :exec923 SELECT commit_pending_closure($1::bigint)924 925--- PASS: TestService_cleanupPendingClosuresHandler (1.47s)926=== CONT TestLeadElectsOneAndHandsOver9272026-10-01 08:28:18.978 UTC [91423] ERROR: relation "goose_db_version" does not exist at character 369282026-10-01 08:28:18.978 UTC [91423] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9292026/10/01 08:28:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9302026/10/01 08:28:19 INFO Received uploads request method=POST path=/api/pending_closures9312026-10-01 08:28:19.126 UTC [91426] ERROR: relation "goose_db_version" does not exist at character 369322026-10-01 08:28:19.126 UTC [91426] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9332026/10/01 08:28:19 OK 20241026095416_initial_model.sql (100.53ms)9342026/10/01 08:28:19 OK 20251210153512_drop_unused_gin_index.sql (8.33ms)9352026/10/01 08:28:19 OK 20251218171726_add_pins.sql (48.24ms)9362026/10/01 08:28:19 OK 20260628120000_add_object_size_and_stats.sql (19.82ms)9372026/10/01 08:28:19 OK 20260905000000_add_claims.sql (30.59ms)9382026/10/01 08:28:19 OK 20260920000000_drop_claims.sql (40.98ms)9392026/10/01 08:28:19 OK 20260923120000_add_pushes.sql (17.69ms)9402026/10/01 08:28:19 goose: successfully migrated database to version: 202609231200009412026/10/01 08:28:19 OK 1_commit_pending_closure.sql (2.63ms)9422026/10/01 08:28:19 OK 2_object_stats_trigger.sql (519.71µs)9432026/10/01 08:28:19 OK 3_commit_push.sql (330.58µs)9442026/10/01 08:28:19 goose: up to current file version: 39452026/10/01 08:28:19 OK 20241026095416_initial_model.sql (147.82ms)9462026/10/01 08:28:19 OK 20251210153512_drop_unused_gin_index.sql (11.84ms)9472026/10/01 08:28:19 OK 20251218171726_add_pins.sql (14.56ms)9482026/10/01 08:28:19 OK 20260628120000_add_object_size_and_stats.sql (36.16ms)949--- PASS: TestService_Rustfstest (1.91s)950=== CONT TestPush_SignsNarinfosOfItsPendingObjects9512026/10/01 08:28:19 OK 20260905000000_add_claims.sql (77.88ms)9522026/10/01 08:28:19 OK 20260920000000_drop_claims.sql (15.27ms)9532026-10-01 08:28:19.488 UTC [91430] ERROR: relation "goose_db_version" does not exist at character 369542026-10-01 08:28:19.488 UTC [91430] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9552026/10/01 08:28:19 OK 20260923120000_add_pushes.sql (6.57ms)9562026/10/01 08:28:19 goose: successfully migrated database to version: 202609231200009572026/10/01 08:28:19 OK 1_commit_pending_closure.sql (2.17ms)9582026/10/01 08:28:19 OK 2_object_stats_trigger.sql (455.54µs)9592026/10/01 08:28:19 OK 3_commit_push.sql (344.71µs)9602026/10/01 08:28:19 goose: up to current file version: 39612026/10/01 08:28:19 INFO Received uploads request method=POST path=/api/pending_closures9622026/10/01 08:28:19 OK 20241026095416_initial_model.sql (134.28ms)9632026/10/01 08:28:19 OK 20251210153512_drop_unused_gin_index.sql (10.9ms)9642026/10/01 08:28:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9652026/10/01 08:28:19 OK 20251218171726_add_pins.sql (129.13ms)9662026/10/01 08:28:19 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTAwMGQzZmUtZTNjNy00MGQxLWFjZmUtYTFlNDBhOTFhNjQ4LmEzYjU0ZDVjLTU2MGUtNDk3OC1iNjM3LWE0NTNlYzEwNjlhY3gxNzkwODQzMjk4NDU2NjU1MDAw parts=109672026/10/01 08:28:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9682026/10/01 08:28:19 INFO Completed upload id=19692026/10/01 08:28:19 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009702026/10/01 08:28:19 INFO Received uploads request method=POST path=/api/pending_closures9712026/10/01 08:28:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures9722026/10/01 08:28:19 INFO Aborted multipart uploads count=09732026/10/01 08:28:19 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=09742026/10/01 08:28:19 OK 20260628120000_add_object_size_and_stats.sql (34.05ms)9752026/10/01 08:28:19 INFO Vacuumed table table=pending_closures9762026/10/01 08:28:19 INFO Vacuumed table table=pending_objects9772026/10/01 08:28:19 OK 20260905000000_add_claims.sql (28.88ms)9782026/10/01 08:28:19 INFO Vacuumed table table=multipart_uploads9792026/10/01 08:28:19 INFO Vacuumed table table=closures9802026/10/01 08:28:19 OK 20260920000000_drop_claims.sql (40.01ms)9812026/10/01 08:28:19 OK 20260923120000_add_pushes.sql (8.27ms)9822026/10/01 08:28:19 goose: successfully migrated database to version: 202609231200009832026/10/01 08:28:19 INFO Vacuumed table table=objects9842026/10/01 08:28:19 OK 1_commit_pending_closure.sql (2.5ms)9852026/10/01 08:28:19 OK 2_object_stats_trigger.sql (532.21µs)9862026/10/01 08:28:19 OK 3_commit_push.sql (338.38µs)9872026/10/01 08:28:19 goose: up to current file version: 39882026/10/01 08:28:19 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000989--- PASS: TestService_createPendingClosureHandler (2.43s)990=== CONT TestGCTaskStore_GetReturnsLatest991--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)992=== CONT TestPush_RejectsBadRequests9932026/10/01 08:28:19 INFO Received uploads request method=POST path=/api/pending_closures994--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.52s)995=== CONT TestGCTaskStore_GetEmpty996--- PASS: TestGCTaskStore_GetEmpty (0.00s)997=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9982026/10/01 08:28:20 INFO Received uploads request method=POST path=/api/pending_closures9992026/10/01 08:28:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10002026/10/01 08:28:20 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTAwMGQzZmUtZTNjNy00MGQxLWFjZmUtYTFlNDBhOTFhNjQ4LjUyODdjNmNkLTA1NDMtNDIwMS1hYmY0LWRmZmZkZTk2MDg5OXgxNzkwODQzMzAwMjUwNzA1MDAw10012026/10/01 08:28:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10022026/10/01 08:28:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTAwMGQzZmUtZTNjNy00MGQxLWFjZmUtYTFlNDBhOTFhNjQ4LjUyODdjNmNkLTA1NDMtNDIwMS1hYmY0LWRmZmZkZTk2MDg5OXgxNzkwODQzMzAwMjUwNzA1MDAw parts=11003--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.58s)1004=== CONT TestGCTaskStore_ConflictDifferentParams1005--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1006=== CONT TestPushDedupSurvivesConcurrentGC10072026/10/01 08:28:20 INFO Received uploads request method=POST path=/api/pending_closures10082026/10/01 08:28:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTAwMGQzZmUtZTNjNy00MGQxLWFjZmUtYTFlNDBhOTFhNjQ4LmZjOGM2NzM0LTI0YjQtNGM5NS1hZTA3LTEwNjgwNzJmZTllOXgxNzkwODQzMjk5MTM5MzUyMDAw parts=1010092026/10/01 08:28:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10102026/10/01 08:28:20 INFO Completed upload id=110112026/10/01 08:28:20 INFO Received uploads request method=POST path=/api/pending_closures10122026/10/01 08:28:20 INFO Received uploads request method=POST path=/api/pending_closures10132026/10/01 08:28:20 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10142026/10/01 08:28:20 WARN Found objects in DB but missing from S3, will re-upload count=11015--- PASS: TestService_verifyS3Integrity (3.12s)1016=== CONT TestPush_CompleteCommitsEveryRoot10172026/10/01 08:28:20 INFO Received uploads request method=POST path=/api/pending_closures10182026-10-01 08:28:20.739 UTC [91440] ERROR: relation "goose_db_version" does not exist at character 3610192026-10-01 08:28:20.739 UTC [91440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10202026/10/01 08:28:20 INFO lead: acquired remote=192.0.2.1:123410212026/10/01 08:28:20 INFO lead: released remote=192.0.2.1:12341022--- PASS: TestLeadEndsOnShutdown (2.50s)1023=== CONT TestGCMetrics10242026/10/01 08:28:20 OK 20241026095416_initial_model.sql (123.68ms)10252026/10/01 08:28:20 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)10262026/10/01 08:28:20 OK 20251218171726_add_pins.sql (1.85ms)10272026/10/01 08:28:20 OK 20260628120000_add_object_size_and_stats.sql (59.96ms)10282026-10-01 08:28:21.026 UTC [91443] ERROR: relation "goose_db_version" does not exist at character 3610292026-10-01 08:28:21.026 UTC [91443] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10302026/10/01 08:28:21 OK 20260905000000_add_claims.sql (34.41ms)10312026/10/01 08:28:21 OK 20260920000000_drop_claims.sql (2.48ms)10322026/10/01 08:28:21 OK 20260923120000_add_pushes.sql (1.7ms)10332026/10/01 08:28:21 goose: successfully migrated database to version: 2026092312000010342026/10/01 08:28:21 OK 1_commit_pending_closure.sql (2.75ms)10352026/10/01 08:28:21 OK 2_object_stats_trigger.sql (884.79µs)10362026/10/01 08:28:21 OK 3_commit_push.sql (455.92µs)10372026/10/01 08:28:21 goose: up to current file version: 310382026/10/01 08:28:21 OK 20241026095416_initial_model.sql (75.11ms)10392026/10/01 08:28:21 OK 20251210153512_drop_unused_gin_index.sql (12.96ms)10402026/10/01 08:28:21 OK 20251218171726_add_pins.sql (40.08ms)10412026/10/01 08:28:21 OK 20260628120000_add_object_size_and_stats.sql (45.74ms)10422026/10/01 08:28:21 OK 20260905000000_add_claims.sql (75.21ms)10432026/10/01 08:28:21 OK 20260920000000_drop_claims.sql (9.99ms)10442026/10/01 08:28:21 OK 20260923120000_add_pushes.sql (16.24ms)10452026/10/01 08:28:21 goose: successfully migrated database to version: 2026092312000010462026/10/01 08:28:21 OK 1_commit_pending_closure.sql (2.91ms)10472026/10/01 08:28:21 OK 2_object_stats_trigger.sql (525.13µs)10482026/10/01 08:28:21 OK 3_commit_push.sql (385.58µs)10492026/10/01 08:28:21 goose: up to current file version: 310502026/10/01 08:28:21 INFO lead: acquired remote=192.0.2.1:123410512026/10/01 08:28:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10522026/10/01 08:28:21 INFO lead: released remote=192.0.2.1:123410532026/10/01 08:28:21 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTAwMGQzZmUtZTNjNy00MGQxLWFjZmUtYTFlNDBhOTFhNjQ4LjIyNmY2NDQ2LTdlMTUtNDE0Ni04NTg3LTNlZjY5YjVhM2E3OHgxNzkwODQzMjk5Njk1MzQ5MDAw parts=1210542026/10/01 08:28:21 INFO Received uploads request method=POST path=/api/pending_closures1055--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.99s)1056=== CONT TestGCTaskStore_DeduplicateSameParams1057--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1058=== CONT TestGCBugBareHashReferences10592026/10/01 08:28:21 INFO lead: acquired remote=192.0.2.1:123410602026/10/01 08:28:21 INFO lead: released remote=192.0.2.1:12341061--- PASS: TestLeadElectsOneAndHandsOver (2.56s)1062=== CONT TestGCTaskStore_StartNew1063--- PASS: TestGCTaskStore_StartNew (0.00s)1064=== CONT TestGetExistingObjectsLocksRows10652026/10/01 08:28:21 INFO Received push request method=POST path=/api/pushes10662026/10/01 08:28:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10672026/10/01 08:28:21 INFO Signed narinfos id=1 count=11068--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.30s)1069=== CONT TestRegisterCompletedObjectNeedsPendingRow10702026-10-01 08:28:21.719 UTC [91451] ERROR: relation "goose_db_version" does not exist at character 3610712026-10-01 08:28:21.719 UTC [91451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10722026-10-01 08:28:21.721 UTC [91452] ERROR: relation "goose_db_version" does not exist at character 3610732026-10-01 08:28:21.721 UTC [91452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10742026/10/01 08:28:21 OK 20241026095416_initial_model.sql (29.29ms)10752026/10/01 08:28:21 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)10762026/10/01 08:28:21 OK 20241026095416_initial_model.sql (22.7ms)10772026/10/01 08:28:21 OK 20251210153512_drop_unused_gin_index.sql (972.17µs)10782026/10/01 08:28:21 OK 20251218171726_add_pins.sql (2.31ms)10792026/10/01 08:28:21 OK 20260628120000_add_object_size_and_stats.sql (18.27ms)10802026/10/01 08:28:21 OK 20251218171726_add_pins.sql (19.31ms)10812026/10/01 08:28:21 OK 20260628120000_add_object_size_and_stats.sql (26.65ms)10822026/10/01 08:28:21 OK 20260905000000_add_claims.sql (34.64ms)10832026/10/01 08:28:21 OK 20260905000000_add_claims.sql (10.89ms)10842026/10/01 08:28:21 OK 20260920000000_drop_claims.sql (3.47ms)10852026/10/01 08:28:21 OK 20260923120000_add_pushes.sql (2.22ms)10862026/10/01 08:28:21 goose: successfully migrated database to version: 2026092312000010872026/10/01 08:28:21 OK 20260920000000_drop_claims.sql (3.2ms)10882026/10/01 08:28:21 OK 1_commit_pending_closure.sql (2.14ms)10892026/10/01 08:28:21 OK 2_object_stats_trigger.sql (595µs)10902026/10/01 08:28:21 OK 3_commit_push.sql (517.58µs)10912026/10/01 08:28:21 goose: up to current file version: 310922026/10/01 08:28:21 OK 20260923120000_add_pushes.sql (16.72ms)10932026/10/01 08:28:21 goose: successfully migrated database to version: 2026092312000010942026/10/01 08:28:21 OK 1_commit_pending_closure.sql (1.66ms)10952026/10/01 08:28:21 OK 2_object_stats_trigger.sql (379.04µs)10962026/10/01 08:28:21 OK 3_commit_push.sql (268.71µs)10972026/10/01 08:28:21 goose: up to current file version: 310982026-10-01 08:28:21.941 UTC [91454] ERROR: relation "goose_db_version" does not exist at character 3610992026-10-01 08:28:21.941 UTC [91454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11002026-10-01 08:28:22.012 UTC [91455] ERROR: relation "goose_db_version" does not exist at character 3611012026-10-01 08:28:22.012 UTC [91455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11022026/10/01 08:28:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1103=== RUN TestPush_RejectsBadRequests/root_not_in_objects1104=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1105=== RUN TestPush_RejectsBadRequests/no_roots1106=== PAUSE TestPush_RejectsBadRequests/no_roots1107=== RUN TestPush_RejectsBadRequests/no_objects1108=== PAUSE TestPush_RejectsBadRequests/no_objects1109=== RUN TestPush_RejectsBadRequests/bad_root1110=== PAUSE TestPush_RejectsBadRequests/bad_root1111=== CONT TestParseSingleRange1112=== RUN TestParseSingleRange/none1113=== PAUSE TestParseSingleRange/none1114=== RUN TestParseSingleRange/unknown_unit1115=== PAUSE TestParseSingleRange/unknown_unit1116=== RUN TestParseSingleRange/multi-range_ignored1117=== PAUSE TestParseSingleRange/multi-range_ignored1118=== RUN TestParseSingleRange/malformed_no_dash1119=== PAUSE TestParseSingleRange/malformed_no_dash1120=== RUN TestParseSingleRange/malformed_both_empty1121=== PAUSE TestParseSingleRange/malformed_both_empty1122=== RUN TestParseSingleRange/malformed_end_before_start1123=== PAUSE TestParseSingleRange/malformed_end_before_start1124=== RUN TestParseSingleRange/closed1125=== PAUSE TestParseSingleRange/closed1126=== RUN TestParseSingleRange/open-ended1127=== PAUSE TestParseSingleRange/open-ended1128=== RUN TestParseSingleRange/end_clamped_to_size1129=== PAUSE TestParseSingleRange/end_clamped_to_size1130=== RUN TestParseSingleRange/suffix1131=== PAUSE TestParseSingleRange/suffix1132=== RUN TestParseSingleRange/suffix_exceeds_size1133=== PAUSE TestParseSingleRange/suffix_exceeds_size1134=== RUN TestParseSingleRange/single_byte1135=== PAUSE TestParseSingleRange/single_byte1136=== RUN TestParseSingleRange/start_past_EOF1137=== PAUSE TestParseSingleRange/start_past_EOF1138=== RUN TestParseSingleRange/start_far_past_EOF1139=== PAUSE TestParseSingleRange/start_far_past_EOF1140=== CONT TestSweepSkipsRowsLockedByPush11412026/10/01 08:28:22 OK 20241026095416_initial_model.sql (234.44ms)11422026/10/01 08:28:22 OK 20251210153512_drop_unused_gin_index.sql (5.7ms)11432026/10/01 08:28:22 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTAwMGQzZmUtZTNjNy00MGQxLWFjZmUtYTFlNDBhOTFhNjQ4LmRhOTc2NTg5LTFlZmYtNDE5OC1iOGI3LWYxODRjMmViOWQ2YngxNzkwODQzMzAwNTk4NDkzMDAw parts=121144--- PASS: TestRedundantMultipartUpload (4.13s)1145=== CONT TestFailedS3DeleteKeepsTombstone11462026/10/01 08:28:22 OK 20241026095416_initial_model.sql (192.29ms)11472026/10/01 08:28:22 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)11482026/10/01 08:28:22 OK 20251218171726_add_pins.sql (30.9ms)11492026/10/01 08:28:22 OK 20251218171726_add_pins.sql (24.9ms)11502026/10/01 08:28:22 OK 20260628120000_add_object_size_and_stats.sql (30.3ms)11512026/10/01 08:28:22 OK 20260628120000_add_object_size_and_stats.sql (27.43ms)11522026/10/01 08:28:22 OK 20260905000000_add_claims.sql (14.27ms)11532026/10/01 08:28:22 OK 20260905000000_add_claims.sql (37.51ms)11542026/10/01 08:28:22 OK 20260920000000_drop_claims.sql (16.58ms)11552026/10/01 08:28:22 OK 20260920000000_drop_claims.sql (31.33ms)11562026/10/01 08:28:22 OK 20260923120000_add_pushes.sql (17.38ms)11572026/10/01 08:28:22 goose: successfully migrated database to version: 2026092312000011582026-10-01 08:28:22.364 UTC [91460] ERROR: relation "goose_db_version" does not exist at character 3611592026-10-01 08:28:22.364 UTC [91460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11602026/10/01 08:28:22 OK 1_commit_pending_closure.sql (2.88ms)11612026/10/01 08:28:22 OK 2_object_stats_trigger.sql (497.17µs)11622026/10/01 08:28:22 OK 3_commit_push.sql (378.46µs)11632026/10/01 08:28:22 goose: up to current file version: 311642026/10/01 08:28:22 OK 20260923120000_add_pushes.sql (10.02ms)11652026/10/01 08:28:22 goose: successfully migrated database to version: 2026092312000011662026/10/01 08:28:22 OK 1_commit_pending_closure.sql (2.61ms)11672026/10/01 08:28:22 OK 2_object_stats_trigger.sql (531.21µs)11682026/10/01 08:28:22 OK 3_commit_push.sql (417.25µs)11692026/10/01 08:28:22 goose: up to current file version: 311702026/10/01 08:28:22 INFO Received push request method=POST path=/api/pushes11712026/10/01 08:28:22 INFO Received complete push request method=POST path=/api/pushes/1/complete11722026/10/01 08:28:22 INFO Received push request method=POST path=/api/pushes11732026/10/01 08:28:22 OK 20241026095416_initial_model.sql (113.34ms)11742026/10/01 08:28:22 OK 20251210153512_drop_unused_gin_index.sql (14.71ms)11752026/10/01 08:28:22 OK 20251218171726_add_pins.sql (10.36ms)11762026/10/01 08:28:22 OK 20260628120000_add_object_size_and_stats.sql (28.82ms)11772026/10/01 08:28:22 INFO Aborted multipart uploads count=011782026/10/01 08:28:22 WARN Force mode enabled - objects will be deleted immediately without grace period11792026/10/01 08:28: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=011802026/10/01 08:28:22 INFO Vacuumed table table=pending_closures11812026/10/01 08:28:22 OK 20260905000000_add_claims.sql (51.67ms)11822026/10/01 08:28:22 INFO Vacuumed table table=pending_objects11832026/10/01 08:28:22 OK 20260920000000_drop_claims.sql (29.03ms)11842026/10/01 08:28:22 INFO Vacuumed table table=multipart_uploads11852026/10/01 08:28:22 OK 20260923120000_add_pushes.sql (29.84ms)11862026/10/01 08:28:22 goose: successfully migrated database to version: 2026092312000011872026/10/01 08:28:22 INFO Vacuumed table table=closures11882026/10/01 08:28:22 OK 1_commit_pending_closure.sql (5.38ms)11892026/10/01 08:28:22 OK 2_object_stats_trigger.sql (1.07ms)11902026/10/01 08:28:22 OK 3_commit_push.sql (2.27ms)11912026/10/01 08:28:22 goose: up to current file version: 311922026/10/01 08:28:22 INFO Vacuumed table table=objects11932026/10/01 08:28:22 INFO Received complete push request method=POST path=/api/pushes/2/complete1194--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.68s)1195=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11962026/10/01 08:28:22 INFO Received uploads request method=POST path=/api/pending_closures11972026/10/01 08:28:22 INFO Aborted multipart uploads count=011982026/10/01 08:28:22 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=011992026/10/01 08:28:22 INFO Vacuumed table table=pending_closures12002026/10/01 08:28:22 INFO Vacuumed table table=pending_objects12012026/10/01 08:28:22 INFO Vacuumed table table=multipart_uploads12022026/10/01 08:28:22 INFO Vacuumed table table=closures12032026/10/01 08:28:22 INFO Vacuumed table table=objects12042026/10/01 08:28:22 INFO Received push request method=POST path=/api/pushes12052026/10/01 08:28:22 INFO Aborted multipart uploads count=012062026/10/01 08:28:22 WARN Force mode enabled - objects will be deleted immediately without grace period12072026/10/01 08:28:22 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012082026/10/01 08:28:22 INFO Vacuumed table table=pending_closures12092026/10/01 08:28:22 INFO Vacuumed table table=pending_objects12102026/10/01 08:28:22 INFO Vacuumed table table=multipart_uploads12112026/10/01 08:28:22 INFO Vacuumed table table=closures12122026/10/01 08:28:22 INFO Vacuumed table table=objects1213--- PASS: TestPushDedupSurvivesConcurrentGC (2.47s)1214=== CONT TestClientSharedPathCommittedMidPush12152026/10/01 08:28:23 INFO Received complete push request method=POST path=/api/pushes/1/complete1216--- PASS: TestPush_CompleteCommitsEveryRoot (2.42s)1217=== CONT TestForceGCDuringPushOffersSweptObject1218=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1219=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1220=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1221=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1222=== CONT TestReadRedirectUsesPublicS3URL12232026-10-01 08:28:23.055 UTC [91468] ERROR: relation "goose_db_version" does not exist at character 3612242026-10-01 08:28:23.055 UTC [91468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12252026-10-01 08:28:23.085 UTC [91471] ERROR: relation "goose_db_version" does not exist at character 3612262026-10-01 08:28:23.085 UTC [91471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12272026/10/01 08:28:23 WARN Rate limiter enabled after throttle name=s3-test rate=512282026/10/01 08:28:23 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1229=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1230 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101231 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001232--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.62s)1233=== CONT TestClientWithDependencies12342026-10-01 08:28:23.133 UTC [91472] ERROR: relation "goose_db_version" does not exist at character 3612352026-10-01 08:28:23.133 UTC [91472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12362026/10/01 08:28:23 INFO Aborted multipart uploads count=012372026/10/01 08:28:23 WARN Force mode enabled - objects will be deleted immediately without grace period12382026/10/01 08:28:23 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012392026/10/01 08:28:23 INFO Vacuumed table table=pending_closures12402026/10/01 08:28:23 INFO Vacuumed table table=pending_objects12412026/10/01 08:28:23 INFO Vacuumed table table=multipart_uploads12422026/10/01 08:28:23 INFO Vacuumed table table=closures12432026/10/01 08:28:23 INFO Vacuumed table table=objects1244--- PASS: TestGCMetrics (2.33s)1245=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12462026/10/01 08:28:23 OK 20241026095416_initial_model.sql (124.47ms)12472026/10/01 08:28:23 OK 20251210153512_drop_unused_gin_index.sql (8.62ms)12482026/10/01 08:28:23 OK 20251218171726_add_pins.sql (17.61ms)12492026/10/01 08:28:23 OK 20241026095416_initial_model.sql (114.78ms)12502026/10/01 08:28:23 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)12512026/10/01 08:28:23 OK 20260628120000_add_object_size_and_stats.sql (5.68ms)12522026/10/01 08:28:23 OK 20251218171726_add_pins.sql (3.55ms)12532026/10/01 08:28:23 OK 20260905000000_add_claims.sql (3.25ms)12542026/10/01 08:28:23 OK 20241026095416_initial_model.sql (67.48ms)12552026/10/01 08:28:23 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)12562026/10/01 08:28:23 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)12572026/10/01 08:28:23 OK 20260920000000_drop_claims.sql (2.08ms)12582026/10/01 08:28:23 OK 20260923120000_add_pushes.sql (1.65ms)12592026/10/01 08:28:23 goose: successfully migrated database to version: 2026092312000012602026/10/01 08:28:23 OK 20251218171726_add_pins.sql (2.55ms)12612026/10/01 08:28:23 OK 1_commit_pending_closure.sql (1.45ms)12622026/10/01 08:28:23 OK 2_object_stats_trigger.sql (276.75µs)12632026/10/01 08:28:23 OK 3_commit_push.sql (767.33µs)12642026/10/01 08:28:23 goose: up to current file version: 312652026/10/01 08:28:23 OK 20260905000000_add_claims.sql (12.35ms)12662026/10/01 08:28:23 OK 20260628120000_add_object_size_and_stats.sql (34.05ms)12672026/10/01 08:28:23 OK 20260920000000_drop_claims.sql (32.02ms)12682026/10/01 08:28:23 OK 20260923120000_add_pushes.sql (15.5ms)12692026/10/01 08:28:23 goose: successfully migrated database to version: 2026092312000012702026/10/01 08:28:23 OK 1_commit_pending_closure.sql (1.7ms)12712026/10/01 08:28:23 OK 2_object_stats_trigger.sql (403.29µs)12722026/10/01 08:28:23 OK 3_commit_push.sql (296.92µs)12732026/10/01 08:28:23 goose: up to current file version: 312742026/10/01 08:28:23 OK 20260905000000_add_claims.sql (38.94ms)12752026/10/01 08:28:23 OK 20260920000000_drop_claims.sql (14.03ms)12762026/10/01 08:28:23 OK 20260923120000_add_pushes.sql (14.87ms)12772026/10/01 08:28:23 goose: successfully migrated database to version: 2026092312000012782026/10/01 08:28:23 OK 1_commit_pending_closure.sql (4.08ms)12792026/10/01 08:28:23 OK 2_object_stats_trigger.sql (502.08µs)12802026/10/01 08:28:23 OK 3_commit_push.sql (469.25µs)12812026/10/01 08:28:23 goose: up to current file version: 312822026-10-01 08:28:23.651 UTC [91478] ERROR: relation "goose_db_version" does not exist at character 3612832026-10-01 08:28:23.651 UTC [91478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1284--- PASS: TestGCBugBareHashReferences (2.27s)1285=== CONT TestReadProxyRangeRequest12862026/10/01 08:28:23 OK 20241026095416_initial_model.sql (204.04ms)12872026/10/01 08:28:23 OK 20251210153512_drop_unused_gin_index.sql (9.16ms)1288--- PASS: TestGetExistingObjectsLocksRows (2.41s)1289=== CONT TestResolveDBConnectionString1290=== RUN TestResolveDBConnectionString/flag_wins1291=== PAUSE TestResolveDBConnectionString/flag_wins1292=== RUN TestResolveDBConnectionString/file_when_flag_empty1293=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1294=== RUN TestResolveDBConnectionString/missing_file_is_an_error1295=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1296=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1297=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1298=== RUN TestResolveDBConnectionString/nothing_configured1299=== PAUSE TestResolveDBConnectionString/nothing_configured1300=== CONT TestReadRedirectKeepsNarinfoProxied13012026/10/01 08:28:23 OK 20251218171726_add_pins.sql (20.38ms)13022026/10/01 08:28:23 OK 20260628120000_add_object_size_and_stats.sql (42.27ms)13032026/10/01 08:28:24 OK 20260905000000_add_claims.sql (55.89ms)13042026/10/01 08:28:24 OK 20260920000000_drop_claims.sql (25.14ms)13052026-10-01 08:28:24.081 UTC [91485] ERROR: relation "goose_db_version" does not exist at character 3613062026-10-01 08:28:24.081 UTC [91485] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13072026/10/01 08:28:24 OK 20260923120000_add_pushes.sql (20.72ms)13082026/10/01 08:28:24 goose: successfully migrated database to version: 2026092312000013092026/10/01 08:28:24 OK 1_commit_pending_closure.sql (3.57ms)13102026/10/01 08:28:24 OK 2_object_stats_trigger.sql (1.63ms)13112026/10/01 08:28:24 OK 3_commit_push.sql (517.25µs)13122026/10/01 08:28:24 goose: up to current file version: 31313--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.45s)1314=== CONT TestGCSweepDeliversEachKeyOnce13152026/10/01 08:28:24 OK 20241026095416_initial_model.sql (118.33ms)13162026/10/01 08:28:24 OK 20251210153512_drop_unused_gin_index.sql (16.82ms)13172026/10/01 08:28:24 OK 20251218171726_add_pins.sql (31.59ms)13182026/10/01 08:28:24 OK 20260628120000_add_object_size_and_stats.sql (47.35ms)13192026/10/01 08:28:24 OK 20260905000000_add_claims.sql (86.65ms)13202026/10/01 08:28:24 INFO Aborted multipart uploads count=013212026/10/01 08:28:24 WARN Force mode enabled - objects will be deleted immediately without grace period13222026/10/01 08:28:24 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013232026/10/01 08:28:24 OK 20260920000000_drop_claims.sql (62.8ms)13242026/10/01 08:28:24 INFO Vacuumed table table=pending_closures13252026/10/01 08:28:24 INFO Vacuumed table table=pending_objects13262026/10/01 08:28:24 INFO Vacuumed table table=multipart_uploads13272026/10/01 08:28:24 INFO Vacuumed table table=closures13282026/10/01 08:28:24 OK 20260923120000_add_pushes.sql (20.09ms)13292026/10/01 08:28:24 goose: successfully migrated database to version: 2026092312000013302026/10/01 08:28:24 OK 1_commit_pending_closure.sql (3.8ms)13312026/10/01 08:28:24 OK 2_object_stats_trigger.sql (665.17µs)13322026/10/01 08:28:24 OK 3_commit_push.sql (368.54µs)13332026/10/01 08:28:24 goose: up to current file version: 313342026/10/01 08:28:24 INFO Vacuumed table table=objects13352026/10/01 08:28:24 INFO Aborted multipart uploads count=013362026/10/01 08:28:24 WARN Force mode enabled - objects will be deleted immediately without grace period13372026/10/01 08:28:24 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=013382026/10/01 08:28:24 INFO Vacuumed table table=pending_closures13392026/10/01 08:28:24 INFO Vacuumed table table=pending_objects13402026/10/01 08:28:24 INFO Vacuumed table table=multipart_uploads13412026/10/01 08:28:24 INFO Vacuumed table table=closures13422026/10/01 08:28:24 INFO Vacuumed table table=objects1343--- PASS: TestSweepSkipsRowsLockedByPush (2.48s)1344=== CONT TestClientFallsBackToClosures13452026-10-01 08:28:24.706 UTC [91490] ERROR: relation "goose_db_version" does not exist at character 3613462026-10-01 08:28:24.706 UTC [91490] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13472026/10/01 08:28:24 INFO Received uploads request method=POST path=/api/pending_closures13482026/10/01 08:28:25 OK 20241026095416_initial_model.sql (318.23ms)13492026/10/01 08:28:25 OK 20251210153512_drop_unused_gin_index.sql (7.09ms)13502026-10-01 08:28:25.114 UTC [91493] ERROR: relation "goose_db_version" does not exist at character 3613512026-10-01 08:28:25.114 UTC [91493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13522026/10/01 08:28:25 INFO Aborted multipart uploads count=013532026/10/01 08:28:25 WARN Force mode enabled - objects will be deleted immediately without grace period13542026/10/01 08:28:25 OK 20251218171726_add_pins.sql (57ms)13552026/10/01 08:28:25 OK 20260628120000_add_object_size_and_stats.sql (13.45ms)13562026-10-01 08:28:25.178 UTC [91494] ERROR: relation "goose_db_version" does not exist at character 3613572026-10-01 08:28:25.178 UTC [91494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13582026/10/01 08:28:25 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."13592026/10/01 08:28:25 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."1360--- PASS: TestFailedS3DeleteKeepsTombstone (2.94s)1361=== CONT TestReadRedirectNar13622026/10/01 08:28:25 OK 20260905000000_add_claims.sql (19.46ms)13632026/10/01 08:28:25 OK 20260920000000_drop_claims.sql (39.81ms)13642026-10-01 08:28:25.237 UTC [91496] ERROR: relation "goose_db_version" does not exist at character 3613652026-10-01 08:28:25.237 UTC [91496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13662026/10/01 08:28:25 OK 20260923120000_add_pushes.sql (10.11ms)13672026/10/01 08:28:25 goose: successfully migrated database to version: 2026092312000013682026/10/01 08:28:25 OK 1_commit_pending_closure.sql (1.75ms)13692026/10/01 08:28:25 OK 2_object_stats_trigger.sql (411.5µs)13702026/10/01 08:28:25 OK 3_commit_push.sql (315.54µs)13712026/10/01 08:28:25 goose: up to current file version: 313722026-10-01 08:28:25.276 UTC [91499] ERROR: relation "goose_db_version" does not exist at character 3613732026-10-01 08:28:25.276 UTC [91499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13742026/10/01 08:28:25 OK 20241026095416_initial_model.sql (144.71ms)13752026/10/01 08:28:25 OK 20251210153512_drop_unused_gin_index.sql (10.11ms)13762026/10/01 08:28:25 OK 20251218171726_add_pins.sql (24.73ms)13772026/10/01 08:28:25 OK 20260628120000_add_object_size_and_stats.sql (27.59ms)13782026/10/01 08:28:25 OK 20241026095416_initial_model.sql (152.23ms)13792026/10/01 08:28:25 OK 20251210153512_drop_unused_gin_index.sql (8.58ms)13802026/10/01 08:28:25 OK 20241026095416_initial_model.sql (145.22ms)13812026/10/01 08:28:25 OK 20251210153512_drop_unused_gin_index.sql (21.67ms)13822026/10/01 08:28:25 OK 20251218171726_add_pins.sql (49.82ms)13832026/10/01 08:28:25 OK 20260905000000_add_claims.sql (74.66ms)13842026/10/01 08:28:25 OK 20260920000000_drop_claims.sql (23.47ms)13852026/10/01 08:28:25 OK 20251218171726_add_pins.sql (41.2ms)13862026/10/01 08:28:25 OK 20260628120000_add_object_size_and_stats.sql (50.05ms)13872026/10/01 08:28:25 OK 20260923120000_add_pushes.sql (28.83ms)13882026/10/01 08:28:25 goose: successfully migrated database to version: 2026092312000013892026/10/01 08:28:25 OK 1_commit_pending_closure.sql (4.69ms)13902026/10/01 08:28:25 OK 2_object_stats_trigger.sql (780.83µs)13912026/10/01 08:28:25 OK 3_commit_push.sql (545.38µs)13922026/10/01 08:28:25 goose: up to current file version: 313932026/10/01 08:28:25 OK 20241026095416_initial_model.sql (196.31ms)13942026/10/01 08:28:25 OK 20251210153512_drop_unused_gin_index.sql (16.91ms)13952026/10/01 08:28:25 OK 20260628120000_add_object_size_and_stats.sql (52.94ms)13962026/10/01 08:28:25 INFO Received push request method=POST path=/api/pushes13972026/10/01 08:28:25 OK 20260905000000_add_claims.sql (96.08ms)13982026/10/01 08:28:25 OK 20251218171726_add_pins.sql (56.19ms)13992026/10/01 08:28:25 OK 20260905000000_add_claims.sql (113.96ms)14002026/10/01 08:28:25 OK 20260920000000_drop_claims.sql (78.5ms)14012026/10/01 08:28:25 OK 20260628120000_add_object_size_and_stats.sql (85.23ms)14022026/10/01 08:28:25 OK 20260920000000_drop_claims.sql (63.71ms)14032026/10/01 08:28:25 OK 20260923120000_add_pushes.sql (44.38ms)14042026/10/01 08:28:25 goose: successfully migrated database to version: 2026092312000014052026/10/01 08:28:25 OK 1_commit_pending_closure.sql (4.65ms)14062026/10/01 08:28:25 OK 2_object_stats_trigger.sql (972.71µs)14072026/10/01 08:28:25 OK 3_commit_push.sql (769.79µs)14082026/10/01 08:28:25 goose: up to current file version: 31409--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.02s)1410=== CONT TestTombstonedObjectOfferedWithoutWaiting14112026/10/01 08:28:25 OK 20260923120000_add_pushes.sql (27.92ms)14122026/10/01 08:28:25 goose: successfully migrated database to version: 2026092312000014132026/10/01 08:28:25 OK 1_commit_pending_closure.sql (2.46ms)14142026/10/01 08:28:25 OK 2_object_stats_trigger.sql (480.75µs)14152026/10/01 08:28:25 OK 3_commit_push.sql (410.21µs)14162026/10/01 08:28:25 goose: up to current file version: 314172026/10/01 08:28:25 OK 20260905000000_add_claims.sql (98.45ms)14182026/10/01 08:28:25 OK 20260920000000_drop_claims.sql (27.62ms)14192026/10/01 08:28:25 OK 20260923120000_add_pushes.sql (11.15ms)14202026/10/01 08:28:25 goose: successfully migrated database to version: 2026092312000014212026/10/01 08:28:25 OK 1_commit_pending_closure.sql (2.81ms)14222026/10/01 08:28:25 OK 2_object_stats_trigger.sql (578.17µs)14232026/10/01 08:28:25 OK 3_commit_push.sql (346.67µs)14242026/10/01 08:28:25 goose: up to current file version: 31425--- PASS: TestReadRedirectUsesPublicS3URL (2.97s)1426=== CONT TestClientPushesUseOnePush14272026-10-01 08:28:26.198 UTC [91504] ERROR: relation "goose_db_version" does not exist at character 3614282026-10-01 08:28:26.198 UTC [91504] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14292026-10-01 08:28:26.493 UTC [91506] ERROR: relation "goose_db_version" does not exist at character 3614302026-10-01 08:28:26.493 UTC [91506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14312026/10/01 08:28:26 OK 20241026095416_initial_model.sql (264.45ms)14322026/10/01 08:28:26 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)14332026/10/01 08:28:26 OK 20251218171726_add_pins.sql (27.93ms)14342026/10/01 08:28:26 OK 20260628120000_add_object_size_and_stats.sql (29.96ms)14352026-10-01 08:28:26.599 UTC [91508] ERROR: relation "goose_db_version" does not exist at character 3614362026-10-01 08:28:26.599 UTC [91508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14372026/10/01 08:28:26 INFO Received uploads request method=POST path=/api/pending_closures14382026/10/01 08:28:26 OK 20260905000000_add_claims.sql (50.49ms)14392026/10/01 08:28:26 OK 20260920000000_drop_claims.sql (1.31ms)14402026/10/01 08:28:26 OK 20260923120000_add_pushes.sql (3.64ms)14412026/10/01 08:28:26 goose: successfully migrated database to version: 2026092312000014422026/10/01 08:28:26 OK 1_commit_pending_closure.sql (968.42µs)14432026/10/01 08:28:26 OK 2_object_stats_trigger.sql (221.58µs)14442026/10/01 08:28:26 OK 3_commit_push.sql (188.92µs)14452026/10/01 08:28:26 goose: up to current file version: 314462026/10/01 08:28:26 OK 20241026095416_initial_model.sql (111.44ms)14472026/10/01 08:28:26 OK 20251210153512_drop_unused_gin_index.sql (5.61ms)14482026/10/01 08:28:26 OK 20251218171726_add_pins.sql (8.74ms)14492026/10/01 08:28:26 OK 20241026095416_initial_model.sql (38.76ms)14502026/10/01 08:28:26 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)14512026/10/01 08:28:26 OK 20251218171726_add_pins.sql (9.83ms)14522026/10/01 08:28:26 OK 20260628120000_add_object_size_and_stats.sql (23.65ms)14532026/10/01 08:28:26 OK 20260628120000_add_object_size_and_stats.sql (19.52ms)14542026/10/01 08:28:26 OK 20260905000000_add_claims.sql (23.42ms)14552026/10/01 08:28:26 OK 20260920000000_drop_claims.sql (6.85ms)14562026/10/01 08:28:26 OK 20260905000000_add_claims.sql (14.42ms)14572026/10/01 08:28:26 OK 20260923120000_add_pushes.sql (9.27ms)14582026/10/01 08:28:26 goose: successfully migrated database to version: 2026092312000014592026/10/01 08:28:26 OK 1_commit_pending_closure.sql (862.75µs)14602026/10/01 08:28:26 OK 2_object_stats_trigger.sql (248.54µs)14612026/10/01 08:28:26 OK 3_commit_push.sql (191.92µs)14622026/10/01 08:28:26 goose: up to current file version: 314632026/10/01 08:28:26 INFO Received push request method=POST path=/api/pushes14642026/10/01 08:28:26 OK 20260920000000_drop_claims.sql (15.59ms)14652026-10-01 08:28:26.751 UTC [91514] ERROR: relation "goose_db_version" does not exist at character 3614662026-10-01 08:28:26.751 UTC [91514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14672026/10/01 08:28:26 OK 20260923120000_add_pushes.sql (8.15ms)14682026/10/01 08:28:26 goose: successfully migrated database to version: 2026092312000014692026/10/01 08:28:26 OK 1_commit_pending_closure.sql (826.96µs)14702026/10/01 08:28:26 OK 2_object_stats_trigger.sql (223.04µs)14712026/10/01 08:28:26 OK 3_commit_push.sql (192.08µs)14722026/10/01 08:28:26 goose: up to current file version: 314732026/10/01 08:28:26 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14742026/10/01 08:28:26 INFO Uploading lxza0z8h818v071k7sqfvdqar7g97drf-shared-dep (136B)14752026/10/01 08:28:26 INFO Uploading 8b7rihm5pi7qan3p7zsxbcns94nqwljz-top (256B)14762026/10/01 08:28:26 WARN Failed to register uploaded object key=8b7rihm5pi7qan3p7zsxbcns94nqwljz.ls error="server returned 404: 404 page not found\n"14772026/10/01 08:28:26 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14782026/10/01 08:28:26 WARN Failed to register uploaded object key=nar/12ynln66wmhi4njv9fajcpjmwfnv9wg4k2xgnhw13rximcv2k26v.nar.zst error="server returned 404: 404 page not found\n"14792026/10/01 08:28:26 WARN Failed to register uploaded object key=lxza0z8h818v071k7sqfvdqar7g97drf.ls error="server returned 404: 404 page not found\n"14802026/10/01 08:28:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14812026/10/01 08:28:26 INFO Signed narinfos id=1 count=214822026/10/01 08:28:26 INFO Uploading 2 narinfos14832026/10/01 08:28:26 WARN Failed to register uploaded object key=lxza0z8h818v071k7sqfvdqar7g97drf.narinfo error="server returned 404: 404 page not found\n"14842026/10/01 08:28:26 INFO Received complete push request method=POST path=/api/pushes/1/complete14852026/10/01 08:28:26 WARN Failed to register uploaded object key=8b7rihm5pi7qan3p7zsxbcns94nqwljz.narinfo error="server returned 404: 404 page not found\n"14862026/10/01 08:28:26 INFO Upload complete. (132ms)1487=== NAME TestClientSharedPathCommittedMidPush1488 client_integration_test.go:680: Retrieved narinfo from S3:1489 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientSharedPathCommittedMidPush1530648663/001/store/lxza0z8h818v071k7sqfvdqar7g97drf-shared-dep1490 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1491 Compression: zstd1492 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821493 NarSize: 1361494 References: 1495 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1496 client_integration_test.go:680: Retrieved narinfo from S3:1497 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientSharedPathCommittedMidPush1530648663/001/store/8b7rihm5pi7qan3p7zsxbcns94nqwljz-top1498 URL: nar/12ynln66wmhi4njv9fajcpjmwfnv9wg4k2xgnhw13rximcv2k26v.nar.zst1499 Compression: zstd1500 NarHash: sha256:12ynln66wmhi4njv9fajcpjmwfnv9wg4k2xgnhw13rximcv2k26v1501 NarSize: 2561502 References: /nix/var/nix/builds/nix-91269-3505625895/TestClientSharedPathCommittedMidPush1530648663/001/store/lxza0z8h818v071k7sqfvdqar7g97drf-shared-dep1503 CA: text:sha256:1w571isw6nnrh2459gmyhl1sl2334m52lrxrqg78mbxvr4qf6hda1504--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.66s)1505=== CONT TestReadProxyDisabled1506--- PASS: TestClientSharedPathCommittedMidPush (3.88s)1507=== CONT TestGCSweepSkipsPendingObjects15082026/10/01 08:28:26 OK 20241026095416_initial_model.sql (109.33ms)15092026/10/01 08:28:26 OK 20251210153512_drop_unused_gin_index.sql (9.85ms)15102026/10/01 08:28:26 OK 20251218171726_add_pins.sql (16.53ms)15112026/10/01 08:28:26 OK 20260628120000_add_object_size_and_stats.sql (26.83ms)15122026/10/01 08:28:26 OK 20260905000000_add_claims.sql (22.41ms)15132026/10/01 08:28:26 OK 20260920000000_drop_claims.sql (20.96ms)15142026/10/01 08:28:26 OK 20260923120000_add_pushes.sql (2.97ms)15152026/10/01 08:28:26 goose: successfully migrated database to version: 2026092312000015162026/10/01 08:28:27 OK 1_commit_pending_closure.sql (926.58µs)15172026/10/01 08:28:27 OK 2_object_stats_trigger.sql (235.17µs)15182026/10/01 08:28:27 OK 3_commit_push.sql (192.42µs)15192026/10/01 08:28:27 goose: up to current file version: 31520--- PASS: TestReadProxyRangeRequest (3.24s)1521=== CONT TestPinProtectsFromGC15222026-10-01 08:28:27.072 UTC [91527] ERROR: relation "goose_db_version" does not exist at character 3615232026-10-01 08:28:27.072 UTC [91527] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1524=== NAME TestClientWithDependencies1525 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-91269-3505625895/TestClientWithDependencies674344464/001/store/k511i8n1z1wi2yqlsv87y2hld4z7m497-test-script1526 client_integration_test.go:615: Found 1 dependencies (including self)15272026/10/01 08:28:27 OK 20241026095416_initial_model.sql (75.13ms)15282026/10/01 08:28:27 OK 20251210153512_drop_unused_gin_index.sql (10.13ms)15292026/10/01 08:28:27 OK 20251218171726_add_pins.sql (11.65ms)1530--- PASS: TestReadRedirectKeepsNarinfoProxied (3.27s)1531=== CONT TestReadProxyRootRedirectsToIndexHTML15322026/10/01 08:28:27 INFO Received push request method=POST path=/api/pushes15332026/10/01 08:28:27 OK 20260628120000_add_object_size_and_stats.sql (41.15ms)15342026/10/01 08:28:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15352026/10/01 08:28:27 INFO Uploading k511i8n1z1wi2yqlsv87y2hld4z7m497-test-script (136B)15362026/10/01 08:28:27 OK 20260905000000_add_claims.sql (29.55ms)15372026/10/01 08:28:27 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15382026/10/01 08:28:27 WARN Failed to register uploaded object key=k511i8n1z1wi2yqlsv87y2hld4z7m497.ls error="server returned 404: 404 page not found\n"15392026/10/01 08:28:27 WARN Failed to register uploaded object key=log/kv2f5cshl3kvriv47s46knai2rgkk1zb-test-script.drv error="server returned 404: 404 page not found\n"15402026/10/01 08:28:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15412026/10/01 08:28:27 INFO Signed narinfos id=1 count=115422026/10/01 08:28:27 INFO Uploading 1 narinfos15432026/10/01 08:28:27 OK 20260920000000_drop_claims.sql (45.66ms)15442026-10-01 08:28:27.320 UTC [91536] ERROR: relation "goose_db_version" does not exist at character 3615452026-10-01 08:28:27.320 UTC [91536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15462026/10/01 08:28:27 INFO Received complete push request method=POST path=/api/pushes/1/complete15472026/10/01 08:28:27 WARN Failed to register uploaded object key=k511i8n1z1wi2yqlsv87y2hld4z7m497.narinfo error="server returned 404: 404 page not found\n"15482026/10/01 08:28:27 OK 20260923120000_add_pushes.sql (3.37ms)15492026/10/01 08:28:27 goose: successfully migrated database to version: 2026092312000015502026/10/01 08:28:27 OK 1_commit_pending_closure.sql (1.06ms)15512026/10/01 08:28:27 OK 2_object_stats_trigger.sql (232.13µs)15522026/10/01 08:28:27 OK 3_commit_push.sql (170.17µs)15532026/10/01 08:28:27 goose: up to current file version: 315542026/10/01 08:28:27 INFO Upload complete. (157ms)1555=== NAME TestClientWithDependencies1556 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-91269-3505625895/TestClientWithDependencies674344464/001/store) requires matching store prefix1557--- PASS: TestClientWithDependencies (4.30s)1558=== CONT TestDeduplicatedObjectsRecordedAsPending15592026/10/01 08:28:27 OK 20241026095416_initial_model.sql (140.3ms)15602026-10-01 08:28:27.527 UTC [91539] ERROR: relation "goose_db_version" does not exist at character 3615612026-10-01 08:28:27.527 UTC [91539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15622026/10/01 08:28:27 INFO Aborted multipart uploads count=015632026/10/01 08:28:27 OK 20251210153512_drop_unused_gin_index.sql (7.18ms)15642026/10/01 08:28:27 WARN Force mode enabled - objects will be deleted immediately without grace period15652026/10/01 08:28:27 OK 20251218171726_add_pins.sql (30.18ms)15662026/10/01 08:28:27 OK 20260628120000_add_object_size_and_stats.sql (35.98ms)15672026/10/01 08:28:27 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=015682026/10/01 08:28:27 INFO Vacuumed table table=pending_closures15692026/10/01 08:28:27 INFO Vacuumed table table=pending_objects15702026/10/01 08:28:27 INFO Vacuumed table table=multipart_uploads15712026/10/01 08:28:27 INFO Vacuumed table table=closures15722026/10/01 08:28:27 INFO Vacuumed table table=objects1573--- PASS: TestGCSweepDeliversEachKeyOnce (3.48s)1574=== CONT TestReadProxyConditionalGet15752026/10/01 08:28:27 OK 20260905000000_add_claims.sql (40.14ms)15762026/10/01 08:28:27 OK 20260920000000_drop_claims.sql (47.53ms)15772026/10/01 08:28:27 OK 20260923120000_add_pushes.sql (6.62ms)15782026/10/01 08:28:27 goose: successfully migrated database to version: 2026092312000015792026/10/01 08:28:27 OK 1_commit_pending_closure.sql (2.65ms)15802026/10/01 08:28:27 OK 2_object_stats_trigger.sql (549.5µs)15812026/10/01 08:28:27 OK 3_commit_push.sql (318.25µs)15822026/10/01 08:28:27 goose: up to current file version: 315832026/10/01 08:28:27 OK 20241026095416_initial_model.sql (149.86ms)15842026/10/01 08:28:27 OK 20251210153512_drop_unused_gin_index.sql (2.94ms)15852026/10/01 08:28:27 OK 20251218171726_add_pins.sql (26.11ms)15862026/10/01 08:28:27 OK 20260628120000_add_object_size_and_stats.sql (28.9ms)15872026/10/01 08:28:27 OK 20260905000000_add_claims.sql (40.72ms)15882026/10/01 08:28:27 OK 20260920000000_drop_claims.sql (15.45ms)15892026/10/01 08:28:27 OK 20260923120000_add_pushes.sql (9.61ms)15902026/10/01 08:28:27 goose: successfully migrated database to version: 2026092312000015912026/10/01 08:28:27 OK 1_commit_pending_closure.sql (1.47ms)15922026/10/01 08:28:27 OK 2_object_stats_trigger.sql (271.88µs)15932026/10/01 08:28:27 OK 3_commit_push.sql (231.88µs)15942026/10/01 08:28:27 goose: up to current file version: 31595--- PASS: TestReadRedirectNar (2.78s)1596=== CONT TestCreatePin_ReservedPins15972026/10/01 08:28:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60583/oidc15982026-10-01 08:28:28.131 UTC [91551] ERROR: relation "goose_db_version" does not exist at character 3615992026-10-01 08:28:28.131 UTC [91551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16002026/10/01 08:28:28 INFO Received uploads request method=POST path=/api/pending_closures16012026/10/01 08:28:28 INFO Received uploads request method=POST path=/api/pending_closures16022026-10-01 08:28:28.225 UTC [91556] ERROR: relation "goose_db_version" does not exist at character 3616032026-10-01 08:28:28.225 UTC [91556] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1604--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.51s)1605=== CONT TestReadProxyHead16062026/10/01 08:28:28 INFO Received uploads request method=POST path=/api/pending_closures16072026/10/01 08:28:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16082026/10/01 08:28:28 INFO Uploading 6m57zjhnp1mny86770pga8kw3hnfjh0d-a (248B)16092026/10/01 08:28:28 INFO Uploading c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0-shared-dep (136B)16102026/10/01 08:28:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16112026/10/01 08:28:28 WARN Failed to register uploaded object key=1667zfka9k39rzx1xdggrk2ayfkwvwi8.ls error="server returned 404: 404 page not found\n"16122026/10/01 08:28:28 WARN Failed to register uploaded object key=c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0.ls error="server returned 404: 404 page not found\n"16132026/10/01 08:28:28 WARN Failed to register uploaded object key=nar/0zaqlckslm678frid38qw5mrk68j1n4jyzs5fb2gjwgk8759nhbm.nar.zst error="server returned 404: 404 page not found\n"16142026/10/01 08:28:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16152026/10/01 08:28:28 WARN Failed to register uploaded object key=6m57zjhnp1mny86770pga8kw3hnfjh0d.ls error="server returned 404: 404 page not found\n"16162026/10/01 08:28:28 INFO Signed narinfos id=1 count=216172026/10/01 08:28:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16182026/10/01 08:28:28 INFO Signed narinfos id=2 count=216192026/10/01 08:28:28 INFO Uploading 4 narinfos16202026/10/01 08:28:28 WARN Failed to register uploaded object key=1667zfka9k39rzx1xdggrk2ayfkwvwi8.narinfo error="server returned 404: 404 page not found\n"16212026/10/01 08:28:28 WARN Failed to register uploaded object key=6m57zjhnp1mny86770pga8kw3hnfjh0d.narinfo error="server returned 404: 404 page not found\n"16222026/10/01 08:28:28 WARN Failed to register uploaded object key=c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0.narinfo error="server returned 404: 404 page not found\n"16232026/10/01 08:28:28 OK 20241026095416_initial_model.sql (141.85ms)16242026/10/01 08:28:28 OK 20251210153512_drop_unused_gin_index.sql (5.38ms)16252026/10/01 08:28:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16262026/10/01 08:28:28 WARN Failed to register uploaded object key=c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0.narinfo error="server returned 404: 404 page not found\n"16272026/10/01 08:28:28 OK 20251218171726_add_pins.sql (26.25ms)16282026/10/01 08:28:28 INFO Completed upload id=116292026/10/01 08:28:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16302026/10/01 08:28:28 INFO Completed upload id=216312026/10/01 08:28:28 INFO Upload complete. (211ms)1632=== NAME TestClientFallsBackToClosures1633 client_pushes_test.go:112: Retrieved narinfo from S3:1634 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientFallsBackToClosures624237648/001/store/c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0-shared-dep1635 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1636 Compression: zstd1637 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821638 NarSize: 1361639 References: 1640 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1641 client_pushes_test.go:112: Retrieved narinfo from S3:1642 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientFallsBackToClosures624237648/001/store/6m57zjhnp1mny86770pga8kw3hnfjh0d-a1643 URL: nar/0zaqlckslm678frid38qw5mrk68j1n4jyzs5fb2gjwgk8759nhbm.nar.zst1644 Compression: zstd1645 NarHash: sha256:0zaqlckslm678frid38qw5mrk68j1n4jyzs5fb2gjwgk8759nhbm1646 NarSize: 2481647 References: /nix/var/nix/builds/nix-91269-3505625895/TestClientFallsBackToClosures624237648/001/store/c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0-shared-dep1648 CA: text:sha256:1ama94ki5f1nmi5x02gs60sq5y1pn1x9mjajisaisz18x17wyl351649 client_pushes_test.go:112: Retrieved narinfo from S3:1650 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientFallsBackToClosures624237648/001/store/1667zfka9k39rzx1xdggrk2ayfkwvwi8-b1651 URL: nar/0zaqlckslm678frid38qw5mrk68j1n4jyzs5fb2gjwgk8759nhbm.nar.zst1652 Compression: zstd1653 NarHash: sha256:0zaqlckslm678frid38qw5mrk68j1n4jyzs5fb2gjwgk8759nhbm1654 NarSize: 2481655 References: /nix/var/nix/builds/nix-91269-3505625895/TestClientFallsBackToClosures624237648/001/store/c58f3jn5avzbj4xs9mwnw9mm9h0wdyl0-shared-dep1656 CA: text:sha256:1ama94ki5f1nmi5x02gs60sq5y1pn1x9mjajisaisz18x17wyl3516572026/10/01 08:28:28 OK 20260628120000_add_object_size_and_stats.sql (41.17ms)16582026-10-01 08:28:28.407 UTC [91559] ERROR: relation "goose_db_version" does not exist at character 3616592026-10-01 08:28:28.407 UTC [91559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1660--- PASS: TestClientFallsBackToClosures (3.79s)1661=== CONT TestOrphanedObjectsGCStressTest16622026/10/01 08:28:28 OK 20260905000000_add_claims.sql (53.55ms)16632026/10/01 08:28:28 OK 20260920000000_drop_claims.sql (19.32ms)16642026/10/01 08:28:28 OK 20241026095416_initial_model.sql (161.26ms)16652026/10/01 08:28:28 OK 20260923120000_add_pushes.sql (8.03ms)16662026/10/01 08:28:28 goose: successfully migrated database to version: 2026092312000016672026/10/01 08:28:28 OK 1_commit_pending_closure.sql (1.37ms)16682026/10/01 08:28:28 OK 2_object_stats_trigger.sql (305.92µs)16692026/10/01 08:28:28 OK 3_commit_push.sql (325.58µs)16702026/10/01 08:28:28 goose: up to current file version: 316712026/10/01 08:28:28 OK 20251210153512_drop_unused_gin_index.sql (12.19ms)16722026/10/01 08:28:28 OK 20251218171726_add_pins.sql (29.23ms)16732026/10/01 08:28:28 OK 20260628120000_add_object_size_and_stats.sql (32.78ms)16742026/10/01 08:28:28 OK 20241026095416_initial_model.sql (139.94ms)16752026/10/01 08:28:28 OK 20260905000000_add_claims.sql (57.22ms)16762026/10/01 08:28:28 OK 20251210153512_drop_unused_gin_index.sql (878.71µs)16772026/10/01 08:28:28 OK 20260920000000_drop_claims.sql (5.22ms)16782026/10/01 08:28:28 OK 20260923120000_add_pushes.sql (12.96ms)16792026/10/01 08:28:28 goose: successfully migrated database to version: 2026092312000016802026/10/01 08:28:28 OK 20251218171726_add_pins.sql (17.44ms)16812026/10/01 08:28:28 OK 1_commit_pending_closure.sql (1.83ms)16822026/10/01 08:28:28 OK 2_object_stats_trigger.sql (295.08µs)16832026/10/01 08:28:28 OK 3_commit_push.sql (592.5µs)16842026/10/01 08:28:28 goose: up to current file version: 316852026/10/01 08:28:28 OK 20260628120000_add_object_size_and_stats.sql (8.39ms)16862026-10-01 08:28:28.622 UTC [91565] ERROR: relation "goose_db_version" does not exist at character 3616872026-10-01 08:28:28.622 UTC [91565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16882026/10/01 08:28:28 OK 20260905000000_add_claims.sql (28.19ms)16892026/10/01 08:28:28 OK 20260920000000_drop_claims.sql (16.21ms)16902026/10/01 08:28:28 OK 20260923120000_add_pushes.sql (22.01ms)16912026/10/01 08:28:28 goose: successfully migrated database to version: 2026092312000016922026/10/01 08:28:28 OK 1_commit_pending_closure.sql (1.66ms)16932026/10/01 08:28:28 OK 2_object_stats_trigger.sql (296.25µs)16942026/10/01 08:28:28 OK 3_commit_push.sql (183.71µs)16952026/10/01 08:28:28 goose: up to current file version: 31696--- PASS: TestReadProxyDisabled (1.85s)1697=== CONT TestObjectStatsTrigger16982026/10/01 08:28:28 OK 20241026095416_initial_model.sql (100.16ms)16992026/10/01 08:28:28 OK 20251210153512_drop_unused_gin_index.sql (6.83ms)17002026/10/01 08:28:28 OK 20251218171726_add_pins.sql (20.24ms)17012026/10/01 08:28:28 OK 20260628120000_add_object_size_and_stats.sql (14.79ms)17022026/10/01 08:28:28 OK 20260905000000_add_claims.sql (23.88ms)17032026-10-01 08:28:28.827 UTC [91574] ERROR: relation "goose_db_version" does not exist at character 3617042026-10-01 08:28:28.827 UTC [91574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17052026/10/01 08:28:28 INFO Received push request method=POST path=/api/pushes17062026/10/01 08:28:28 OK 20260920000000_drop_claims.sql (8.91ms)17072026/10/01 08:28:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17082026/10/01 08:28:28 INFO Uploading gf12590ndwnsq3cpihzis3nd2wfsiq00-a (248B)17092026/10/01 08:28:28 INFO Uploading fm5la4f1bc40hsnax95c53j5b3iq8vyv-shared-dep (136B)17102026/10/01 08:28:28 OK 20260923120000_add_pushes.sql (14.22ms)17112026/10/01 08:28:28 goose: successfully migrated database to version: 2026092312000017122026/10/01 08:28:28 OK 1_commit_pending_closure.sql (954.67µs)17132026/10/01 08:28:28 OK 2_object_stats_trigger.sql (596.88µs)17142026/10/01 08:28:28 OK 3_commit_push.sql (228.21µs)17152026/10/01 08:28:28 goose: up to current file version: 317162026/10/01 08:28:28 WARN Failed to register uploaded object key=5jh1k5v40isdqrp8sj1xgj0ysdz9qw7x.ls error="server returned 404: 404 page not found\n"17172026/10/01 08:28:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17182026/10/01 08:28:28 WARN Failed to register uploaded object key=fm5la4f1bc40hsnax95c53j5b3iq8vyv.ls error="server returned 404: 404 page not found\n"17192026/10/01 08:28:28 WARN Failed to register uploaded object key=gf12590ndwnsq3cpihzis3nd2wfsiq00.ls error="server returned 404: 404 page not found\n"17202026/10/01 08:28:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17212026/10/01 08:28:28 WARN Failed to register uploaded object key=nar/0sxii538jacwwbbsi81xh6qn1k0rqdb263k91p35s77ia696s9rr.nar.zst error="server returned 404: 404 page not found\n"17222026/10/01 08:28:28 INFO Signed narinfos id=1 count=317232026/10/01 08:28:28 INFO Uploading 3 narinfos17242026/10/01 08:28:28 WARN Failed to register uploaded object key=gf12590ndwnsq3cpihzis3nd2wfsiq00.narinfo error="server returned 404: 404 page not found\n"17252026/10/01 08:28:28 INFO Received complete push request method=POST path=/api/pushes/1/complete17262026/10/01 08:28:28 WARN Failed to register uploaded object key=5jh1k5v40isdqrp8sj1xgj0ysdz9qw7x.narinfo error="server returned 404: 404 page not found\n"17272026/10/01 08:28:28 WARN Failed to register uploaded object key=fm5la4f1bc40hsnax95c53j5b3iq8vyv.narinfo error="server returned 404: 404 page not found\n"17282026/10/01 08:28:28 INFO Upload complete. (118ms)1729=== NAME TestClientPushesUseOnePush1730 client_pushes_test.go:97: Retrieved narinfo from S3:1731 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientPushesUseOnePush4218765917/001/store/fm5la4f1bc40hsnax95c53j5b3iq8vyv-shared-dep1732 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1733 Compression: zstd1734 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821735 NarSize: 1361736 References: 1737 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17382026/10/01 08:28:28 INFO Received uploads request method=POST path=/api/pending_closures1739 client_pushes_test.go:97: Retrieved narinfo from S3:1740 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientPushesUseOnePush4218765917/001/store/gf12590ndwnsq3cpihzis3nd2wfsiq00-a1741 URL: nar/0sxii538jacwwbbsi81xh6qn1k0rqdb263k91p35s77ia696s9rr.nar.zst1742 Compression: zstd1743 NarHash: sha256:0sxii538jacwwbbsi81xh6qn1k0rqdb263k91p35s77ia696s9rr1744 NarSize: 2481745 References: /nix/var/nix/builds/nix-91269-3505625895/TestClientPushesUseOnePush4218765917/001/store/fm5la4f1bc40hsnax95c53j5b3iq8vyv-shared-dep1746 CA: text:sha256:1gmyzlif8bzpnzk32gqxxp3kq96ykv54wpcjxqn93wlhg38205fc1747 client_pushes_test.go:97: Retrieved narinfo from S3:1748 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientPushesUseOnePush4218765917/001/store/5jh1k5v40isdqrp8sj1xgj0ysdz9qw7x-b1749 URL: nar/0sxii538jacwwbbsi81xh6qn1k0rqdb263k91p35s77ia696s9rr.nar.zst1750 Compression: zstd1751 NarHash: sha256:0sxii538jacwwbbsi81xh6qn1k0rqdb263k91p35s77ia696s9rr1752 NarSize: 2481753 References: /nix/var/nix/builds/nix-91269-3505625895/TestClientPushesUseOnePush4218765917/001/store/fm5la4f1bc40hsnax95c53j5b3iq8vyv-shared-dep1754 CA: text:sha256:1gmyzlif8bzpnzk32gqxxp3kq96ykv54wpcjxqn93wlhg38205fc17552026/10/01 08:28:28 OK 20241026095416_initial_model.sql (99.82ms)17562026/10/01 08:28:28 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)1757--- PASS: TestClientPushesUseOnePush (2.95s)1758=== CONT TestOrphanedObjectsGC17592026/10/01 08:28:28 INFO Aborted multipart uploads count=017602026/10/01 08:28:28 WARN Force mode enabled - objects will be deleted immediately without grace period17612026/10/01 08:28:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017622026/10/01 08:28:28 INFO Vacuumed table table=pending_closures17632026/10/01 08:28:29 OK 20251218171726_add_pins.sql (43.1ms)17642026/10/01 08:28:29 INFO Vacuumed table table=pending_objects17652026/10/01 08:28:29 INFO Vacuumed table table=multipart_uploads17662026/10/01 08:28:29 INFO Vacuumed table table=closures17672026-10-01 08:28:29.019 UTC [91576] ERROR: relation "goose_db_version" does not exist at character 3617682026-10-01 08:28:29.019 UTC [91576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17692026/10/01 08:28:29 INFO Vacuumed table table=objects17702026/10/01 08:28:29 OK 20260628120000_add_object_size_and_stats.sql (25.55ms)1771--- PASS: TestGCSweepSkipsPendingObjects (2.21s)1772=== CONT TestService_ReadScope_PublicByDefault17732026/10/01 08:28:29 OK 20260905000000_add_claims.sql (66.02ms)17742026/10/01 08:28:29 OK 20260920000000_drop_claims.sql (33.79ms)17752026/10/01 08:28:29 OK 20260923120000_add_pushes.sql (6.34ms)17762026/10/01 08:28:29 goose: successfully migrated database to version: 2026092312000017772026/10/01 08:28:29 OK 1_commit_pending_closure.sql (1.91ms)17782026/10/01 08:28:29 OK 2_object_stats_trigger.sql (361.21µs)17792026/10/01 08:28:29 OK 3_commit_push.sql (272.96µs)17802026/10/01 08:28:29 goose: up to current file version: 317812026/10/01 08:28:29 OK 20241026095416_initial_model.sql (118.08ms)17822026/10/01 08:28:29 OK 20251210153512_drop_unused_gin_index.sql (19.32ms)17832026/10/01 08:28:29 OK 20251218171726_add_pins.sql (29.47ms)17842026/10/01 08:28:29 OK 20260628120000_add_object_size_and_stats.sql (11.4ms)17852026-10-01 08:28:29.302 UTC [91584] ERROR: relation "goose_db_version" does not exist at character 3617862026-10-01 08:28:29.302 UTC [91584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17872026/10/01 08:28:29 OK 20260905000000_add_claims.sql (34.88ms)17882026/10/01 08:28:29 OK 20260920000000_drop_claims.sql (31.78ms)17892026/10/01 08:28:29 OK 20260923120000_add_pushes.sql (15.35ms)17902026/10/01 08:28:29 goose: successfully migrated database to version: 2026092312000017912026/10/01 08:28:29 OK 1_commit_pending_closure.sql (1.6ms)17922026/10/01 08:28:29 OK 2_object_stats_trigger.sql (312.58µs)17932026/10/01 08:28:29 OK 3_commit_push.sql (268.33µs)17942026/10/01 08:28:29 goose: up to current file version: 31795--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.17s)1796=== CONT TestMultipartCleanup1797=== NAME TestPinProtectsFromGC1798 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-91269-3505625895/TestPinProtectsFromGC3084315340/001/store/7y4bxf423p3lbcq57q7zv95dimi9cab6-pinned-file.txt1799 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-91269-3505625895/TestPinProtectsFromGC3084315340/001/store/s7da7sdmx0y70afjas3qahghlsqjg4aw-unpinned-file.txt18002026/10/01 08:28:29 OK 20241026095416_initial_model.sql (137.74ms)18012026/10/01 08:28:29 OK 20251210153512_drop_unused_gin_index.sql (836.08µs)18022026-10-01 08:28:29.513 UTC [91591] ERROR: relation "goose_db_version" does not exist at character 3618032026-10-01 08:28:29.513 UTC [91591] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18042026/10/01 08:28:29 OK 20251218171726_add_pins.sql (17.95ms)18052026/10/01 08:28:29 OK 20260628120000_add_object_size_and_stats.sql (15.14ms)18062026/10/01 08:28:29 INFO Received push request method=POST path=/api/pushes18072026/10/01 08:28:29 OK 20260905000000_add_claims.sql (37.6ms)18082026/10/01 08:28:29 OK 20260920000000_drop_claims.sql (7.08ms)18092026/10/01 08:28:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18102026/10/01 08:28:29 INFO Uploading 7y4bxf423p3lbcq57q7zv95dimi9cab6-pinned-file.txt (128B)18112026/10/01 08:28:29 OK 20260923120000_add_pushes.sql (7.2ms)18122026/10/01 08:28:29 goose: successfully migrated database to version: 2026092312000018132026/10/01 08:28:29 OK 1_commit_pending_closure.sql (897.29µs)18142026/10/01 08:28:29 OK 2_object_stats_trigger.sql (242.21µs)18152026/10/01 08:28:29 OK 3_commit_push.sql (188.25µs)18162026/10/01 08:28:29 goose: up to current file version: 318172026/10/01 08:28:29 WARN Failed to register uploaded object key=7y4bxf423p3lbcq57q7zv95dimi9cab6.ls error="server returned 404: 404 page not found\n"18182026/10/01 08:28:29 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"18192026/10/01 08:28:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18202026/10/01 08:28:29 INFO Signed narinfos id=1 count=118212026/10/01 08:28:29 INFO Uploading 1 narinfos18222026/10/01 08:28:29 INFO Received uploads request method=POST path=/api/pending_closures18232026/10/01 08:28:29 INFO Received complete push request method=POST path=/api/pushes/1/complete18242026/10/01 08:28:29 WARN Failed to register uploaded object key=7y4bxf423p3lbcq57q7zv95dimi9cab6.narinfo error="server returned 404: 404 page not found\n"1825--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.22s)1826=== CONT TestService_RequireScope_OIDC18272026/10/01 08:28:29 INFO Upload complete. (143ms)18282026/10/01 08:28:29 OK 20241026095416_initial_model.sql (128.29ms)18292026/10/01 08:28:29 OK 20251210153512_drop_unused_gin_index.sql (8.7ms)18302026/10/01 08:28:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60636/oidc18312026/10/01 08:28:29 OK 20251218171726_add_pins.sql (32.13ms)18322026/10/01 08:28:29 OK 20260628120000_add_object_size_and_stats.sql (25.98ms)18332026/10/01 08:28:29 INFO Received push request method=POST path=/api/pushes18342026/10/01 08:28:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18352026/10/01 08:28:29 INFO Uploading s7da7sdmx0y70afjas3qahghlsqjg4aw-unpinned-file.txt (128B)18362026/10/01 08:28:29 WARN Failed to register uploaded object key=s7da7sdmx0y70afjas3qahghlsqjg4aw.ls error="server returned 404: 404 page not found\n"18372026-10-01 08:28:29.745 UTC [91600] ERROR: relation "goose_db_version" does not exist at character 3618382026-10-01 08:28:29.745 UTC [91600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18392026/10/01 08:28:29 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18402026/10/01 08:28:29 INFO Signed narinfos id=2 count=118412026/10/01 08:28:29 INFO Uploading 1 narinfos18422026/10/01 08:28:29 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18432026/10/01 08:28:29 INFO Received complete push request method=POST path=/api/pushes/2/complete18442026/10/01 08:28:29 WARN Failed to register uploaded object key=s7da7sdmx0y70afjas3qahghlsqjg4aw.narinfo error="server returned 404: 404 page not found\n"18452026/10/01 08:28:29 INFO Upload complete. (73ms)18462026/10/01 08:28:29 OK 20260905000000_add_claims.sql (35.52ms)18472026/10/01 08:28:29 INFO Received create pin request method=POST path=/api/pins/myapp18482026/10/01 08:28:29 OK 20260920000000_drop_claims.sql (29.85ms)18492026/10/01 08:28:29 OK 20260923120000_add_pushes.sql (13.84ms)18502026/10/01 08:28:29 goose: successfully migrated database to version: 2026092312000018512026/10/01 08:28:29 OK 1_commit_pending_closure.sql (979.75µs)18522026/10/01 08:28:29 OK 2_object_stats_trigger.sql (254.17µs)18532026/10/01 08:28:29 OK 3_commit_push.sql (193.33µs)18542026/10/01 08:28:29 goose: up to current file version: 318552026/10/01 08:28:29 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-91269-3505625895/TestPinProtectsFromGC3084315340/001/store/7y4bxf423p3lbcq57q7zv95dimi9cab6-pinned-file.txt narinfo_key=7y4bxf423p3lbcq57q7zv95dimi9cab6.narinfo18562026/10/01 08:28:29 INFO Starting cleanup of old closures method=DELETE path=/api/closures18572026/10/01 08:28:29 INFO Garbage collection started18582026/10/01 08:28:29 INFO Aborted multipart uploads count=018592026/10/01 08:28:29 WARN Force mode enabled - objects will be deleted immediately without grace period1860--- PASS: TestReadProxyConditionalGet (2.23s)1861=== CONT TestServerTLSConfig1862=== RUN TestServerTLSConfig/no_client_CA1863=== PAUSE TestServerTLSConfig/no_client_CA1864=== RUN TestServerTLSConfig/missing_CA_file1865=== PAUSE TestServerTLSConfig/missing_CA_file1866=== RUN TestServerTLSConfig/not_a_PEM_file1867=== PAUSE TestServerTLSConfig/not_a_PEM_file1868=== CONT TestCacheConfigHandler1869=== RUN TestCacheConfigHandler/full_config,_no_issuer1870=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1871=== RUN TestCacheConfigHandler/no_cache_url_configured1872=== PAUSE TestCacheConfigHandler/no_cache_url_configured1873=== RUN TestCacheConfigHandler/no_signing_keys1874=== PAUSE TestCacheConfigHandler/no_signing_keys1875=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1876=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1877=== CONT TestService_NativeMTLS18782026/10/01 08:28:29 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=018792026/10/01 08:28:29 INFO Vacuumed table table=pending_closures18802026/10/01 08:28:29 OK 20241026095416_initial_model.sql (188.86ms)18812026/10/01 08:28:29 INFO Vacuumed table table=pending_objects18822026/10/01 08:28:29 INFO Vacuumed table table=multipart_uploads18832026/10/01 08:28:30 OK 20251210153512_drop_unused_gin_index.sql (20.15ms)18842026/10/01 08:28:30 INFO Vacuumed table table=closures18852026/10/01 08:28:30 OK 20251218171726_add_pins.sql (16.67ms)18862026/10/01 08:28:30 INFO Vacuumed table table=objects18872026/10/01 08:28:30 OK 20260628120000_add_object_size_and_stats.sql (24.49ms)18882026/10/01 08:28:30 OK 20260905000000_add_claims.sql (35.64ms)18892026-10-01 08:28:30.081 UTC [91606] ERROR: relation "goose_db_version" does not exist at character 3618902026-10-01 08:28:30.081 UTC [91606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18912026/10/01 08:28:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18922026/10/01 08:28:30 WARN Refused reserved pin name=worker-x86_64-linux18932026/10/01 08:28:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18942026/10/01 08:28:30 INFO Received create pin request method=POST path=/api/pins/my-app18952026/10/01 08:28:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1896--- PASS: TestCreatePin_ReservedPins (2.13s)1897=== CONT TestService_AuthMiddleware_OIDC18982026/10/01 08:28:30 OK 20260920000000_drop_claims.sql (30.16ms)18992026/10/01 08:28:30 OK 20260923120000_add_pushes.sql (20.15ms)19002026/10/01 08:28:30 goose: successfully migrated database to version: 2026092312000019012026/10/01 08:28:30 OK 1_commit_pending_closure.sql (2.22ms)19022026/10/01 08:28:30 OK 2_object_stats_trigger.sql (525.5µs)19032026/10/01 08:28:30 OK 3_commit_push.sql (223.38µs)19042026/10/01 08:28:30 goose: up to current file version: 319052026/10/01 08:28:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60652/oidc19062026/10/01 08:28:30 OK 20241026095416_initial_model.sql (45.59ms)19072026/10/01 08:28:30 OK 20251210153512_drop_unused_gin_index.sql (7.83ms)19082026/10/01 08:28:30 OK 20251218171726_add_pins.sql (11.44ms)19092026/10/01 08:28:30 OK 20260628120000_add_object_size_and_stats.sql (17.04ms)19102026/10/01 08:28:30 OK 20260905000000_add_claims.sql (31.73ms)19112026/10/01 08:28:30 OK 20260920000000_drop_claims.sql (17.77ms)19122026/10/01 08:28:30 OK 20260923120000_add_pushes.sql (13.91ms)19132026/10/01 08:28:30 goose: successfully migrated database to version: 2026092312000019142026/10/01 08:28:30 OK 1_commit_pending_closure.sql (2.24ms)19152026/10/01 08:28:30 OK 2_object_stats_trigger.sql (299.42µs)19162026/10/01 08:28:30 OK 3_commit_push.sql (213.67µs)19172026/10/01 08:28:30 goose: up to current file version: 31918--- PASS: TestReadProxyHead (2.07s)1919=== CONT TestClientMultipleUploads19202026-10-01 08:28:30.437 UTC [91611] ERROR: relation "goose_db_version" does not exist at character 3619212026-10-01 08:28:30.437 UTC [91611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19222026-10-01 08:28:30.458 UTC [91612] ERROR: relation "goose_db_version" does not exist at character 3619232026-10-01 08:28:30.458 UTC [91612] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19242026/10/01 08:28:30 OK 20241026095416_initial_model.sql (107.94ms)19252026/10/01 08:28:30 OK 20251210153512_drop_unused_gin_index.sql (15.56ms)19262026/10/01 08:28:30 OK 20251218171726_add_pins.sql (21.22ms)19272026/10/01 08:28:30 OK 20241026095416_initial_model.sql (146.42ms)19282026/10/01 08:28:30 OK 20260628120000_add_object_size_and_stats.sql (42.62ms)19292026/10/01 08:28:30 OK 20251210153512_drop_unused_gin_index.sql (20.45ms)19302026/10/01 08:28:30 OK 20251218171726_add_pins.sql (23.63ms)19312026/10/01 08:28:30 OK 20260905000000_add_claims.sql (82.37ms)19322026/10/01 08:28:30 OK 20260628120000_add_object_size_and_stats.sql (59.3ms)19332026/10/01 08:28:30 OK 20260920000000_drop_claims.sql (25.36ms)19342026/10/01 08:28:30 OK 20260923120000_add_pushes.sql (29.27ms)19352026/10/01 08:28:30 goose: successfully migrated database to version: 2026092312000019362026/10/01 08:28:30 OK 1_commit_pending_closure.sql (5.24ms)19372026/10/01 08:28:30 OK 2_object_stats_trigger.sql (1.07ms)19382026/10/01 08:28:30 OK 3_commit_push.sql (1.18ms)19392026/10/01 08:28:30 goose: up to current file version: 319402026/10/01 08:28:30 OK 20260905000000_add_claims.sql (77.96ms)19412026/10/01 08:28:30 OK 20260920000000_drop_claims.sql (20.4ms)1942--- PASS: TestObjectStatsTrigger (2.18s)1943=== CONT TestMetricsInventory19442026/10/01 08:28:30 OK 20260923120000_add_pushes.sql (66.13ms)19452026/10/01 08:28:30 goose: successfully migrated database to version: 2026092312000019462026/10/01 08:28:30 OK 1_commit_pending_closure.sql (3.75ms)19472026/10/01 08:28:30 OK 2_object_stats_trigger.sql (721.04µs)19482026/10/01 08:28:30 OK 3_commit_push.sql (488.29µs)19492026/10/01 08:28:30 goose: up to current file version: 319502026-10-01 08:28:31.002 UTC [91615] ERROR: relation "goose_db_version" does not exist at character 3619512026-10-01 08:28:31.002 UTC [91615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1952--- PASS: TestService_ReadScope_PublicByDefault (2.02s)1953=== CONT TestClientIntegration19542026/10/01 08:28:31 OK 20241026095416_initial_model.sql (181.22ms)19552026/10/01 08:28:31 OK 20251210153512_drop_unused_gin_index.sql (9.86ms)19562026/10/01 08:28:31 OK 20251218171726_add_pins.sql (43.65ms)19572026/10/01 08:28:31 OK 20260628120000_add_object_size_and_stats.sql (40.48ms)19582026/10/01 08:28:31 OK 20260905000000_add_claims.sql (56.87ms)19592026/10/01 08:28:31 OK 20260920000000_drop_claims.sql (33.79ms)19602026/10/01 08:28:31 OK 20260923120000_add_pushes.sql (14.2ms)19612026/10/01 08:28:31 goose: successfully migrated database to version: 2026092312000019622026/10/01 08:28:31 OK 1_commit_pending_closure.sql (5.39ms)19632026/10/01 08:28:31 OK 2_object_stats_trigger.sql (1.09ms)19642026/10/01 08:28:31 OK 3_commit_push.sql (1.5ms)19652026/10/01 08:28:31 goose: up to current file version: 319662026-10-01 08:28:31.447 UTC [91618] ERROR: relation "goose_db_version" does not exist at character 3619672026-10-01 08:28:31.447 UTC [91618] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19682026-10-01 08:28:31.599 UTC [91619] ERROR: relation "goose_db_version" does not exist at character 3619692026-10-01 08:28:31.599 UTC [91619] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19702026/10/01 08:28:31 OK 20241026095416_initial_model.sql (233.55ms)19712026/10/01 08:28:31 OK 20251210153512_drop_unused_gin_index.sql (4.76ms)19722026/10/01 08:28:31 INFO Received uploads request method=POST path=/api/pending_closures19732026/10/01 08:28:31 OK 20251218171726_add_pins.sql (41.59ms)19742026/10/01 08:28:31 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01975=== NAME TestPinProtectsFromGC1976 client_integration_test.go:794: Pin successfully protected closure from garbage collection19772026/10/01 08:28:31 OK 20260628120000_add_object_size_and_stats.sql (30.47ms)19782026/10/01 08:28:31 OK 20241026095416_initial_model.sql (179.54ms)19792026/10/01 08:28:31 OK 20251210153512_drop_unused_gin_index.sql (8.5ms)1980--- PASS: TestPinProtectsFromGC (4.86s)1981=== CONT TestNARDeduplicationMetadataUploadBug19822026/10/01 08:28:31 OK 20260905000000_add_claims.sql (50.73ms)19832026/10/01 08:28:31 OK 20251218171726_add_pins.sql (15.37ms)19842026/10/01 08:28:31 OK 20260920000000_drop_claims.sql (25.82ms)19852026/10/01 08:28:31 OK 20260628120000_add_object_size_and_stats.sql (23.08ms)19862026/10/01 08:28:31 OK 20260923120000_add_pushes.sql (10.29ms)19872026/10/01 08:28:31 goose: successfully migrated database to version: 2026092312000019882026/10/01 08:28:31 OK 1_commit_pending_closure.sql (1.93ms)19892026/10/01 08:28:31 OK 2_object_stats_trigger.sql (358.29µs)19902026/10/01 08:28:31 OK 3_commit_push.sql (306.88µs)19912026/10/01 08:28:31 goose: up to current file version: 319922026/10/01 08:28:31 INFO Received cleanup request method=DELETE path=/api/pending_closures19932026/10/01 08:28:31 OK 20260905000000_add_claims.sql (53.95ms)19942026/10/01 08:28:31 INFO Aborted multipart uploads count=119952026/10/01 08:28:31 OK 20260920000000_drop_claims.sql (24.35ms)19962026-10-01 08:28:31.984 UTC [91622] ERROR: relation "goose_db_version" does not exist at character 3619972026-10-01 08:28:31.984 UTC [91622] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1998--- PASS: TestMultipartCleanup (2.60s)1999=== CONT TestClientErrorHandling2000=== RUN TestClientErrorHandling/InvalidStorePath2001=== PAUSE TestClientErrorHandling/InvalidStorePath2002=== RUN TestClientErrorHandling/InvalidAuthToken2003=== PAUSE TestClientErrorHandling/InvalidAuthToken2004=== RUN TestClientErrorHandling/ServerNotAvailable2005=== PAUSE TestClientErrorHandling/ServerNotAvailable2006=== CONT TestCreatePendingClosureRejectsOversizedNAR20072026/10/01 08:28:31 INFO Received uploads request method=POST path=/api/pending_closures2008--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2009=== CONT TestCacheConfigHandlerMaxNarSize2010--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)2011=== CONT TestGenerateLandingPage2012--- PASS: TestGenerateLandingPage (0.00s)2013=== CONT TestService_readinessHandler20142026/10/01 08:28:31 OK 20260923120000_add_pushes.sql (11.91ms)20152026/10/01 08:28:31 goose: successfully migrated database to version: 2026092312000020162026/10/01 08:28:31 OK 1_commit_pending_closure.sql (1.86ms)20172026/10/01 08:28:31 OK 2_object_stats_trigger.sql (409.29µs)20182026/10/01 08:28:31 OK 3_commit_push.sql (309.88µs)20192026/10/01 08:28:31 goose: up to current file version: 320202026-10-01 08:28:32.059 UTC [91625] ERROR: relation "goose_db_version" does not exist at character 3620212026-10-01 08:28:32.059 UTC [91625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2022=== NAME TestOrphanedObjectsGC2023 orphaned_objects_gc_test.go:290: GC Test Summary:2024 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2025 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2026 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2027 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2028 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2029--- PASS: TestOrphanedObjectsGC (3.20s)2030=== CONT TestService_healthCheckHandler2031=== RUN TestService_RequireScope_OIDC/builder_may_write2032=== PAUSE TestService_RequireScope_OIDC/builder_may_write2033=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2034=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2035=== RUN TestService_RequireScope_OIDC/ops_may_admin2036=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2037=== RUN TestService_RequireScope_OIDC/ops_may_not_write2038=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2039=== RUN TestService_RequireScope_OIDC/reader_may_not_write2040=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2041=== RUN TestService_RequireScope_OIDC/static_token_may_admin2042=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2043=== RUN TestService_RequireScope_OIDC/static_token_may_write2044=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2045=== RUN TestService_RequireScope_OIDC/reader_may_read2046=== PAUSE TestService_RequireScope_OIDC/reader_may_read2047=== RUN TestService_RequireScope_OIDC/writer_implies_read2048=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2049=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2050=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2051=== CONT TestGracefulShutdownDrainsInflight20522026/10/01 08:28:32 INFO Starting HTTP server address=127.0.0.1:6067020532026/10/01 08:28:32 INFO Shutdown signal received, draining in-flight requests timeout=10s20542026/10/01 08:28:32 OK 20241026095416_initial_model.sql (186.02ms)20552026/10/01 08:28:32 OK 20251210153512_drop_unused_gin_index.sql (12.64ms)2056=== CONT TestGCTaskStore_Fail2057=== CONT TestService_ReadAuthMiddleware2058--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2059--- PASS: TestGCTaskStore_Fail (0.00s)20602026/10/01 08:28:32 OK 20241026095416_initial_model.sql (206.41ms)20612026/10/01 08:28:32 OK 20251218171726_add_pins.sql (64.95ms)20622026/10/01 08:28:32 OK 20251210153512_drop_unused_gin_index.sql (8.22ms)20632026/10/01 08:28:32 OK 20260628120000_add_object_size_and_stats.sql (34.9ms)20642026/10/01 08:28:32 OK 20251218171726_add_pins.sql (34.23ms)20652026/10/01 08:28:32 OK 20260628120000_add_object_size_and_stats.sql (35.51ms)20662026/10/01 08:28:32 OK 20260905000000_add_claims.sql (54.52ms)20672026/10/01 08:28:32 OK 20260920000000_drop_claims.sql (16.32ms)20682026/10/01 08:28:32 OK 20260923120000_add_pushes.sql (18.27ms)20692026/10/01 08:28:32 goose: successfully migrated database to version: 2026092312000020702026/10/01 08:28:32 OK 1_commit_pending_closure.sql (3.55ms)20712026/10/01 08:28:32 OK 2_object_stats_trigger.sql (765.04µs)20722026/10/01 08:28:32 OK 3_commit_push.sql (2.75ms)20732026/10/01 08:28:32 goose: up to current file version: 320742026/10/01 08:28:32 OK 20260905000000_add_claims.sql (63.6ms)20752026/10/01 08:28:32 OK 20260920000000_drop_claims.sql (27.31ms)20762026/10/01 08:28:32 WARN mTLS auth: subject not in bound subjects subject="CN=reader"20772026/10/01 08:28:32 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2078--- PASS: TestService_NativeMTLS (2.62s)2079=== CONT TestGCTaskStore_PhaseUpdates2080--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)2081=== CONT TestService_AuthMiddleware_MTLSBoundSubjects20822026/10/01 08:28:32 OK 20260923120000_add_pushes.sql (8.96ms)20832026/10/01 08:28:32 goose: successfully migrated database to version: 2026092312000020842026/10/01 08:28:32 OK 1_commit_pending_closure.sql (3.98ms)20852026/10/01 08:28:32 OK 2_object_stats_trigger.sql (718.33µs)20862026/10/01 08:28:32 OK 3_commit_push.sql (499.42µs)20872026/10/01 08:28:32 goose: up to current file version: 32088=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2089=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2090=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2091=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2092=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2093=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2094=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2095=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2096=== CONT TestCacheStatsHandler20972026-10-01 08:28:32.956 UTC [91634] ERROR: relation "goose_db_version" does not exist at character 3620982026-10-01 08:28:32.956 UTC [91634] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20992026-10-01 08:28:33.147 UTC [91635] ERROR: relation "goose_db_version" does not exist at character 3621002026-10-01 08:28:33.147 UTC [91635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21012026/10/01 08:28:33 OK 20241026095416_initial_model.sql (160.15ms)21022026/10/01 08:28:33 OK 20251210153512_drop_unused_gin_index.sql (13.99ms)21032026/10/01 08:28:33 OK 20251218171726_add_pins.sql (38.14ms)21042026/10/01 08:28:33 OK 20260628120000_add_object_size_and_stats.sql (21.23ms)21052026/10/01 08:28:33 OK 20260905000000_add_claims.sql (23.21ms)21062026/10/01 08:28:33 OK 20260920000000_drop_claims.sql (16.36ms)21072026/10/01 08:28:33 OK 20241026095416_initial_model.sql (98ms)2108=== NAME TestClientMultipleUploads2109 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-91269-3505625895/TestClientMultipleUploads2053983481/001/store/lanfzcw04zqc1w4pxhvm363ckrvd2h7d-test-file-0.txt21102026/10/01 08:28:33 OK 20251210153512_drop_unused_gin_index.sql (8.1ms)21112026/10/01 08:28:33 OK 20260923120000_add_pushes.sql (10.29ms)21122026/10/01 08:28:33 goose: successfully migrated database to version: 2026092312000021132026/10/01 08:28:33 OK 1_commit_pending_closure.sql (1.6ms)21142026/10/01 08:28:33 OK 2_object_stats_trigger.sql (345.13µs)21152026/10/01 08:28:33 OK 3_commit_push.sql (247.38µs)21162026/10/01 08:28:33 goose: up to current file version: 321172026/10/01 08:28:33 OK 20251218171726_add_pins.sql (10.95ms)21182026/10/01 08:28:33 OK 20260628120000_add_object_size_and_stats.sql (35.64ms)21192026/10/01 08:28:33 OK 20260905000000_add_claims.sql (66.15ms)2120 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-91269-3505625895/TestClientMultipleUploads2053983481/001/store/6vmbg3zcbmxs0jjybwgsxjhydr3gibiz-test-file-1.txt21212026/10/01 08:28:33 OK 20260920000000_drop_claims.sql (29.18ms)21222026/10/01 08:28:33 OK 20260923120000_add_pushes.sql (11.79ms)21232026/10/01 08:28:33 goose: successfully migrated database to version: 2026092312000021242026/10/01 08:28:33 OK 1_commit_pending_closure.sql (1.22ms)21252026/10/01 08:28:33 OK 2_object_stats_trigger.sql (249.67µs)21262026/10/01 08:28:33 OK 3_commit_push.sql (188.67µs)21272026/10/01 08:28:33 goose: up to current file version: 32128 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-91269-3505625895/TestClientMultipleUploads2053983481/001/store/3m9lkmxpahzlxjm5qp11740hs1j2v51q-test-file-2.txt21292026/10/01 08:28:33 INFO Received push request method=POST path=/api/pushes2130--- PASS: TestMetricsInventory (2.75s)2131=== CONT TestService_AuthMiddleware_MTLSProxyHeader21322026/10/01 08:28:33 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)21332026/10/01 08:28:33 INFO Uploading lanfzcw04zqc1w4pxhvm363ckrvd2h7d-test-file-0.txt (160B)21342026/10/01 08:28:33 INFO Uploading 6vmbg3zcbmxs0jjybwgsxjhydr3gibiz-test-file-1.txt (160B)21352026/10/01 08:28:33 INFO Uploading 3m9lkmxpahzlxjm5qp11740hs1j2v51q-test-file-2.txt (160B)21362026/10/01 08:28:33 WARN Failed to register uploaded object key=3m9lkmxpahzlxjm5qp11740hs1j2v51q.ls error="server returned 404: 404 page not found\n"21372026/10/01 08:28:33 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"21382026/10/01 08:28:33 WARN Failed to register uploaded object key=lanfzcw04zqc1w4pxhvm363ckrvd2h7d.ls error="server returned 404: 404 page not found\n"21392026/10/01 08:28:33 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"21402026/10/01 08:28:33 WARN Failed to register uploaded object key=6vmbg3zcbmxs0jjybwgsxjhydr3gibiz.ls error="server returned 404: 404 page not found\n"21412026/10/01 08:28:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21422026/10/01 08:28:33 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"21432026/10/01 08:28:33 INFO Signed narinfos id=1 count=321442026/10/01 08:28:33 INFO Uploading 3 narinfos21452026/10/01 08:28:33 WARN Failed to register uploaded object key=3m9lkmxpahzlxjm5qp11740hs1j2v51q.narinfo error="server returned 404: 404 page not found\n"21462026/10/01 08:28:33 WARN Failed to register uploaded object key=lanfzcw04zqc1w4pxhvm363ckrvd2h7d.narinfo error="server returned 404: 404 page not found\n"21472026/10/01 08:28:33 INFO Received complete push request method=POST path=/api/pushes/1/complete21482026/10/01 08:28:33 WARN Failed to register uploaded object key=6vmbg3zcbmxs0jjybwgsxjhydr3gibiz.narinfo error="server returned 404: 404 page not found\n"21492026/10/01 08:28:33 INFO Upload complete. (166ms)2150=== NAME TestClientMultipleUploads2151 client_integration_test.go:369: Uploaded 3 paths in 199.986209ms2152--- PASS: TestClientMultipleUploads (3.50s)2153=== CONT TestReadProxyNarinfoAlreadyDecompressed21542026-10-01 08:28:33.899 UTC [91652] ERROR: relation "goose_db_version" does not exist at character 3621552026-10-01 08:28:33.899 UTC [91652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21562026-10-01 08:28:33.900 UTC [91650] ERROR: relation "goose_db_version" does not exist at character 3621572026-10-01 08:28:33.900 UTC [91650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21582026-10-01 08:28:33.973 UTC [91654] ERROR: relation "goose_db_version" does not exist at character 3621592026-10-01 08:28:33.973 UTC [91654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21602026-10-01 08:28:33.988 UTC [91655] ERROR: relation "goose_db_version" does not exist at character 3621612026-10-01 08:28:33.988 UTC [91655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2162=== NAME TestClientIntegration2163 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-91269-3505625895/TestClientIntegration2078269402/002/store/w005fvngyj2l317a4vwrb3m66bhicpbc-test-file.txt21642026/10/01 08:28:34 OK 20241026095416_initial_model.sql (72.13ms)21652026/10/01 08:28:34 OK 20241026095416_initial_model.sql (80.46ms)21662026/10/01 08:28:34 OK 20251210153512_drop_unused_gin_index.sql (5.33ms)21672026/10/01 08:28:34 OK 20251210153512_drop_unused_gin_index.sql (7.99ms)21682026/10/01 08:28:34 OK 20251218171726_add_pins.sql (8.95ms)21692026/10/01 08:28:34 OK 20251218171726_add_pins.sql (8.38ms)21702026/10/01 08:28:34 OK 20260628120000_add_object_size_and_stats.sql (18.05ms)21712026/10/01 08:28:34 OK 20260628120000_add_object_size_and_stats.sql (23.68ms)21722026-10-01 08:28:34.048 UTC [91657] ERROR: relation "goose_db_version" does not exist at character 3621732026-10-01 08:28:34.048 UTC [91657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21742026/10/01 08:28:34 OK 20241026095416_initial_model.sql (51.58ms)21752026/10/01 08:28:34 OK 20260905000000_add_claims.sql (16.63ms)21762026/10/01 08:28:34 OK 20251210153512_drop_unused_gin_index.sql (7.99ms)21772026/10/01 08:28:34 OK 20260905000000_add_claims.sql (19.34ms)21782026/10/01 08:28:34 OK 20260920000000_drop_claims.sql (14.62ms)21792026/10/01 08:28:34 OK 20251218171726_add_pins.sql (6.98ms)21802026/10/01 08:28:34 OK 20260923120000_add_pushes.sql (2.93ms)21812026/10/01 08:28:34 goose: successfully migrated database to version: 2026092312000021822026/10/01 08:28:34 OK 20260920000000_drop_claims.sql (8.69ms)21832026/10/01 08:28:34 OK 1_commit_pending_closure.sql (1.3ms)21842026/10/01 08:28:34 OK 2_object_stats_trigger.sql (241.83µs)21852026/10/01 08:28:34 OK 3_commit_push.sql (191.71µs)21862026/10/01 08:28:34 goose: up to current file version: 321872026/10/01 08:28:34 OK 20241026095416_initial_model.sql (75.46ms)21882026/10/01 08:28:34 OK 20260923120000_add_pushes.sql (17.98ms)21892026/10/01 08:28:34 goose: successfully migrated database to version: 2026092312000021902026/10/01 08:28:34 OK 1_commit_pending_closure.sql (943.46µs)21912026/10/01 08:28:34 INFO Received push request method=POST path=/api/pushes21922026/10/01 08:28:34 OK 2_object_stats_trigger.sql (250.17µs)21932026/10/01 08:28:34 OK 3_commit_push.sql (181.96µs)21942026/10/01 08:28:34 goose: up to current file version: 321952026/10/01 08:28:34 OK 20251210153512_drop_unused_gin_index.sql (7.28ms)21962026/10/01 08:28:34 OK 20260628120000_add_object_size_and_stats.sql (28.54ms)21972026/10/01 08:28:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21982026/10/01 08:28:34 INFO Uploading w005fvngyj2l317a4vwrb3m66bhicpbc-test-file.txt (152B)21992026/10/01 08:28:34 OK 20251218171726_add_pins.sql (28.1ms)22002026/10/01 08:28:34 WARN Failed to register uploaded object key=w005fvngyj2l317a4vwrb3m66bhicpbc.ls error="server returned 404: 404 page not found\n"22012026/10/01 08:28:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22022026/10/01 08:28:34 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"22032026/10/01 08:28:34 INFO Signed narinfos id=1 count=122042026/10/01 08:28:34 INFO Uploading 1 narinfos22052026/10/01 08:28:34 OK 20260628120000_add_object_size_and_stats.sql (30.84ms)22062026/10/01 08:28:34 OK 20260905000000_add_claims.sql (58.35ms)22072026/10/01 08:28:34 INFO Received complete push request method=POST path=/api/pushes/1/complete22082026/10/01 08:28:34 WARN Failed to register uploaded object key=w005fvngyj2l317a4vwrb3m66bhicpbc.narinfo error="server returned 404: 404 page not found\n"22092026/10/01 08:28:34 INFO Upload complete. (155ms)22102026/10/01 08:28:34 OK 20260920000000_drop_claims.sql (37.48ms)22112026/10/01 08:28:34 OK 20260923120000_add_pushes.sql (10.65ms)22122026/10/01 08:28:34 goose: successfully migrated database to version: 2026092312000022132026/10/01 08:28:34 OK 1_commit_pending_closure.sql (947.63µs)22142026/10/01 08:28:34 OK 2_object_stats_trigger.sql (234.96µs)22152026/10/01 08:28:34 OK 3_commit_push.sql (210.38µs)22162026/10/01 08:28:34 goose: up to current file version: 322172026/10/01 08:28:34 OK 20260905000000_add_claims.sql (54.89ms)22182026/10/01 08:28:34 OK 20260920000000_drop_claims.sql (13.81ms)22192026/10/01 08:28:34 INFO All 1 paths already cached2220 client_integration_test.go:312: Retrieved narinfo from S3:2221 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientIntegration2078269402/002/store/w005fvngyj2l317a4vwrb3m66bhicpbc-test-file.txt2222 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2223 Compression: zstd2224 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12225 NarSize: 1522226 References: 2227 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12228 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2229 client_integration_test.go:313: Decompressed .ls content (64 bytes):2230 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2231 client_integration_test.go:316: Testing garbage collection...22322026/10/01 08:28:34 OK 20241026095416_initial_model.sql (160.91ms)22332026/10/01 08:28:34 OK 20260923120000_add_pushes.sql (11.57ms)22342026/10/01 08:28:34 goose: successfully migrated database to version: 2026092312000022352026/10/01 08:28:34 OK 1_commit_pending_closure.sql (829.13µs)22362026/10/01 08:28:34 OK 2_object_stats_trigger.sql (206.21µs)22372026/10/01 08:28:34 OK 3_commit_push.sql (169.83µs)22382026/10/01 08:28:34 goose: up to current file version: 322392026/10/01 08:28:34 OK 20251210153512_drop_unused_gin_index.sql (13.32ms)22402026/10/01 08:28:34 OK 20251218171726_add_pins.sql (12.11ms)22412026/10/01 08:28:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures22422026/10/01 08:28:34 INFO Garbage collection started22432026/10/01 08:28:34 INFO Aborted multipart uploads count=022442026/10/01 08:28:34 WARN Force mode enabled - objects will be deleted immediately without grace period22452026/10/01 08:28:34 OK 20260628120000_add_object_size_and_stats.sql (23.61ms)22462026/10/01 08:28:34 OK 20260905000000_add_claims.sql (73.1ms)22472026/10/01 08:28:34 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=022482026-10-01 08:28:34.380 UTC [91666] ERROR: relation "goose_db_version" does not exist at character 3622492026-10-01 08:28:34.380 UTC [91666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22502026/10/01 08:28:34 INFO Vacuumed table table=pending_closures22512026/10/01 08:28:34 OK 20260920000000_drop_claims.sql (28.86ms)22522026/10/01 08:28:34 OK 20260923120000_add_pushes.sql (5.4ms)22532026/10/01 08:28:34 goose: successfully migrated database to version: 2026092312000022542026/10/01 08:28:34 OK 1_commit_pending_closure.sql (1.21ms)22552026/10/01 08:28:34 OK 2_object_stats_trigger.sql (271.67µs)22562026/10/01 08:28:34 OK 3_commit_push.sql (236.17µs)22572026/10/01 08:28:34 goose: up to current file version: 322582026/10/01 08:28:34 INFO Vacuumed table table=pending_objects22592026/10/01 08:28:34 INFO Vacuumed table table=multipart_uploads22602026/10/01 08:28:34 INFO Vacuumed table table=closures22612026/10/01 08:28:34 INFO Vacuumed table table=objects2262=== NAME TestNARDeduplicationMetadataUploadBug2263 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-91269-3505625895/TestNARDeduplicationMetadataUploadBug1624763057/001/store/63vd7y3m2f8ajg9kb35lbpx6grsax472-file1.txt22642026/10/01 08:28:34 OK 20241026095416_initial_model.sql (151.54ms)22652026/10/01 08:28:34 OK 20251210153512_drop_unused_gin_index.sql (4.25ms)22662026/10/01 08:28:34 WARN readiness check failed error="closed pool"2267--- PASS: TestService_readinessHandler (2.60s)2268=== CONT TestIsValidCachePath2269=== RUN TestIsValidCachePath/narinfo2270=== PAUSE TestIsValidCachePath/narinfo2271=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2272=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2273=== RUN TestIsValidCachePath/nar_zst2274=== PAUSE TestIsValidCachePath/nar_zst2275=== RUN TestIsValidCachePath/nar_xz2276=== PAUSE TestIsValidCachePath/nar_xz2277=== RUN TestIsValidCachePath/nar_bz22278=== PAUSE TestIsValidCachePath/nar_bz22279=== RUN TestIsValidCachePath/nar_uncompressed2280=== PAUSE TestIsValidCachePath/nar_uncompressed2281=== RUN TestIsValidCachePath/ls2282=== PAUSE TestIsValidCachePath/ls2283=== RUN TestIsValidCachePath/log2284=== PAUSE TestIsValidCachePath/log2285=== RUN TestIsValidCachePath/realisation2286=== PAUSE TestIsValidCachePath/realisation2287=== RUN TestIsValidCachePath/nix-cache-info2288=== PAUSE TestIsValidCachePath/nix-cache-info2289=== RUN TestIsValidCachePath/index.html2290=== PAUSE TestIsValidCachePath/index.html2291=== RUN TestIsValidCachePath/traversal_parent2292=== PAUSE TestIsValidCachePath/traversal_parent2293=== RUN TestIsValidCachePath/traversal_in_middle2294=== PAUSE TestIsValidCachePath/traversal_in_middle2295=== RUN TestIsValidCachePath/invalid_char_e2296=== PAUSE TestIsValidCachePath/invalid_char_e2297=== RUN TestIsValidCachePath/invalid_char_u2298=== PAUSE TestIsValidCachePath/invalid_char_u2299=== RUN TestIsValidCachePath/random_path2300=== PAUSE TestIsValidCachePath/random_path2301=== RUN TestIsValidCachePath/empty2302=== PAUSE TestIsValidCachePath/empty2303=== RUN TestIsValidCachePath/leading_slash2304=== PAUSE TestIsValidCachePath/leading_slash2305=== RUN TestIsValidCachePath/wrong_extension2306=== PAUSE TestIsValidCachePath/wrong_extension2307=== RUN TestIsValidCachePath/short_hash2308=== PAUSE TestIsValidCachePath/short_hash2309=== CONT TestReadProxyNarinfo23102026/10/01 08:28:34 OK 20251218171726_add_pins.sql (10.6ms)23112026/10/01 08:28:34 OK 20260628120000_add_object_size_and_stats.sql (28.56ms)23122026/10/01 08:28:34 OK 20260905000000_add_claims.sql (16.13ms)23132026/10/01 08:28:34 INFO Received push request method=POST path=/api/pushes23142026/10/01 08:28:34 OK 20260920000000_drop_claims.sql (26.26ms)23152026/10/01 08:28:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23162026/10/01 08:28:34 INFO Uploading 63vd7y3m2f8ajg9kb35lbpx6grsax472-file1.txt (160B)23172026/10/01 08:28:34 OK 20260923120000_add_pushes.sql (21.37ms)23182026/10/01 08:28:34 goose: successfully migrated database to version: 2026092312000023192026/10/01 08:28:34 OK 1_commit_pending_closure.sql (902.96µs)23202026/10/01 08:28:34 OK 2_object_stats_trigger.sql (228.38µs)23212026/10/01 08:28:34 OK 3_commit_push.sql (174.75µs)23222026/10/01 08:28:34 goose: up to current file version: 323232026/10/01 08:28:34 WARN Failed to register uploaded object key=63vd7y3m2f8ajg9kb35lbpx6grsax472.ls error="server returned 404: 404 page not found\n"23242026/10/01 08:28:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23252026/10/01 08:28:34 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"23262026/10/01 08:28:34 INFO Signed narinfos id=1 count=123272026/10/01 08:28:34 INFO Uploading 1 narinfos23282026/10/01 08:28:34 INFO Received complete push request method=POST path=/api/pushes/1/complete23292026/10/01 08:28:34 WARN Failed to register uploaded object key=63vd7y3m2f8ajg9kb35lbpx6grsax472.narinfo error="server returned 404: 404 page not found\n"23302026/10/01 08:28:34 INFO Upload complete. (122ms)2331=== NAME TestNARDeduplicationMetadataUploadBug2332 metadata_upload_test.go:54: Retrieved narinfo from S3:2333 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestNARDeduplicationMetadataUploadBug1624763057/001/store/63vd7y3m2f8ajg9kb35lbpx6grsax472-file1.txt2334 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2335 Compression: zstd2336 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2337 NarSize: 1602338 References: 2339 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2340 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2341 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2342 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2343--- PASS: TestService_healthCheckHandler (2.66s)2344=== CONT TestReadProxyNarStreaming2345=== NAME TestNARDeduplicationMetadataUploadBug2346 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-91269-3505625895/TestNARDeduplicationMetadataUploadBug1624763057/001/store/7f1z1v3v8ch0wxxwljbvj8gx74567xlj-file2.txt23472026/10/01 08:28:34 INFO Received push request method=POST path=/api/pushes23482026/10/01 08:28:34 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)23492026/10/01 08:28:34 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign23502026/10/01 08:28:34 INFO Signed narinfos id=2 count=123512026/10/01 08:28:34 INFO Uploading 1 narinfos23522026/10/01 08:28:34 WARN Failed to register uploaded object key=7f1z1v3v8ch0wxxwljbvj8gx74567xlj.ls error="server returned 404: 404 page not found\n"23532026/10/01 08:28:34 INFO Received complete push request method=POST path=/api/pushes/2/complete23542026/10/01 08:28:34 WARN Failed to register uploaded object key=7f1z1v3v8ch0wxxwljbvj8gx74567xlj.narinfo error="server returned 404: 404 page not found\n"23552026/10/01 08:28:34 INFO Upload complete. (96ms)2356 metadata_upload_test.go:76: Retrieved narinfo from S3:2357 StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestNARDeduplicationMetadataUploadBug1624763057/001/store/7f1z1v3v8ch0wxxwljbvj8gx74567xlj-file2.txt2358 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2359 Compression: zstd2360 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2361 NarSize: 1602362 References: 2363 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2364 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2365 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2366 {"version":1,"root":{"type":"regular","size":44}}2367--- PASS: TestNARDeduplicationMetadataUploadBug (3.15s)2368=== CONT TestProxyHeadersOnlyTrustedOnSocket23692026-10-01 08:28:35.053 UTC [91683] ERROR: relation "goose_db_version" does not exist at character 3623702026-10-01 08:28:35.053 UTC [91683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2371--- PASS: TestService_ReadAuthMiddleware (2.81s)2372=== CONT TestClientCADerivations23732026-10-01 08:28:35.183 UTC [91688] ERROR: relation "goose_db_version" does not exist at character 3623742026-10-01 08:28:35.183 UTC [91688] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23752026/10/01 08:28:35 OK 20241026095416_initial_model.sql (147.19ms)23762026/10/01 08:28:35 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)23772026/10/01 08:28:35 OK 20251218171726_add_pins.sql (35.65ms)23782026/10/01 08:28:35 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"23792026/10/01 08:28:35 WARN mTLS auth: bound subjects configured but subject DN unavailable23802026/10/01 08:28:35 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2381--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.82s)2382=== CONT TestReadProxy40423832026/10/01 08:28:35 OK 20260628120000_add_object_size_and_stats.sql (26.71ms)23842026/10/01 08:28:35 OK 20260905000000_add_claims.sql (65.16ms)23852026/10/01 08:28:35 OK 20260920000000_drop_claims.sql (23.57ms)23862026/10/01 08:28:35 OK 20241026095416_initial_model.sql (180.36ms)23872026/10/01 08:28:35 OK 20251210153512_drop_unused_gin_index.sql (9ms)23882026/10/01 08:28:35 OK 20260923120000_add_pushes.sql (23.81ms)23892026/10/01 08:28:35 goose: successfully migrated database to version: 2026092312000023902026/10/01 08:28:35 OK 1_commit_pending_closure.sql (3.08ms)23912026/10/01 08:28:35 OK 2_object_stats_trigger.sql (636.88µs)23922026/10/01 08:28:35 OK 3_commit_push.sql (392.83µs)23932026/10/01 08:28:35 goose: up to current file version: 323942026/10/01 08:28:35 OK 20251218171726_add_pins.sql (28.49ms)23952026/10/01 08:28:35 OK 20260628120000_add_object_size_and_stats.sql (34.55ms)23962026/10/01 08:28:35 OK 20260905000000_add_claims.sql (62.84ms)23972026/10/01 08:28:35 OK 20260920000000_drop_claims.sql (22.09ms)23982026/10/01 08:28:35 OK 20260923120000_add_pushes.sql (19.73ms)23992026/10/01 08:28:35 goose: successfully migrated database to version: 2026092312000024002026/10/01 08:28:35 OK 1_commit_pending_closure.sql (3.74ms)24012026/10/01 08:28:35 OK 2_object_stats_trigger.sql (828µs)24022026/10/01 08:28:35 OK 3_commit_push.sql (571.21µs)24032026/10/01 08:28:35 goose: up to current file version: 32404--- PASS: TestCacheStatsHandler (2.82s)2405=== CONT TestReadProxyInvalidPath2406--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.21s)2407=== CONT TestProxyWriteTimeout/narinfo2408=== CONT TestProxyWriteTimeout/unknown_size2409=== CONT TestProxyWriteTimeout/10_GiB_nar2410=== CONT TestProxyWriteTimeout/1_GiB_nar2411--- PASS: TestProxyWriteTimeout (0.00s)2412 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2413 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2414 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2415 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2416=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info24172026/10/01 08:28:35 INFO Received uploads request method=POST path=/2418=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key24192026/10/01 08:28:35 INFO Received request for more parts method=POST path=/2420=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key24212026/10/01 08:28:35 INFO Received complete multipart upload request method=POST path=/2422=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal24232026/10/01 08:28:35 INFO Received uploads request method=POST path=/2424--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2425 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2426 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2427 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2428 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2429=== CONT TestIsValidUploadKey/narinfo2430=== CONT TestIsValidUploadKey/unknown_type2431=== CONT TestIsValidUploadKey/empty_key2432=== CONT TestIsValidUploadKey/absolute2433=== CONT TestIsValidUploadKey/traversal_nar2434=== CONT TestIsValidUploadKey/traversal2435=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2436=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2437=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2438=== CONT TestIsValidUploadKey/index.html2439=== CONT TestIsValidUploadKey/nix-cache-info2440=== CONT TestIsValidUploadKey/realisation_plus_in_output2441=== CONT TestIsValidUploadKey/realisation2442=== CONT TestIsValidUploadKey/build_log_equals2443=== CONT TestIsValidUploadKey/build_log_question_mark2444=== CONT TestIsValidUploadKey/build_log_plus_in_name2445=== CONT TestIsValidUploadKey/build_log_home-manager_file2446=== CONT TestIsValidUploadKey/build_log2447=== CONT TestIsValidUploadKey/listing2448=== CONT TestIsValidUploadKey/nar_plain2449=== CONT TestIsValidUploadKey/nar_xz2450=== CONT TestIsValidUploadKey/nar_zst2451--- PASS: TestIsValidUploadKey (0.01s)2452 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2453 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2454 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2455 --- PASS: TestIsValidUploadKey/absolute (0.00s)2456 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2457 --- PASS: TestIsValidUploadKey/traversal (0.00s)2458 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2459 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2460 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2461 --- PASS: TestIsValidUploadKey/index.html (0.00s)2462 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2463 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2464 --- PASS: TestIsValidUploadKey/realisation (0.00s)2465 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2466 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2467 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2468 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2469 --- PASS: TestIsValidUploadKey/build_log (0.00s)2470 --- PASS: TestIsValidUploadKey/listing (0.00s)2471 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2472 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2473 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2474=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts24752026/10/01 08:28:35 INFO Received request for more parts method=POST path=/2476=== NAME TestOrphanedObjectsGCStressTest2477 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2478=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure24792026/10/01 08:28:35 INFO Received uploads request method=POST path=/2480=== NAME TestOrphanedObjectsGCStressTest2481 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion24822026-10-01 08:28:36.051 UTC [91693] ERROR: relation "goose_db_version" does not exist at character 3624832026-10-01 08:28:36.051 UTC [91693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2484--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.26s)2485=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart24862026/10/01 08:28:36 INFO Received complete multipart upload request method=POST path=/2487=== CONT TestPush_RejectsBadRequests/root_not_in_objects24882026/10/01 08:28:36 INFO Received push request method=POST path=/api/pushes2489=== CONT TestPush_RejectsBadRequests/no_objects24902026/10/01 08:28:36 INFO Received push request method=POST path=/api/pushes2491=== CONT TestPush_RejectsBadRequests/bad_root24922026/10/01 08:28:36 INFO Received push request method=POST path=/api/pushes2493=== CONT TestPush_RejectsBadRequests/no_roots24942026/10/01 08:28:36 INFO Received push request method=POST path=/api/pushes2495=== CONT TestParseSingleRange/none2496=== CONT TestParseSingleRange/open-ended2497=== CONT TestParseSingleRange/start_far_past_EOF2498=== CONT TestParseSingleRange/start_past_EOF2499=== CONT TestParseSingleRange/single_byte2500--- PASS: TestPush_RejectsBadRequests (2.21s)2501 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2502 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2503 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2504 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2505=== CONT TestParseSingleRange/suffix_exceeds_size2506=== CONT TestParseSingleRange/suffix2507=== CONT TestParseSingleRange/end_clamped_to_size2508=== CONT TestParseSingleRange/malformed_both_empty2509=== CONT TestParseSingleRange/closed2510=== CONT TestParseSingleRange/malformed_end_before_start2511=== CONT TestParseSingleRange/multi-range_ignored2512=== CONT TestParseSingleRange/malformed_no_dash2513=== CONT TestParseSingleRange/unknown_unit2514--- PASS: TestParseSingleRange (0.00s)2515 --- PASS: TestParseSingleRange/none (0.00s)2516 --- PASS: TestParseSingleRange/open-ended (0.00s)2517 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2518 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2519 --- PASS: TestParseSingleRange/single_byte (0.00s)2520 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2521 --- PASS: TestParseSingleRange/suffix (0.00s)2522 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2523 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2524 --- PASS: TestParseSingleRange/closed (0.00s)2525 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2526 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2527 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2528 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2529=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows25302026/10/01 08:28:36 OK 20241026095416_initial_model.sql (33.52ms)25312026/10/01 08:28:36 OK 20251210153512_drop_unused_gin_index.sql (479.08µs)25322026/10/01 08:28:36 OK 20251218171726_add_pins.sql (987.33µs)25332026/10/01 08:28:36 OK 20260628120000_add_object_size_and_stats.sql (1.14ms)25342026/10/01 08:28:36 OK 20260905000000_add_claims.sql (1.05ms)25352026-10-01 08:28:36.116 UTC [91696] ERROR: relation "goose_db_version" does not exist at character 3625362026-10-01 08:28:36.116 UTC [91696] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25372026/10/01 08:28:36 OK 20260920000000_drop_claims.sql (723.46µs)25382026/10/01 08:28:36 OK 20260923120000_add_pushes.sql (389.21µs)25392026/10/01 08:28:36 goose: successfully migrated database to version: 2026092312000025402026/10/01 08:28:36 OK 1_commit_pending_closure.sql (1.05ms)25412026/10/01 08:28:36 OK 2_object_stats_trigger.sql (220.46µs)25422026/10/01 08:28:36 OK 3_commit_push.sql (174.08µs)25432026/10/01 08:28:36 goose: up to current file version: 32544--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2545 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2546 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2547 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.33s)2548=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check25492026/10/01 08:28:36 OK 20241026095416_initial_model.sql (64.36ms)25502026/10/01 08:28:36 OK 20251210153512_drop_unused_gin_index.sql (7.2ms)25512026/10/01 08:28:36 OK 20251218171726_add_pins.sql (7.14ms)25522026/10/01 08:28:36 OK 20260628120000_add_object_size_and_stats.sql (16.82ms)25532026/10/01 08:28:36 OK 20260905000000_add_claims.sql (26.95ms)25542026/10/01 08:28:36 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02555=== NAME TestClientIntegration2556 client_integration_test.go:323: Objects in database after GC:2557 client_integration_test.go:323: Successfully deleted all objects with GC --force25582026/10/01 08:28:36 OK 20260920000000_drop_claims.sql (16.81ms)25592026/10/01 08:28:36 OK 20260923120000_add_pushes.sql (16.29ms)25602026/10/01 08:28:36 goose: successfully migrated database to version: 2026092312000025612026/10/01 08:28:36 OK 1_commit_pending_closure.sql (1.26ms)25622026/10/01 08:28:36 OK 2_object_stats_trigger.sql (232.46µs)25632026/10/01 08:28:36 OK 3_commit_push.sql (190.04µs)25642026/10/01 08:28:36 goose: up to current file version: 32565--- PASS: TestReadProxyNarinfo (1.73s)2566=== CONT TestResolveDBConnectionString/flag_wins2567=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2568=== CONT TestResolveDBConnectionString/nothing_configured2569=== CONT TestResolveDBConnectionString/missing_file_is_an_error2570=== CONT TestResolveDBConnectionString/file_when_flag_empty2571=== CONT TestServerTLSConfig/no_client_CA2572=== CONT TestServerTLSConfig/not_a_PEM_file2573--- PASS: TestResolveDBConnectionString (0.03s)2574 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2575 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2576 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2577 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2578 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2579--- PASS: TestClientIntegration (5.24s)2580=== CONT TestServerTLSConfig/missing_CA_file2581=== CONT TestCacheConfigHandler/full_config,_no_issuer2582=== CONT TestCacheConfigHandler/no_signing_keys2583=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2584=== CONT TestCacheConfigHandler/no_cache_url_configured2585--- PASS: TestCacheConfigHandler (0.00s)2586 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2587 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2588 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2589 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2590=== CONT TestClientErrorHandling/InvalidStorePath2591--- PASS: TestServerTLSConfig (0.00s)2592 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2593 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2594 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2595=== CONT TestClientErrorHandling/ServerNotAvailable25962026-10-01 08:28:36.461 UTC [91703] ERROR: relation "goose_db_version" does not exist at character 3625972026-10-01 08:28:36.461 UTC [91703] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25982026-10-01 08:28:36.472 UTC [91704] ERROR: relation "goose_db_version" does not exist at character 3625992026-10-01 08:28:36.472 UTC [91704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26002026/10/01 08:28:36 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/present2601--- PASS: TestReadProxyNarStreaming (1.74s)2602=== CONT TestClientErrorHandling/InvalidAuthToken26032026/10/01 08:28:36 OK 20241026095416_initial_model.sql (131.3ms)26042026/10/01 08:28:36 OK 20251210153512_drop_unused_gin_index.sql (8ms)26052026/10/01 08:28:36 OK 20241026095416_initial_model.sql (121.47ms)26062026/10/01 08:28:36 OK 20251210153512_drop_unused_gin_index.sql (766.67µs)26072026/10/01 08:28:36 OK 20251218171726_add_pins.sql (2.84ms)26082026/10/01 08:28:36 OK 20251218171726_add_pins.sql (2.23ms)26092026/10/01 08:28:36 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.827826ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26102026/10/01 08:28:36 OK 20260628120000_add_object_size_and_stats.sql (11.27ms)26112026/10/01 08:28:36 OK 20260628120000_add_object_size_and_stats.sql (21.37ms)26122026-10-01 08:28:36.670 UTC [91709] ERROR: relation "goose_db_version" does not exist at character 3626132026-10-01 08:28:36.670 UTC [91709] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26142026/10/01 08:28:36 OK 20260905000000_add_claims.sql (21.27ms)26152026/10/01 08:28:36 OK 20260905000000_add_claims.sql (18.62ms)26162026/10/01 08:28:36 OK 20260920000000_drop_claims.sql (8.49ms)26172026/10/01 08:28:36 OK 20260923120000_add_pushes.sql (6.51ms)26182026/10/01 08:28:36 goose: successfully migrated database to version: 2026092312000026192026/10/01 08:28:36 OK 1_commit_pending_closure.sql (1.48ms)26202026/10/01 08:28:36 OK 2_object_stats_trigger.sql (238.92µs)26212026/10/01 08:28:36 OK 3_commit_push.sql (195.58µs)26222026/10/01 08:28:36 goose: up to current file version: 326232026/10/01 08:28:36 OK 20260920000000_drop_claims.sql (15.99ms)26242026/10/01 08:28:36 OK 20260923120000_add_pushes.sql (28.14ms)26252026/10/01 08:28:36 goose: successfully migrated database to version: 2026092312000026262026/10/01 08:28:36 OK 1_commit_pending_closure.sql (1.67ms)26272026/10/01 08:28:36 OK 2_object_stats_trigger.sql (262.46µs)26282026/10/01 08:28:36 OK 3_commit_push.sql (200.38µs)26292026/10/01 08:28:36 goose: up to current file version: 326302026/10/01 08:28:36 OK 20241026095416_initial_model.sql (75.81ms)26312026/10/01 08:28:36 OK 20251210153512_drop_unused_gin_index.sql (6.22ms)26322026/10/01 08:28:36 OK 20251218171726_add_pins.sql (8.66ms)26332026/10/01 08:28:36 OK 20260628120000_add_object_size_and_stats.sql (23.3ms)26342026-10-01 08:28:36.861 UTC [91710] ERROR: relation "goose_db_version" does not exist at character 3626352026-10-01 08:28:36.861 UTC [91710] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26362026/10/01 08:28:36 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.199434ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26372026/10/01 08:28:36 OK 20260905000000_add_claims.sql (49.26ms)26382026/10/01 08:28:36 OK 20260920000000_drop_claims.sql (16.86ms)26392026/10/01 08:28:36 INFO Starting HTTP server address=127.0.0.1:6075226402026/10/01 08:28:36 INFO Starting HTTP server address=/nix/var/nix/builds/nix-91269-3505625895/TestProxyHeadersOnlyTrustedOnSocket439598376/001/proxy.sock26412026/10/01 08:28:36 WARN mTLS auth: subject not in bound subjects subject="CN=someone"26422026/10/01 08:28:36 INFO Shutdown signal received, draining in-flight requests timeout=10s2643--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.88s)2644=== CONT TestService_RequireScope_OIDC/builder_may_write26452026/10/01 08:28:36 OK 20260923120000_add_pushes.sql (23.55ms)26462026/10/01 08:28:36 goose: successfully migrated database to version: 202609231200002647=== CONT TestService_RequireScope_OIDC/static_token_may_admin2648=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2649=== CONT TestService_RequireScope_OIDC/writer_implies_read2650=== CONT TestService_RequireScope_OIDC/reader_may_read2651=== CONT TestService_RequireScope_OIDC/static_token_may_write2652=== CONT TestService_RequireScope_OIDC/ops_may_not_write2653=== CONT TestService_RequireScope_OIDC/reader_may_not_write2654=== CONT TestService_RequireScope_OIDC/ops_may_admin2655=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2656=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token26572026/10/01 08:28:36 OK 1_commit_pending_closure.sql (3.39ms)26582026/10/01 08:28:36 OK 2_object_stats_trigger.sql (639.46µs)26592026/10/01 08:28:36 OK 3_commit_push.sql (390.46µs)26602026/10/01 08:28:36 goose: up to current file version: 32661=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26622026/10/01 08:28:36 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]2663=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2664=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26652026/10/01 08:28:36 WARN Authentication failed token_preview=eyJhbGciOi...XZ5so_ksRw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2666=== CONT TestIsValidCachePath/narinfo2667=== CONT TestIsValidCachePath/index.html2668=== CONT TestIsValidCachePath/short_hash2669=== CONT TestIsValidCachePath/wrong_extension2670=== CONT TestIsValidCachePath/leading_slash2671=== CONT TestIsValidCachePath/empty2672=== CONT TestIsValidCachePath/random_path2673=== CONT TestIsValidCachePath/invalid_char_u2674=== CONT TestIsValidCachePath/invalid_char_e2675=== CONT TestIsValidCachePath/traversal_in_middle2676=== CONT TestIsValidCachePath/traversal_parent2677=== CONT TestIsValidCachePath/nar_uncompressed2678=== CONT TestIsValidCachePath/nix-cache-info2679=== CONT TestIsValidCachePath/realisation2680=== CONT TestIsValidCachePath/log2681=== CONT TestIsValidCachePath/ls2682=== CONT TestIsValidCachePath/nar_xz2683=== CONT TestIsValidCachePath/nar_bz22684=== CONT TestIsValidCachePath/nar_zst2685=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2686--- PASS: TestIsValidCachePath (0.00s)2687 --- PASS: TestIsValidCachePath/narinfo (0.00s)2688 --- PASS: TestIsValidCachePath/index.html (0.00s)2689 --- PASS: TestIsValidCachePath/short_hash (0.00s)2690 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2691 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2692 --- PASS: TestIsValidCachePath/empty (0.00s)2693 --- PASS: TestIsValidCachePath/random_path (0.00s)2694 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2695 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2696 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2697 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2698 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2699 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2700 --- PASS: TestIsValidCachePath/realisation (0.00s)2701 --- PASS: TestIsValidCachePath/log (0.00s)2702 --- PASS: TestIsValidCachePath/ls (0.00s)2703 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2704 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2705 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2706 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2707--- PASS: TestService_RequireScope_OIDC (2.57s)2708 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2709 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2710 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2711 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2712 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2713 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2714 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2715 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2716 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2717 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2718--- PASS: TestService_AuthMiddleware_OIDC (2.73s)2719 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2720 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2721 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2722 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)27232026/10/01 08:28:37 OK 20241026095416_initial_model.sql (133.09ms)27242026/10/01 08:28:37 OK 20251210153512_drop_unused_gin_index.sql (13.04ms)27252026/10/01 08:28:37 OK 20251218171726_add_pins.sql (24.83ms)27262026/10/01 08:28:37 OK 20260628120000_add_object_size_and_stats.sql (39.97ms)27272026/10/01 08:28:37 OK 20260905000000_add_claims.sql (69.48ms)27282026/10/01 08:28:37 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=879.422499ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27292026/10/01 08:28:37 OK 20260920000000_drop_claims.sql (63.97ms)27302026/10/01 08:28:37 OK 20260923120000_add_pushes.sql (13.9ms)27312026/10/01 08:28:37 goose: successfully migrated database to version: 2026092312000027322026/10/01 08:28:37 OK 1_commit_pending_closure.sql (1.14ms)27332026/10/01 08:28:37 OK 2_object_stats_trigger.sql (270.79µs)27342026/10/01 08:28:37 OK 3_commit_push.sql (238.63µs)27352026/10/01 08:28:37 goose: up to current file version: 32736--- PASS: TestReadProxy404 (2.17s)27372026-10-01 08:28:37.681 UTC [91716] ERROR: relation "goose_db_version" does not exist at character 3627382026-10-01 08:28:37.681 UTC [91716] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2739=== NAME TestClientCADerivations2740 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-91269-3505625895/TestClientCADerivations1082117096/001/store/wqdf8a0wli0rzcak1prry3sxh0i2bdwd-ca-test2741--- PASS: TestReadProxyInvalidPath (2.11s)2742=== NAME TestClientCADerivations2743 client_ca_test.go:139: Found 1 dependencies (including self)27442026-10-01 08:28:37.827 UTC [91720] ERROR: relation "goose_db_version" does not exist at character 3627452026-10-01 08:28:37.827 UTC [91720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27462026/10/01 08:28:37 OK 20241026095416_initial_model.sql (110.2ms)27472026/10/01 08:28:37 OK 20251210153512_drop_unused_gin_index.sql (9.53ms)27482026/10/01 08:28:37 OK 20251218171726_add_pins.sql (14.27ms)27492026/10/01 08:28:37 OK 20260628120000_add_object_size_and_stats.sql (10.85ms)2750=== NAME TestOrphanedObjectsGCStressTest2751 orphaned_objects_gc_test.go:509: Stress test completed successfully:2752 orphaned_objects_gc_test.go:510: - Active objects preserved: 202753 orphaned_objects_gc_test.go:511: - Objects deleted: 2102754 orphaned_objects_gc_test.go:512: - Total GC'd: 2102755--- PASS: TestOrphanedObjectsGCStressTest (9.46s)27562026-10-01 08:28:37.889 UTC [91724] ERROR: relation "goose_db_version" does not exist at character 3627572026-10-01 08:28:37.889 UTC [91724] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27582026/10/01 08:28:37 OK 20260905000000_add_claims.sql (41.15ms)27592026/10/01 08:28:37 INFO Received push request method=POST path=/api/pushes27602026/10/01 08:28:37 OK 20260920000000_drop_claims.sql (13.36ms)27612026/10/01 08:28:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27622026/10/01 08:28:37 INFO Uploading wqdf8a0wli0rzcak1prry3sxh0i2bdwd-ca-test (144B)27632026/10/01 08:28:37 OK 20260923120000_add_pushes.sql (4.36ms)27642026/10/01 08:28:37 goose: successfully migrated database to version: 2026092312000027652026/10/01 08:28:37 OK 20241026095416_initial_model.sql (70.71ms)27662026/10/01 08:28:37 OK 1_commit_pending_closure.sql (1.32ms)27672026/10/01 08:28:37 OK 2_object_stats_trigger.sql (511.42µs)27682026/10/01 08:28:37 OK 3_commit_push.sql (258.33µs)27692026/10/01 08:28:37 goose: up to current file version: 327702026/10/01 08:28:37 OK 20251210153512_drop_unused_gin_index.sql (6.34ms)27712026/10/01 08:28:37 WARN Failed to register uploaded object key=wqdf8a0wli0rzcak1prry3sxh0i2bdwd.ls error="server returned 404: 404 page not found\n"27722026/10/01 08:28:37 WARN Failed to register uploaded object key=log/2i6ra8c82kfxkg345acilp2mbk1yk81g-ca-test.drv error="server returned 404: 404 page not found\n"27732026/10/01 08:28:37 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"27742026/10/01 08:28:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27752026/10/01 08:28:37 INFO Signed narinfos id=1 count=127762026/10/01 08:28:37 INFO Uploading 1 narinfos27772026/10/01 08:28:37 OK 20251218171726_add_pins.sql (27.16ms)27782026/10/01 08:28:37 INFO Received complete push request method=POST path=/api/pushes/1/complete27792026/10/01 08:28:37 WARN Failed to register uploaded object key=wqdf8a0wli0rzcak1prry3sxh0i2bdwd.narinfo error="server returned 404: 404 page not found\n"27802026/10/01 08:28:37 INFO Upload complete. (161ms)2781=== NAME TestClientCADerivations2782 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-91269-3505625895/TestClientCADerivations1082117096/001/store/wqdf8a0wli0rzcak1prry3sxh0i2bdwd-ca-test2783 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2784 Compression: zstd2785 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2786 NarSize: 1442787 References: 2788 Deriver: /nix/var/nix/builds/nix-91269-3505625895/TestClientCADerivations1082117096/001/store/2i6ra8c82kfxkg345acilp2mbk1yk81g-ca-test.drv2789 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2790 client_ca_test.go:185: Checking for realisation files in S3...2791 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2792 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache27932026/10/01 08:28:37 OK 20260628120000_add_object_size_and_stats.sql (23.47ms)27942026-10-01 08:28:37.998 UTC [91727] ERROR: relation "goose_db_version" does not exist at character 3627952026-10-01 08:28:37.998 UTC [91727] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27962026/10/01 08:28:37 OK 20241026095416_initial_model.sql (69.89ms)27972026/10/01 08:28:38 OK 20251210153512_drop_unused_gin_index.sql (11.98ms)27982026/10/01 08:28:38 OK 20260905000000_add_claims.sql (39.16ms)27992026/10/01 08:28:38 OK 20251218171726_add_pins.sql (24.21ms)28002026/10/01 08:28:38 OK 20260920000000_drop_claims.sql (28.18ms)28012026/10/01 08:28:38 OK 20260628120000_add_object_size_and_stats.sql (24.5ms)28022026/10/01 08:28:38 OK 20260923120000_add_pushes.sql (8.12ms)28032026/10/01 08:28:38 goose: successfully migrated database to version: 2026092312000028042026/10/01 08:28:38 OK 1_commit_pending_closure.sql (947.88µs)28052026/10/01 08:28:38 OK 2_object_stats_trigger.sql (219.04µs)28062026/10/01 08:28:38 OK 3_commit_push.sql (192.25µs)28072026/10/01 08:28:38 goose: up to current file version: 32808 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket70?endpoint=http://localhost:60440®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-91269-3505625895/TestClientCADerivations1082117096/001/store'2809 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 128102026/10/01 08:28:38 OK 20260905000000_add_claims.sql (44.86ms)28112026/10/01 08:28:38 OK 20260920000000_drop_claims.sql (25.47ms)28122026/10/01 08:28:38 OK 20260923120000_add_pushes.sql (13.21ms)28132026/10/01 08:28:38 goose: successfully migrated database to version: 2026092312000028142026/10/01 08:28:38 OK 1_commit_pending_closure.sql (1.12ms)28152026/10/01 08:28:38 OK 2_object_stats_trigger.sql (257.54µs)28162026/10/01 08:28:38 OK 3_commit_push.sql (228.75µs)28172026/10/01 08:28:38 goose: up to current file version: 328182026/10/01 08:28:38 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.739668696s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2819--- PASS: TestClientCADerivations (3.08s)28202026/10/01 08:28:38 OK 20241026095416_initial_model.sql (129.62ms)28212026/10/01 08:28:38 OK 20251210153512_drop_unused_gin_index.sql (7.13ms)28222026/10/01 08:28:38 OK 20251218171726_add_pins.sql (12.38ms)28232026/10/01 08:28:38 OK 20260628120000_add_object_size_and_stats.sql (11.58ms)28242026/10/01 08:28:38 INFO Received uploads request method=POST path=/api/pending_closures28252026/10/01 08:28:38 INFO Aborted multipart uploads count=028262026/10/01 08:28:38 WARN Force mode enabled - objects will be deleted immediately without grace period28272026/10/01 08:28:38 OK 20260905000000_add_claims.sql (52.7ms)28282026/10/01 08:28:38 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=028292026/10/01 08:28:38 INFO Vacuumed table table=pending_closures28302026/10/01 08:28:38 INFO Vacuumed table table=pending_objects28312026/10/01 08:28:38 INFO Vacuumed table table=multipart_uploads28322026/10/01 08:28:38 INFO Vacuumed table table=closures28332026/10/01 08:28:38 INFO Vacuumed table table=objects28342026/10/01 08:28:38 OK 20260920000000_drop_claims.sql (29.92ms)28352026/10/01 08:28:38 OK 20260923120000_add_pushes.sql (18.26ms)28362026/10/01 08:28:38 goose: successfully migrated database to version: 2026092312000028372026/10/01 08:28:38 OK 1_commit_pending_closure.sql (3.01ms)28382026/10/01 08:28:38 OK 2_object_stats_trigger.sql (931.25µs)28392026/10/01 08:28:38 OK 3_commit_push.sql (723.71µs)28402026/10/01 08:28:38 goose: up to current file version: 328412026/10/01 08:28:38 INFO Received uploads request method=POST path=/api/pending_closures28422026/10/01 08:28:38 INFO Aborted multipart uploads count=028432026/10/01 08:28:38 WARN Force mode enabled - objects will be deleted immediately without grace period28442026/10/01 08:28:38 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=028452026/10/01 08:28:38 INFO Vacuumed table table=pending_closures28462026/10/01 08:28:38 INFO Vacuumed table table=pending_objects28472026/10/01 08:28:38 INFO Vacuumed table table=multipart_uploads28482026/10/01 08:28:38 INFO Vacuumed table table=closures28492026/10/01 08:28:38 INFO Vacuumed table table=objects2850--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2851 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.27s)2852 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.42s)28532026/10/01 08:28:38 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"28542026/10/01 08:28:39 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"28552026/10/01 08:28:39 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-config28562026/10/01 08:28:40 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.395314ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28572026/10/01 08:28:40 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=378.822482ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28582026/10/01 08:28:40 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=833.682252ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28592026/10/01 08:28:41 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.473130401s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28602026/10/01 08:28:42 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"28612026/10/01 08:28:42 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-config28622026/10/01 08:28:43 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.288128ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28632026/10/01 08:28:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=432.322062ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28642026/10/01 08:28:43 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=762.259749ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28652026/10/01 08:28:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.482486752s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28662026/10/01 08:28:45 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_closures28672026/10/01 08:28:46 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.839134ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28682026/10/01 08:28:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=435.869696ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28692026/10/01 08:28:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=753.389666ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28702026/10/01 08:28:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.555708842s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2871--- PASS: TestClientErrorHandling (0.00s)2872 --- PASS: TestClientErrorHandling/InvalidStorePath (2.42s)2873 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.47s)2874 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.67s)2875PASS2876{"timestamp":"2026-10-01T08:28:49.025675Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60488","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}28772026-10-01 08:28:49.132 UTC [91337] LOG: received smart shutdown request28782026-10-01 08:28:49.132 UTC [91337] LOG: background worker "logical replication launcher" (PID 91347) exited with exit code 128792026-10-01 08:28:49.168 UTC [91342] LOG: shutting down28802026-10-01 08:28:49.168 UTC [91342] LOG: checkpoint starting: shutdown immediate28812026-10-01 08:28:50.332 UTC [91342] LOG: checkpoint complete: wrote 12649 buffers (77.2%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 22 recycled; write=0.694 s, sync=0.436 s, total=1.164 s; sync files=25606, longest=0.001 s, average=0.001 s; distance=354398 kB, estimate=354398 kB; lsn=0/171A49A0, redo lsn=0/171A49A028822026-10-01 08:28:50.337 UTC [91337] LOG: database system is shut down2883Running OIDC tests...2884=== RUN TestAudienceForIssuer2885=== PAUSE TestAudienceForIssuer2886=== RUN TestGlobMatch2887=== PAUSE TestGlobMatch2888=== RUN TestValidateToken_ValidToken2889=== PAUSE TestValidateToken_ValidToken2890=== RUN TestValidateToken_WrongAudience2891=== PAUSE TestValidateToken_WrongAudience2892=== RUN TestValidateToken_Expired2893=== PAUSE TestValidateToken_Expired2894=== RUN TestValidateToken_BoundClaimsMismatch2895=== PAUSE TestValidateToken_BoundClaimsMismatch2896=== RUN TestValidateToken_BoundSubjectMismatch2897=== PAUSE TestValidateToken_BoundSubjectMismatch2898=== RUN TestValidateToken_MultipleProviders2899=== PAUSE TestValidateToken_MultipleProviders2900=== RUN TestValidateToken_NoMatchingProvider2901=== PAUSE TestValidateToken_NoMatchingProvider2902=== RUN TestValidateToken_KubernetesServiceAccount2903=== PAUSE TestValidateToken_KubernetesServiceAccount2904=== RUN TestNewValidator_KubernetesRequiresCA2905=== PAUSE TestNewValidator_KubernetesRequiresCA2906=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2907=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2908=== RUN TestPins_ReservedForMatchingRule2909=== PAUSE TestPins_ReservedForMatchingRule2910=== RUN TestPins_TopLevelShorthand2911=== PAUSE TestPins_TopLevelShorthand2912=== RUN TestPins_ConfigValidation2913=== PAUSE TestPins_ConfigValidation2914=== RUN TestScopes_LegacyProviderDefaultsToWrite2915=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2916=== RUN TestScopes_Rules2917=== PAUSE TestScopes_Rules2918=== RUN TestScopes_ConfigValidation2919=== PAUSE TestScopes_ConfigValidation2920=== CONT TestAudienceForIssuer2921--- PASS: TestAudienceForIssuer (0.00s)2922=== CONT TestValidateToken_Expired2923=== CONT TestValidateToken_BoundClaimsMismatch2924=== CONT TestValidateToken_KubernetesServiceAccount2925=== CONT TestPins_ConfigValidation2926=== CONT TestPins_ReservedForMatchingRule2927=== CONT TestValidateToken_ValidToken2928=== CONT TestValidateToken_MultipleProviders2929=== CONT TestValidateToken_NoMatchingProvider2930=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2931--- PASS: TestPins_ConfigValidation (0.01s)2932=== CONT TestScopes_ConfigValidation2933--- PASS: TestScopes_ConfigValidation (0.00s)2934=== CONT TestScopes_Rules2935=== CONT TestValidateToken_WrongAudience29362026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60830/oidc2937--- PASS: TestValidateToken_BoundClaimsMismatch (0.03s)2938=== CONT TestNewValidator_KubernetesRequiresCA29392026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60832/oidc2940--- PASS: TestValidateToken_ValidToken (0.04s)2941=== CONT TestGlobMatch2942=== RUN TestGlobMatch/foo_foo2943=== PAUSE TestGlobMatch/foo_foo2944=== RUN TestGlobMatch/foo_bar2945=== PAUSE TestGlobMatch/foo_bar2946=== RUN TestGlobMatch/*_2947=== PAUSE TestGlobMatch/*_2948=== RUN TestGlobMatch/*_anything2949=== PAUSE TestGlobMatch/*_anything2950=== RUN TestGlobMatch/foo*_foo2951=== PAUSE TestGlobMatch/foo*_foo2952=== RUN TestGlobMatch/foo*_foobar2953=== PAUSE TestGlobMatch/foo*_foobar2954=== RUN TestGlobMatch/foo*_bar2955=== PAUSE TestGlobMatch/foo*_bar2956=== RUN TestGlobMatch/*bar_bar2957=== PAUSE TestGlobMatch/*bar_bar2958=== RUN TestGlobMatch/*bar_foobar2959=== PAUSE TestGlobMatch/*bar_foobar2960=== RUN TestGlobMatch/*bar_foo2961=== PAUSE TestGlobMatch/*bar_foo2962=== RUN TestGlobMatch/foo*bar_foobar2963=== PAUSE TestGlobMatch/foo*bar_foobar2964=== RUN TestGlobMatch/foo*bar_foo123bar2965=== PAUSE TestGlobMatch/foo*bar_foo123bar2966=== RUN TestGlobMatch/foo*bar_foobarbaz2967=== PAUSE TestGlobMatch/foo*bar_foobarbaz2968=== RUN TestGlobMatch/*/*_foo/bar2969=== PAUSE TestGlobMatch/*/*_foo/bar2970=== RUN TestGlobMatch/*/*_foo2971=== PAUSE TestGlobMatch/*/*_foo2972=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2973=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2974=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02975=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02976=== RUN TestGlobMatch/refs/*/main_refs/heads/main2977=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2978=== RUN TestGlobMatch/fo?_foo2979=== PAUSE TestGlobMatch/fo?_foo2980=== RUN TestGlobMatch/fo?_fo2981=== PAUSE TestGlobMatch/fo?_fo2982=== RUN TestGlobMatch/fo?_fooo2983=== PAUSE TestGlobMatch/fo?_fooo2984=== RUN TestGlobMatch/?oo_foo2985=== PAUSE TestGlobMatch/?oo_foo2986=== RUN TestGlobMatch/?oo_boo2987=== PAUSE TestGlobMatch/?oo_boo2988=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2989=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2990=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2991=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2992=== CONT TestValidateToken_BoundSubjectMismatch29932026/10/01 08:28:51 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:608342994--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)2995=== CONT TestPins_TopLevelShorthand29962026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60837/oidc29972026/10/01 08:28:51 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232998--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)2999=== CONT TestScopes_LegacyProviderDefaultsToWrite3000--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)3001=== CONT TestGlobMatch/foo_foo3002=== CONT TestGlobMatch/*/*_foo/bar3003=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3004=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3005=== CONT TestGlobMatch/?oo_boo3006=== CONT TestGlobMatch/?oo_foo3007=== CONT TestGlobMatch/fo?_fooo3008=== CONT TestGlobMatch/fo?_fo3009=== CONT TestGlobMatch/fo?_foo3010=== CONT TestGlobMatch/refs/*/main_refs/heads/main3011=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03012=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3013=== CONT TestGlobMatch/*/*_foo3014=== CONT TestGlobMatch/*bar_bar3015=== CONT TestGlobMatch/foo*bar_foobarbaz3016=== CONT TestGlobMatch/foo*bar_foo123bar3017=== CONT TestGlobMatch/foo*bar_foobar3018=== CONT TestGlobMatch/*bar_foo3019=== CONT TestGlobMatch/*bar_foobar3020=== CONT TestGlobMatch/foo*_bar3021=== CONT TestGlobMatch/foo*_foobar3022=== CONT TestGlobMatch/foo*_foo3023=== CONT TestGlobMatch/*_anything3024=== CONT TestGlobMatch/*_3025=== CONT TestGlobMatch/foo_bar3026--- PASS: TestGlobMatch (0.00s)3027 --- PASS: TestGlobMatch/foo_foo (0.00s)3028 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3029 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3030 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3031 --- PASS: TestGlobMatch/?oo_boo (0.00s)3032 --- PASS: TestGlobMatch/?oo_foo (0.00s)3033 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3034 --- PASS: TestGlobMatch/fo?_fo (0.00s)3035 --- PASS: TestGlobMatch/fo?_foo (0.00s)3036 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3037 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3038 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3039 --- PASS: TestGlobMatch/*/*_foo (0.00s)3040 --- PASS: TestGlobMatch/*bar_bar (0.00s)3041 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3042 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3043 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3044 --- PASS: TestGlobMatch/*bar_foo (0.00s)3045 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3046 --- PASS: TestGlobMatch/foo*_bar (0.00s)3047 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3048 --- PASS: TestGlobMatch/foo*_foo (0.00s)3049 --- PASS: TestGlobMatch/*_anything (0.00s)3050 --- PASS: TestGlobMatch/*_ (0.00s)3051 --- PASS: TestGlobMatch/foo_bar (0.00s)30522026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60841/oidc3053--- PASS: TestPins_TopLevelShorthand (0.02s)30542026/10/01 08:28:51 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60836/oidc3055--- PASS: TestValidateToken_NoMatchingProvider (0.09s)30562026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60846/oidc3057--- PASS: TestScopes_Rules (0.10s)30582026/10/01 08:28:51 http: TLS handshake error from 127.0.0.1:60849: remote error: tls: bad certificate3059--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)30602026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60850/oidc30612026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60852/oidc3062--- PASS: TestPins_ReservedForMatchingRule (0.12s)3063--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)30642026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60854/oidc3065--- PASS: TestValidateToken_WrongAudience (0.15s)30662026/10/01 08:28:51 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60845/oidc30672026/10/01 08:28:51 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:60856/oidc3068--- PASS: TestValidateToken_MultipleProviders (0.16s)30692026/10/01 08:28:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60859/oidc3070--- PASS: TestValidateToken_Expired (0.18s)3071PASS3072Running hook tests...3073=== RUN TestSendPathsEmpty3074=== PAUSE TestSendPathsEmpty3075=== RUN TestQueueEnqueueAndFetch3076=== PAUSE TestQueueEnqueueAndFetch3077=== RUN TestQueueDeduplication3078=== PAUSE TestQueueDeduplication3079=== RUN TestQueueRemove3080=== PAUSE TestQueueRemove3081=== RUN TestQueueFetchBatchLimit3082=== PAUSE TestQueueFetchBatchLimit3083=== RUN TestQueueRetryMovesToBack3084=== PAUSE TestQueueRetryMovesToBack3085=== RUN TestQueueFetchRemoveLifecycle3086=== PAUSE TestQueueFetchRemoveLifecycle3087=== RUN TestQueueConcurrentWriters3088=== PAUSE TestQueueConcurrentWriters3089=== RUN TestQueueRemoveLargeClosure3090=== PAUSE TestQueueRemoveLargeClosure3091=== RUN TestServerClientIntegration3092=== PAUSE TestServerClientIntegration3093=== RUN TestServerQueueError3094=== PAUSE TestServerQueueError3095=== RUN TestGetListenerSocketActivation3096 server_test.go:210: === RUN TestGetListenerSocketActivation3097 --- PASS: TestGetListenerSocketActivation (0.00s)3098 PASS3099 3100--- PASS: TestGetListenerSocketActivation (0.01s)3101=== RUN TestDrainIsolatesPoisonPath3102=== PAUSE TestDrainIsolatesPoisonPath3103=== RUN TestRunNotBlockedByPoisonHead3104=== PAUSE TestRunNotBlockedByPoisonHead3105=== RUN TestDrainGivesUpWhenServerDown3106=== PAUSE TestDrainGivesUpWhenServerDown3107=== RUN TestFailedPathPrunedByLaterClosure3108=== PAUSE TestFailedPathPrunedByLaterClosure3109=== RUN TestWorkerUploadsAndRemoves3110=== PAUSE TestWorkerUploadsAndRemoves3111=== RUN TestWorkerSkipsGCdPaths3112=== PAUSE TestWorkerSkipsGCdPaths3113=== RUN TestWorkerPrunesClosureDeps3114=== PAUSE TestWorkerPrunesClosureDeps3115=== RUN TestDrainTimeout3116=== PAUSE TestDrainTimeout3117=== CONT TestSendPathsEmpty3118=== CONT TestServerQueueError3119--- PASS: TestSendPathsEmpty (0.00s)3120=== CONT TestQueueFetchBatchLimit3121=== CONT TestQueueRetryMovesToBack3122=== CONT TestQueueDeduplication3123=== CONT TestQueueFetchRemoveLifecycle3124=== CONT TestQueueConcurrentWriters3125=== CONT TestWorkerUploadsAndRemoves3126=== CONT TestQueueEnqueueAndFetch3127=== CONT TestQueueRemoveLargeClosure3128=== CONT TestServerClientIntegration31292026/10/01 08:28:51 ERROR Failed to queue paths error="permission denied" count=13130--- PASS: TestServerQueueError (0.00s)3131=== CONT TestQueueRemove3132--- PASS: TestServerClientIntegration (0.00s)3133=== CONT TestDrainGivesUpWhenServerDown3134--- PASS: TestQueueEnqueueAndFetch (0.01s)3135=== CONT TestFailedPathPrunedByLaterClosure31362026/10/01 08:28:51 INFO Upload queue status pending=231372026/10/01 08:28:51 INFO Uploading batch count=23138--- PASS: TestQueueFetchBatchLimit (0.01s)3139=== CONT TestRunNotBlockedByPoisonHead3140--- PASS: TestQueueRemove (0.01s)3141=== CONT TestWorkerPrunesClosureDeps31422026/10/01 08:28:51 INFO Uploading batch count=231432026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=231442026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainGivesUpWhenServerDown9720/002/a3145--- PASS: TestQueueRetryMovesToBack (0.01s)3146=== CONT TestDrainTimeout31472026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainGivesUpWhenServerDown9720/002/b31482026/10/01 08:28:51 INFO Uploading batch count=231492026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=231502026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainGivesUpWhenServerDown9720/002/c31512026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainGivesUpWhenServerDown9720/002/d3152--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3153=== CONT TestDrainIsolatesPoisonPath3154--- PASS: TestQueueDeduplication (0.01s)3155=== CONT TestWorkerSkipsGCdPaths31562026/10/01 08:28:51 INFO Uploading batch count=231572026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=231582026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainGivesUpWhenServerDown9720/002/e31592026/10/01 08:28:51 INFO Uploading batch count=131602026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=131612026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainGivesUpWhenServerDown9720/002/f31622026/10/01 08:28:51 INFO Uploading batch count=131632026/10/01 08:28:51 ERROR Drain finished with paths left in queue remaining=1031642026/10/01 08:28:51 INFO Uploading batch count=131652026/10/01 08:28:51 INFO Uploading batch count=231662026/10/01 08:28:51 INFO Upload queue status pending=331672026/10/01 08:28:51 INFO Uploading batch count=131682026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=131692026/10/01 08:28:51 INFO Upload queue status pending=231702026/10/01 08:28:51 INFO Uploading batch count=131712026/10/01 08:28:51 INFO Upload queue status pending=231722026/10/01 08:28:51 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-91269-3505625895/TestWorkerSkipsGCdPaths864290657/002/nonexistent31732026/10/01 08:28:51 INFO Uploading batch count=431742026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=431752026/10/01 08:28:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91269-3505625895/TestDrainIsolatesPoisonPath3166190792/002/bbb31762026/10/01 08:28:51 INFO Uploading batch count=13177--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)31782026/10/01 08:28:51 INFO Uploading batch count=131792026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=131802026/10/01 08:28:51 INFO Uploading batch count=131812026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=13182--- PASS: TestDrainGivesUpWhenServerDown (0.01s)31832026/10/01 08:28:51 INFO Uploading batch count=131842026/10/01 08:28:51 ERROR Upload failed error="upload failed" count=131852026/10/01 08:28:51 ERROR Drain finished with paths left in queue remaining=13186--- PASS: TestDrainIsolatesPoisonPath (0.01s)3187--- PASS: TestWorkerUploadsAndRemoves (0.03s)3188--- PASS: TestWorkerPrunesClosureDeps (0.03s)3189--- PASS: TestWorkerSkipsGCdPaths (0.02s)3190--- PASS: TestQueueRemoveLargeClosure (0.05s)3191--- PASS: TestQueueConcurrentWriters (0.13s)31922026/10/01 08:28:52 ERROR Upload failed error="context deadline exceeded" count=231932026/10/01 08:28:52 ERROR Drain finished with paths left in queue remaining=43194--- PASS: TestDrainTimeout (0.21s)31952026/10/01 08:28:52 INFO Uploading batch count=131962026/10/01 08:28:52 INFO Uploading batch count=131972026/10/01 08:28:52 INFO Uploading batch count=131982026/10/01 08:28:52 ERROR Upload failed error="upload failed" count=131992026/10/01 08:28:52 INFO Uploading batch count=132002026/10/01 08:28:52 ERROR Upload failed error="upload failed" count=132012026/10/01 08:28:52 INFO Uploading batch count=132022026/10/01 08:28:52 ERROR Upload failed error="upload failed" count=132032026/10/01 08:28:52 INFO Uploading batch count=132042026/10/01 08:28:52 ERROR Upload failed error="upload failed" count=132052026/10/01 08:28:52 ERROR Drain finished with paths left in queue remaining=13206--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3207PASS