niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #306
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestScriptTokenEmptyCommand96--- PASS: TestScriptTokenEmptyCommand (0.00s)97=== CONT TestFileTokenReadsAndCaches98=== CONT TestDoServerRequestAttachesToken99=== CONT TestScriptTokenScriptFails100=== CONT TestScriptTokenBadJSON101=== CONT TestScriptTokenEmptyToken102=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess103--- PASS: TestFileTokenReadsAndCaches (0.00s)104=== CONT TestCaseHackSuffix105=== CONT TestRateLimiterFeedback106=== CONT TestPathInfoCACompatibility107=== CONT TestParsePathInfoJSONMultiplePaths108=== CONT TestParsePathInfoJSON109=== CONT TestPathInfoHashCompatibility110=== CONT TestGetStorePathHash111=== CONT TestConvertHashToNix32112=== CONT TestResolveStorePath113=== RUN TestRateLimiterFeedback/429_enables_limiter1142026/10/01 09:18:07 WARN Rate limiter enabled after throttle name=server-test rate=5115=== PAUSE TestRateLimiterFeedback/429_enables_limiter116--- PASS: TestScriptTokenScriptFails (0.00s)117=== CONT TestStaticToken118--- PASS: TestStaticToken (0.00s)119=== CONT TestRegisterUploadedObjectReusesConnections120=== CONT TestScriptTokenCachesUntilRefresh121=== CONT TestEncodeNixBase32122=== CONT TestScriptTokenNoExpiryRerunsEveryCall123=== CONT TestDumpPathWriterError124=== CONT TestFileTokenEmpty125=== CONT TestUploadMultipart_PartsInParallel126=== CONT TestFileTokenMissing127=== CONT TestFilterOversizedClosures128=== CONT TestPartSizeForNAR129=== CONT TestEncodeNixBase32WithRealHash130--- PASS: TestResolveStorePath (0.00s)131=== CONT TestSetClientTLSErrors132=== RUN TestPathInfoCACompatibility/null_ca_field133=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths134=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths135=== RUN TestEncodeNixBase32/test_string_hash136=== PAUSE TestEncodeNixBase32/test_string_hash137=== RUN TestEncodeNixBase32/empty_input138=== PAUSE TestEncodeNixBase32/empty_input139=== PAUSE TestPathInfoCACompatibility/null_ca_field140=== RUN TestPathInfoCACompatibility/old_string_format_-_text141=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text142=== CONT TestSetClientTLSDoesNotMutateDefaultTransport143=== RUN TestParsePathInfoJSON/Nix_format144=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)145=== RUN TestGetStorePathHash/valid_store_path146=== RUN TestConvertHashToNix32/SRI_format_to_Nix32147=== RUN TestRateLimiterFeedback/503_enables_limiter148=== RUN TestFilterOversizedClosures/no_limit_keeps_everything149=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths150=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive151=== CONT TestSetClientTLS152--- PASS: TestScriptTokenBadJSON (0.00s)153--- PASS: TestFileTokenEmpty (0.00s)154=== RUN TestPartSizeForNAR/zero_stays_at_minimum155=== CONT TestClientSignaturesByStorePath156=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum157=== CONT TestDumpPathSingleFile158--- PASS: TestFileTokenMissing (0.00s)159--- PASS: TestClientSignaturesByStorePath (0.00s)160=== CONT TestDumpPathMatchesNix161=== RUN TestPartSizeForNAR/small_stays_at_minimum162=== PAUSE TestPartSizeForNAR/small_stays_at_minimum163=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum164=== RUN TestSetClientTLSErrors/missing_cert_file165=== PAUSE TestParsePathInfoJSON/Nix_format166=== RUN TestParsePathInfoJSON/Lix_format167=== PAUSE TestParsePathInfoJSON/Lix_format168=== RUN TestParsePathInfoJSON/empty_input169=== PAUSE TestParsePathInfoJSON/empty_input170=== RUN TestParsePathInfoJSON/whitespace_only171=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)172=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything173--- PASS: TestEncodeNixBase32WithRealHash (0.00s)174=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped175=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive176=== RUN TestPathInfoCACompatibility/new_structured_format_-_text177=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text178=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method179=== PAUSE TestRateLimiterFeedback/503_enables_limiter180=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter181=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter182=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter183=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter184=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon185=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon186=== PAUSE TestSetClientTLSErrors/missing_cert_file187=== RUN TestSetClientTLSErrors/missing_key_file188=== PAUSE TestSetClientTLSErrors/missing_key_file189=== RUN TestSetClientTLSErrors/missing_ca_file190=== PAUSE TestSetClientTLSErrors/missing_ca_file191=== RUN TestSetClientTLSErrors/invalid_ca_file192=== PAUSE TestSetClientTLSErrors/invalid_ca_file193=== CONT TestStreamPushReportsSignatures194=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped195=== RUN TestFilterOversizedClosures/all_closures_skipped196=== PAUSE TestFilterOversizedClosures/all_closures_skipped197=== PAUSE TestParsePathInfoJSON/whitespace_only198=== RUN TestParsePathInfoJSON/invalid_JSON199=== PAUSE TestParsePathInfoJSON/invalid_JSON200=== CONT TestShellSplitErrors201=== CONT TestStreamPushGivesUpOnDeadServer202--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)203--- PASS: TestDoServerRequestAttachesToken (0.03s)2042026/10/01 09:18:07 ERROR Upload failed error=boom count=12052026/10/01 09:18:07 ERROR Upload failed error="connection refused" count=20206--- PASS: TestStreamPushReportsSignatures (0.00s)2072026/10/01 09:18:07 ERROR Server seems unavailable, giving up on batch untried=17208=== CONT TestShellSplit209=== CONT TestEncodeNixBase32/test_string_hash210=== CONT TestEncodeNixBase32/empty_input211=== CONT TestRateLimiterFeedback/429_enables_limiter212=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum213=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter214=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method215=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts216=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts217=== RUN TestPartSizeForNAR/1_TiB218=== PAUSE TestPartSizeForNAR/1_TiB219=== RUN TestPartSizeForNAR/5_TiB_S3_max_object220=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object221=== RUN TestPartSizeForNAR/capped_at_5_GiB222=== PAUSE TestPartSizeForNAR/capped_at_5_GiB2232026/10/01 09:18:07 WARN Rate limiter enabled after throttle name=server-test rate=5224=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2252026/10/01 09:18:07 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:34669226=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI227=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512228=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512229=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter230=== CONT TestSetClientTLSErrors/missing_ca_file231=== CONT TestRateLimiterFeedback/503_enables_limiter2322026/10/01 09:18:07 WARN Rate limiter backed off name=server-test rate=5233=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32234=== RUN TestConvertHashToNix32/already_Nix32_format235=== PAUSE TestConvertHashToNix32/already_Nix32_format236=== RUN TestConvertHashToNix32/invalid_format237=== CONT TestSetClientTLSErrors/missing_cert_file238=== CONT TestSetClientTLSErrors/missing_key_file239=== CONT TestFilterOversizedClosures/no_limit_keeps_everything240=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2412026/10/01 09:18:07 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=2000242=== CONT TestSetClientTLSErrors/invalid_ca_file243=== PAUSE TestConvertHashToNix32/invalid_format244=== PAUSE TestGetStorePathHash/valid_store_path245=== RUN TestGetStorePathHash/basename_without_hyphen_should_error246=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error247=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error248=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error249=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error250=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error251=== CONT TestParsePathInfoJSON/whitespace_only252=== CONT TestPathInfoCACompatibility/null_ca_field253=== CONT TestParsePathInfoJSON/empty_input254=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method255=== CONT TestStreamPushReportsEveryPath256=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive257=== CONT TestUploadMultipart_SupersededByPeer258=== CONT TestStreamPushIsolatesFailures259=== CONT TestPathInfoCACompatibility/old_string_format_-_text260=== CONT TestPartSizeForNAR/zero_stays_at_minimum261=== RUN TestSetClientTLS/rejects_connection_without_client_cert262=== CONT TestPartSizeForNAR/capped_at_5_GiB263=== CONT TestParsePathInfoJSON/Lix_format2642026/10/01 09:18:07 ERROR Upload failed error="bad path" count=32652026/10/01 09:18:07 WARN Rate limiter enabled after throttle name=server-test rate=5266=== CONT TestPartSizeForNAR/1_TiB2672026/10/01 09:18:07 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:44165268=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts269=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon270=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512271=== CONT TestFilterOversizedClosures/all_closures_skipped2722026/10/01 09:18:07 WARN Rate limiter backed off name=server-test rate=52732026/10/01 09:18:07 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=50274=== CONT TestConvertHashToNix32/SRI_format_to_Nix32275=== CONT TestGetStorePathHash/valid_store_path276=== CONT TestConvertHashToNix32/already_Nix32_format277=== CONT TestConvertHashToNix32/invalid_format278=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error279=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum280=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error281=== RUN TestUploadMultipart_SupersededByPeer/exists282=== PAUSE TestUploadMultipart_SupersededByPeer/exists283=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)284--- PASS: TestShellSplitErrors (0.00s)285=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths286=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths287=== CONT TestStreamPushBatchesUnderLoad288=== CONT TestParsePathInfoJSON/Nix_format289=== CONT TestParsePathInfoJSON/invalid_JSON290=== CONT TestPathInfoCACompatibility/new_structured_format_-_text291=== CONT TestStreamPushRequestLine292=== CONT TestDoWithRetry_BodyReplayedViaGetBody2932026/10/01 09:18:07 ERROR Upload failed error=boom count=1294=== CONT TestPartSizeForNAR/small_stays_at_minimum295=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert296=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA297=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA298=== RUN TestSetClientTLS/preserves_debug_logging_transport299=== PAUSE TestSetClientTLS/preserves_debug_logging_transport300=== CONT TestSetClientTLS/rejects_connection_without_client_cert301=== CONT TestSetClientTLS/preserves_debug_logging_transport3022026/10/01 09:18:07 WARN Rate limiter enabled after throttle name=server-test rate=53032026/10/01 09:18:07 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:39531304=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3052026/10/01 09:18:07 WARN Rate limiter backed off name=server-test rate=5306=== CONT TestPartSizeForNAR/5_TiB_S3_max_object3072026/10/01 09:18:07 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:39531308=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI309=== CONT TestGetStorePathHash/basename_without_hyphen_should_error310=== RUN TestUploadMultipart_SupersededByPeer/missing311=== PAUSE TestUploadMultipart_SupersededByPeer/missing312=== CONT TestUploadMultipart_SupersededByPeer/exists313--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)314--- PASS: TestShellSplit (0.00s)315=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths316--- PASS: TestEncodeNixBase32 (0.00s)317 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)318 --- PASS: TestEncodeNixBase32/empty_input (0.00s)319--- PASS: TestCaseHackSuffix (0.03s)320--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)321--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)322--- PASS: TestStreamPushReportsEveryPath (0.00s)323--- PASS: TestStreamPushIsolatesFailures (0.00s)324=== CONT TestUploadMultipart_SupersededByPeer/missing325--- PASS: TestScriptTokenEmptyToken (0.04s)326--- PASS: TestFilterOversizedClosures (0.03s)327 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)328 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)329 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)330--- PASS: TestRateLimiterFeedback (0.03s)331 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)332 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)333 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)334 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)335--- PASS: TestConvertHashToNix32 (0.03s)336 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)337 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)338 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)339--- PASS: TestGetStorePathHash (0.03s)340 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)341 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)342 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)343 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)344--- PASS: TestPathInfoHashCompatibility (0.03s)345 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)346 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)347 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)348 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)349--- PASS: TestParsePathInfoJSONMultiplePaths (0.04s)350 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)351 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)352--- PASS: TestPathInfoCACompatibility (0.03s)353 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)354 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)356 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)357 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)358--- PASS: TestParsePathInfoJSON (0.03s)359 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)360 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)361 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)362 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)363 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)364--- PASS: TestSetClientTLSErrors (0.03s)365 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)366 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)367 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)368 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)369--- PASS: TestPartSizeForNAR (0.03s)370 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)372 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)373 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)374 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)376 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)377--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)378 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)379 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)380--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)3812026/10/01 09:18:07 http: TLS handshake error from 127.0.0.1:39806: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.00s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)386--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)387--- PASS: TestStreamPushRequestLine (0.02s)388--- PASS: TestDumpPathWriterError (0.06s)389--- PASS: TestDumpPathSingleFile (0.06s)390--- PASS: TestDumpPathMatchesNix (0.10s)391--- PASS: TestStreamPushBatchesUnderLoad (0.10s)392--- PASS: TestUploadMultipart_PartsInParallel (0.65s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)394PASS395Running server tests...396The files belonging to this database system will be owned by user "nixbld".397This user must also own the server process.398399The database cluster will be initialized with locale "C".400The default database encoding has accordingly been set to "SQL_ASCII".401The default text search configuration will be set to "english".402403Data page checksums are enabled.404405creating directory /build/postgres729025904/data ... ok406creating subdirectories ... ok407selecting dynamic shared memory implementation ... posix408selecting default "max_connections" ... 100409selecting default "shared_buffers" ... 128MB410selecting default time zone ... UTC411creating configuration files ... ok412running bootstrap script ... ok413performing post-bootstrap initialization ... ok414syncing data to disk ... ok415416initdb: warning: enabling "trust" authentication for local connections417initdb: 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.418419Success. You can now start the database server using:420421 pg_ctl -D /build/postgres729025904/data -l logfile start422423/build/postgres729025904:5432 - no response4242026-10-01 09:18:09.356 UTC [128] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:18:09.357 UTC [128] LOG: listening on Unix socket "/build/postgres729025904/.s.PGSQL.5432"4262026-10-01 09:18:09.360 UTC [135] LOG: database system was shut down at 2026-10-01 09:18:09 UTC4272026-10-01 09:18:09.365 UTC [128] LOG: database system is ready to accept connections428/build/postgres729025904:5432 - accepting connections429{"timestamp":"2026-10-01T09:18:09.554921061Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4d3c03f8-0f14-414c-accd-18390cb1583e","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(203)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:18:09.737 UTC [370] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:18:09.737 UTC [370] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.58ms)4762026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)4772026/10/01 09:18:09 OK 20251218171726_add_pins.sql (2.81ms)4782026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (2.52ms)4792026/10/01 09:18:09 OK 20260905000000_add_claims.sql (2.68ms)4802026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (1.72ms)4812026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (1.27ms)4822026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200004832026/10/01 09:18:09 OK 1_commit_pending_closure.sql (1.61ms)4842026/10/01 09:18:09 OK 2_object_stats_trigger.sql (642.37µs)4852026/10/01 09:18:09 OK 3_commit_push.sql (496.45µs)4862026/10/01 09:18:09 goose: up to current file version: 34872026/10/01 09:18:09 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:18:10 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:18:10 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:18:10 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.78s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:18:10.498 UTC [381] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:18:10.498 UTC [381] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.83ms)4982026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.21ms)4992026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.8ms)5002026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (2.86ms)5012026/10/01 09:18:10 OK 20260905000000_add_claims.sql (2.41ms)5022026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (1.51ms)5032026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (1.06ms)5042026/10/01 09:18:10 goose: successfully migrated database to version: 202609231200005052026/10/01 09:18:10 OK 1_commit_pending_closure.sql (1.51ms)5062026/10/01 09:18:10 OK 2_object_stats_trigger.sql (580.89µs)5072026/10/01 09:18:10 OK 3_commit_push.sql (458.78µs)5082026/10/01 09:18:10 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.11s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCTaskStore_StartNew543=== PAUSE TestGCTaskStore_StartNew544=== RUN TestGCTaskStore_DeduplicateSameParams545=== PAUSE TestGCTaskStore_DeduplicateSameParams546=== RUN TestGCTaskStore_ConflictDifferentParams547=== PAUSE TestGCTaskStore_ConflictDifferentParams548=== RUN TestGCTaskStore_GetEmpty549=== PAUSE TestGCTaskStore_GetEmpty550=== RUN TestGCTaskStore_GetReturnsLatest551=== PAUSE TestGCTaskStore_GetReturnsLatest552=== RUN TestGCTaskStore_CompletedAllowsNewTask553=== PAUSE TestGCTaskStore_CompletedAllowsNewTask554=== RUN TestGCTaskStore_PhaseUpdates555=== PAUSE TestGCTaskStore_PhaseUpdates556=== RUN TestGCTaskStore_Fail557=== PAUSE TestGCTaskStore_Fail558=== RUN TestGracefulShutdownDrainsInflight559=== PAUSE TestGracefulShutdownDrainsInflight560=== RUN TestService_healthCheckHandler561=== PAUSE TestService_healthCheckHandler562=== RUN TestService_readinessHandler563=== PAUSE TestService_readinessHandler564=== RUN TestGenerateLandingPage565=== PAUSE TestGenerateLandingPage566=== RUN TestCacheConfigHandlerMaxNarSize567=== PAUSE TestCacheConfigHandlerMaxNarSize568=== RUN TestCreatePendingClosureRejectsOversizedNAR569=== PAUSE TestCreatePendingClosureRejectsOversizedNAR570=== RUN TestNARDeduplicationMetadataUploadBug571=== PAUSE TestNARDeduplicationMetadataUploadBug572=== RUN TestMetricsInventory573=== PAUSE TestMetricsInventory574=== RUN TestService_NativeMTLS575=== PAUSE TestService_NativeMTLS576=== RUN TestServerTLSConfig577=== PAUSE TestServerTLSConfig578=== RUN TestMultipartCleanup579=== PAUSE TestMultipartCleanup580=== RUN TestObjectStatsTrigger581=== PAUSE TestObjectStatsTrigger582=== RUN TestOrphanedObjectsGC583=== PAUSE TestOrphanedObjectsGC584=== RUN TestOrphanedObjectsGCStressTest585=== PAUSE TestOrphanedObjectsGCStressTest586=== RUN TestCreatePin_ReservedPins587=== PAUSE TestCreatePin_ReservedPins588=== RUN TestParseSingleRange589=== PAUSE TestParseSingleRange590=== RUN TestProxyHeadersOnlyTrustedOnSocket591=== PAUSE TestProxyHeadersOnlyTrustedOnSocket592=== RUN TestIsValidCachePath593=== PAUSE TestIsValidCachePath594=== RUN TestReadProxyNarinfo595=== PAUSE TestReadProxyNarinfo596=== RUN TestReadProxyNarinfoAlreadyDecompressed597=== PAUSE TestReadProxyNarinfoAlreadyDecompressed598=== RUN TestReadProxyNarStreaming599=== PAUSE TestReadProxyNarStreaming600=== RUN TestReadProxy404601=== PAUSE TestReadProxy404602=== RUN TestReadProxyInvalidPath603=== PAUSE TestReadProxyInvalidPath604=== RUN TestReadProxyHead605=== PAUSE TestReadProxyHead606=== RUN TestReadProxyConditionalGet607=== PAUSE TestReadProxyConditionalGet608=== RUN TestReadProxyRootRedirectsToIndexHTML609=== PAUSE TestReadProxyRootRedirectsToIndexHTML610=== RUN TestReadProxyDisabled611=== PAUSE TestReadProxyDisabled612=== RUN TestReadRedirectNar613=== PAUSE TestReadRedirectNar614=== RUN TestReadRedirectKeepsNarinfoProxied615=== PAUSE TestReadRedirectKeepsNarinfoProxied616=== RUN TestReadProxyRangeRequest617=== PAUSE TestReadProxyRangeRequest618=== RUN TestReadRedirectUsesPublicS3URL619=== PAUSE TestReadRedirectUsesPublicS3URL620=== RUN TestPush_OverlappingRootsStoreOneRowPerKey621=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey622=== RUN TestPush_CompleteCommitsEveryRoot623=== PAUSE TestPush_CompleteCommitsEveryRoot624=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit625=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit626=== RUN TestPush_RejectsBadRequests627=== PAUSE TestPush_RejectsBadRequests628=== RUN TestPush_SignsNarinfosOfItsPendingObjects629=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects630=== RUN TestRedundantMultipartUpload631=== PAUSE TestRedundantMultipartUpload632=== RUN TestCompleteMultipartUpload_ErrorButObjectExists633=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists634=== RUN TestCompletedNarNotReofferedAcrossClosures635=== PAUSE TestCompletedNarNotReofferedAcrossClosures636=== RUN TestPresignedUploadRegisteredBeforeCommit637=== PAUSE TestPresignedUploadRegisteredBeforeCommit638=== RUN TestService_Rustfstest639=== PAUSE TestService_Rustfstest640=== RUN TestParseSize641=== PAUSE TestParseSize642=== RUN TestSkippedUploadsHandler643=== PAUSE TestSkippedUploadsHandler644=== RUN TestSystemdListenerNotActivated645--- PASS: TestSystemdListenerNotActivated (0.00s)646=== RUN TestWatchdogBeatsWhenHealthy647--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)648=== RUN TestWatchdogSkipsWhenUnhealthy6492026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6502026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6512026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6522026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6532026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6542026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:18:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"659--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)660=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle661=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle662=== RUN TestProxyWriteTimeout663=== PAUSE TestProxyWriteTimeout664=== RUN TestIsValidUploadKey665=== PAUSE TestIsValidUploadKey666=== RUN TestUploadHandlersRejectInvalidKeys667=== PAUSE TestUploadHandlersRejectInvalidKeys668=== RUN TestUploadHandlersRejectOversizedBody669=== PAUSE TestUploadHandlersRejectOversizedBody670=== RUN TestService_cleanupPendingClosuresHandler671=== PAUSE TestService_cleanupPendingClosuresHandler672=== RUN TestService_createPendingClosureHandler673=== PAUSE TestService_createPendingClosureHandler674=== RUN TestService_verifyS3Integrity675=== PAUSE TestService_verifyS3Integrity676=== RUN TestCompleteMultipartUnregistered677=== PAUSE TestCompleteMultipartUnregistered678=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT679=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT680=== CONT TestService_Rustfstest681=== CONT TestPush_OverlappingRootsStoreOneRowPerKey682=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection683=== CONT TestPresignedUploadRegisteredBeforeCommit684=== CONT TestCompletedNarNotReofferedAcrossClosures685=== CONT TestCompleteMultipartUpload_ErrorButObjectExists686=== CONT TestRedundantMultipartUpload687=== CONT TestPush_SignsNarinfosOfItsPendingObjects688=== CONT TestPush_RejectsBadRequests689=== CONT TestGCTaskStore_DeduplicateSameParams690--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)691=== CONT TestGCTaskStore_StartNew692--- PASS: TestGCTaskStore_StartNew (0.00s)693=== CONT TestGCSweepSkipsPendingObjects694=== CONT TestCommitRacingPendingCleanupKeepsObjects695=== CONT TestPushWaitsForSweepHoldingRow696=== CONT TestSweepRechecksPendingAfterLocking697=== CONT TestGetExistingObjectsLocksRows698=== CONT TestGCTaskStore_ConflictDifferentParams699--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)700=== CONT TestDeduplicatedObjectsRecordedAsPending701=== CONT TestRegisterCompletedObjectNeedsPendingRow702=== CONT TestSweepSkipsRowsLockedByPush703=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit704=== CONT TestFailedS3DeleteKeepsTombstone705=== CONT TestPush_CompleteCommitsEveryRoot706=== CONT TestForceGCDuringPushOffersSweptObject707=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows708=== CONT TestGCSweepDeliversEachKeyOnce709=== CONT TestService_AuthMiddleware710=== CONT TestTombstonedObjectOfferedWithoutWaiting711=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows712=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check713=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check714=== CONT TestPushDedupSurvivesConcurrentGC7152026-10-01 09:18:10.946 UTC [447] ERROR: relation "goose_db_version" does not exist at character 367162026-10-01 09:18:10.946 UTC [447] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7172026-10-01 09:18:10.947 UTC [448] ERROR: relation "goose_db_version" does not exist at character 367182026-10-01 09:18:10.947 UTC [448] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026-10-01 09:18:10.949 UTC [449] ERROR: relation "goose_db_version" does not exist at character 367202026-10-01 09:18:10.949 UTC [449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026-10-01 09:18:10.950 UTC [450] ERROR: relation "goose_db_version" does not exist at character 367222026-10-01 09:18:10.950 UTC [450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7232026-10-01 09:18:10.962 UTC [451] ERROR: relation "goose_db_version" does not exist at character 367242026-10-01 09:18:10.962 UTC [451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026-10-01 09:18:10.962 UTC [452] ERROR: relation "goose_db_version" does not exist at character 367262026-10-01 09:18:10.962 UTC [452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7272026-10-01 09:18:10.963 UTC [453] ERROR: relation "goose_db_version" does not exist at character 367282026-10-01 09:18:10.963 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026/10/01 09:18:11 OK 20241026095416_initial_model.sql (52.1ms)7302026/10/01 09:18:11 OK 20241026095416_initial_model.sql (52.76ms)7312026/10/01 09:18:11 OK 20241026095416_initial_model.sql (52.72ms)7322026/10/01 09:18:11 OK 20241026095416_initial_model.sql (54.62ms)7332026-10-01 09:18:11.019 UTC [454] ERROR: relation "goose_db_version" does not exist at character 367342026-10-01 09:18:11.019 UTC [454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7352026-10-01 09:18:11.019 UTC [455] ERROR: relation "goose_db_version" does not exist at character 367362026-10-01 09:18:11.019 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7372026-10-01 09:18:11.020 UTC [456] ERROR: relation "goose_db_version" does not exist at character 367382026-10-01 09:18:11.020 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7392026-10-01 09:18:11.020 UTC [457] ERROR: relation "goose_db_version" does not exist at character 367402026-10-01 09:18:11.020 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7412026/10/01 09:18:11 OK 20241026095416_initial_model.sql (31.49ms)7422026/10/01 09:18:11 OK 20241026095416_initial_model.sql (21.99ms)7432026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (8.4ms)7442026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (8.39ms)7452026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (8.53ms)7462026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (8.54ms)7472026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (4.21ms)7482026/10/01 09:18:11 OK 20241026095416_initial_model.sql (23.2ms)7492026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (3.39ms)7502026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.37ms)7512026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.95ms)7522026/10/01 09:18:11 OK 20251218171726_add_pins.sql (5.89ms)7532026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (3.33ms)7542026/10/01 09:18:11 OK 20251218171726_add_pins.sql (6.17ms)7552026/10/01 09:18:11 OK 20251218171726_add_pins.sql (5.11ms)7562026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.34ms)7572026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.8ms)7582026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.57ms)7592026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.59ms)7602026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (5ms)7612026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)7622026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (5.34ms)7632026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)7642026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.03ms)7652026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.47ms)7662026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.77ms)7672026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)7682026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.78ms)7692026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.35ms)7702026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.43ms)7712026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.06ms)7722026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.41ms)7732026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.86ms)7742026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.53ms)7752026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.58ms)7762026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (5.01ms)7772026-10-01 09:18:11.046 UTC [460] ERROR: relation "goose_db_version" does not exist at character 367782026-10-01 09:18:11.046 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7792026-10-01 09:18:11.046 UTC [461] ERROR: relation "goose_db_version" does not exist at character 367802026-10-01 09:18:11.046 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7812026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.52ms)7822026-10-01 09:18:11.046 UTC [462] ERROR: relation "goose_db_version" does not exist at character 367832026-10-01 09:18:11.046 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026-10-01 09:18:11.047 UTC [463] ERROR: relation "goose_db_version" does not exist at character 367852026-10-01 09:18:11.047 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.2ms)7872026-10-01 09:18:11.047 UTC [464] ERROR: relation "goose_db_version" does not exist at character 367882026-10-01 09:18:11.047 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7892026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200007902026-10-01 09:18:11.047 UTC [465] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 09:18:11.047 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 09:18:11.048 UTC [466] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 09:18:11.048 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026-10-01 09:18:11.048 UTC [467] ERROR: relation "goose_db_version" does not exist at character 367952026-10-01 09:18:11.048 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.84ms)7972026-10-01 09:18:11.048 UTC [468] ERROR: relation "goose_db_version" does not exist at character 367982026-10-01 09:18:11.048 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.96ms)8002026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008012026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.64ms)8022026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008032026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.94ms)8042026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008052026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.92ms)8062026-10-01 09:18:11.049 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368072026-10-01 09:18:11.049 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8082026-10-01 09:18:11.049 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368092026-10-01 09:18:11.049 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8102026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.58ms)8112026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008122026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.77ms)8132026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.69ms)8142026-10-01 09:18:11.050 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368152026-10-01 09:18:11.050 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (4ms)8172026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (3.16ms)8182026-10-01 09:18:11.050 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368192026-10-01 09:18:11.050 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.01ms)8212026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)8222026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.16ms)8232026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.38ms)8242026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)8252026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.84ms)8262026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.17ms)8272026/10/01 09:18:11 OK 1_commit_pending_closure.sql (4.13ms)8282026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.34ms)8292026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008302026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.15ms)8312026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008322026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.03ms)8332026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.4ms)8342026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.32ms)8352026/10/01 09:18:11 OK 3_commit_push.sql (1.61ms)8362026/10/01 09:18:11 goose: up to current file version: 38372026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.52ms)8382026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.2ms)8392026/10/01 09:18:11 OK 3_commit_push.sql (2.25ms)8402026/10/01 09:18:11 goose: up to current file version: 38412026/10/01 09:18:11 OK 3_commit_push.sql (1.95ms)8422026/10/01 09:18:11 goose: up to current file version: 38432026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.54ms)8442026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.77ms)8452026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.61ms)8462026/10/01 09:18:11 OK 20251218171726_add_pins.sql (5.43ms)8472026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.34ms)8482026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.24ms)8492026/10/01 09:18:11 OK 3_commit_push.sql (1.79ms)8502026/10/01 09:18:11 goose: up to current file version: 38512026/10/01 09:18:11 OK 3_commit_push.sql (1.44ms)8522026/10/01 09:18:11 goose: up to current file version: 38532026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.94ms)8542026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.9ms)8552026/10/01 09:18:11 OK 3_commit_push.sql (1.37ms)8562026/10/01 09:18:11 goose: up to current file version: 38572026/10/01 09:18:11 OK 3_commit_push.sql (2.1ms)8582026/10/01 09:18:11 goose: up to current file version: 38592026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (6.51ms)8602026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)8612026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (5.08ms)8622026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.91ms)8632026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.59ms)8642026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.2ms)8652026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.89ms)8662026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.72ms)8672026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.66ms)8682026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.73ms)8692026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.77ms)8702026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.07ms)8712026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.18ms)8722026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.16ms)8732026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.56ms)8742026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.1ms)8752026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.23ms)8762026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.01ms)8772026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.16ms)8782026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.57ms)8792026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008802026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.18ms)8812026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.52ms)8822026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)8832026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)8842026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.49ms)8852026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.61ms)8862026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.06ms)8872026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.12ms)8882026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008892026/10/01 09:18:11 OK 20241026095416_initial_model.sql (13.43ms)8902026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)8912026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.47ms)8922026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)8932026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)8942026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)8952026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)8962026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)8972026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.3ms)8982026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200008992026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)9002026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)9012026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.22ms)9022026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009032026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)9042026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.42ms)9052026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)9062026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.97ms)9072026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.76ms)9082026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.19ms)9092026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures9102026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.93ms)9112026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.76ms)9122026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.86ms)9132026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.51ms)9142026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.84ms)9152026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.91ms)9162026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.35ms)9172026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.31ms)9182026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.47ms)9192026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.58ms)9202026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.61ms)9212026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.61ms)9222026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.19ms)9232026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.43ms)9242026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.67ms)9252026/10/01 09:18:11 OK 3_commit_push.sql (1.65ms)9262026/10/01 09:18:11 goose: up to current file version: 39272026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.8ms)9282026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.51ms)9292026/10/01 09:18:11 OK 3_commit_push.sql (1.31ms)9302026/10/01 09:18:11 goose: up to current file version: 39312026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.73ms)9322026/10/01 09:18:11 OK 3_commit_push.sql (1.26ms)9332026/10/01 09:18:11 goose: up to current file version: 39342026/10/01 09:18:11 OK 3_commit_push.sql (1.23ms)9352026/10/01 09:18:11 goose: up to current file version: 39362026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)9372026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.52ms)9382026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)9392026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.97ms)9402026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)9412026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.83ms)9422026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)9432026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)9442026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)9452026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.91ms)9462026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.21ms)9472026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.32ms)9482026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)9492026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.68ms)9502026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.47ms)9512026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.25ms)9522026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.09ms)9532026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.41ms)9542026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.6ms)9552026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.06ms)9562026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.28ms)9572026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.64ms)9582026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.33ms)9592026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.96ms)9602026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.01ms)9612026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.23ms)9622026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.98ms)9632026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.87ms)9642026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (1.59ms)9652026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009662026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.22ms)9672026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009682026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.97ms)9692026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.87ms)9702026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.03ms)9712026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3ms)9722026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.03ms)9732026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.05ms)9742026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.99ms)9752026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.97ms)9762026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.58ms)9772026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.22ms)9782026/10/01 09:18:11 INFO Received push request method=POST path=/api/pushes9792026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.11ms)9802026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009812026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.8ms)9822026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.75ms)9832026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.6ms)9842026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009852026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.7ms)9862026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009872026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.07ms)9882026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009892026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.71ms)9902026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009912026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.11ms)9922026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009932026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.64ms)9942026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009952026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.69ms)9962026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009972026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.72ms)9982026/10/01 09:18:11 goose: successfully migrated database to version: 202609231200009992026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.83ms)10002026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000010012026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.77ms)10022026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000010032026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.14ms)10042026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.94ms)10052026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.94ms)10062026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.68ms)10072026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.06ms)10082026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.01ms)10092026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.91ms)10102026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.73ms)10112026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.65ms)10122026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.95ms)10132026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.82ms)10142026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.09ms)10152026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.65ms)10162026/10/01 09:18:11 OK 3_commit_push.sql (671.17µs)10172026/10/01 09:18:11 goose: up to current file version: 310182026/10/01 09:18:11 OK 3_commit_push.sql (673.61µs)10192026/10/01 09:18:11 goose: up to current file version: 310202026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.61ms)10212026/10/01 09:18:11 OK 2_object_stats_trigger.sql (681.09µs)10222026/10/01 09:18:11 OK 2_object_stats_trigger.sql (926.63µs)10232026/10/01 09:18:11 OK 2_object_stats_trigger.sql (835.79µs)10242026/10/01 09:18:11 OK 2_object_stats_trigger.sql (888.13µs)10252026/10/01 09:18:11 OK 3_commit_push.sql (761.57µs)10262026/10/01 09:18:11 goose: up to current file version: 310272026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.02ms)10282026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.07ms)10292026/10/01 09:18:11 OK 2_object_stats_trigger.sql (886.81µs)10302026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1ms)10312026/10/01 09:18:11 OK 2_object_stats_trigger.sql (974.49µs)10322026/10/01 09:18:11 OK 3_commit_push.sql (676.97µs)10332026/10/01 09:18:11 goose: up to current file version: 310342026/10/01 09:18:11 OK 3_commit_push.sql (632.05µs)10352026/10/01 09:18:11 goose: up to current file version: 310362026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.04ms)10372026/10/01 09:18:11 OK 3_commit_push.sql (584.55µs)10382026/10/01 09:18:11 goose: up to current file version: 310392026/10/01 09:18:11 OK 3_commit_push.sql (747.51µs)10402026/10/01 09:18:11 goose: up to current file version: 310412026/10/01 09:18:11 OK 3_commit_push.sql (807.59µs)10422026/10/01 09:18:11 goose: up to current file version: 310432026/10/01 09:18:11 OK 3_commit_push.sql (773.27µs)10442026/10/01 09:18:11 goose: up to current file version: 310452026/10/01 09:18:11 OK 3_commit_push.sql (574.11µs)10462026/10/01 09:18:11 goose: up to current file version: 310472026/10/01 09:18:11 OK 3_commit_push.sql (839.83µs)10482026/10/01 09:18:11 goose: up to current file version: 310492026/10/01 09:18:11 OK 3_commit_push.sql (865.37µs)10502026/10/01 09:18:11 goose: up to current file version: 310512026/10/01 09:18:11 OK 3_commit_push.sql (887.97µs)10522026/10/01 09:18:11 goose: up to current file version: 310532026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures1054--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.34s)1055=== CONT TestGCMetrics10562026/10/01 09:18:11 INFO Received push request method=POST path=/api/pushes10572026/10/01 09:18:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10582026/10/01 09:18:11 INFO Signed narinfos id=1 count=11059--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.36s)1060=== CONT TestGCBugBareHashReferences10612026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures10622026/10/01 09:18:11 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10632026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures1064--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.38s)1065=== CONT TestLeadEndsOnShutdown1066--- PASS: TestService_Rustfstest (0.39s)1067=== CONT TestLeadElectsOneAndHandsOver1068--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.52s)1069=== CONT TestResolveDBConnectionString1070=== RUN TestResolveDBConnectionString/flag_wins1071=== PAUSE TestResolveDBConnectionString/flag_wins1072=== RUN TestResolveDBConnectionString/file_when_flag_empty1073=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1074=== RUN TestResolveDBConnectionString/missing_file_is_an_error1075=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1076=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1077=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1078=== RUN TestResolveDBConnectionString/nothing_configured1079=== PAUSE TestResolveDBConnectionString/nothing_configured1080=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock10812026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures10822026-10-01 09:18:11.365 UTC [486] ERROR: relation "goose_db_version" does not exist at character 3610832026-10-01 09:18:11.365 UTC [486] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10842026/10/01 09:18:11 OK 20241026095416_initial_model.sql (10.6ms)10852026-10-01 09:18:11.385 UTC [487] ERROR: relation "goose_db_version" does not exist at character 3610862026-10-01 09:18:11.385 UTC [487] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10872026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)10882026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.5ms)10892026/10/01 09:18:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10902026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.93ms)10912026/10/01 09:18:11 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTY4OWRlZWEtZDEyNS00ZGJkLTliMmQtMWQwNGQxYTlmZmMxLmRmMWUxNzE3LWM2ZDUtNDc1Ny1hYjg3LWZhZjYwMWM4MzcyYngxNzkwODQ2MjkxMzY1NzAwMDcy10922026/10/01 09:18:11 INFO Aborted multipart uploads count=010932026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.23ms)10942026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period10952026/10/01 09:18:11 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTY4OWRlZWEtZDEyNS00ZGJkLTliMmQtMWQwNGQxYTlmZmMxLmRmMWUxNzE3LWM2ZDUtNDc1Ny1hYjg3LWZhZjYwMWM4MzcyYngxNzkwODQ2MjkxMzY1NzAwMDcy parts=110962026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures1097--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.63s)1098=== CONT TestClientFallsBackToClosures10992026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.08ms)11002026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.18ms)11012026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000011022026/10/01 09:18:11 OK 20241026095416_initial_model.sql (12.17ms)11032026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.13ms)11042026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)11052026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.56ms)11062026/10/01 09:18:11 OK 3_commit_push.sql (1.94ms)11072026/10/01 09:18:11 goose: up to current file version: 311082026/10/01 09:18:11 OK 20251218171726_add_pins.sql (9.77ms)11092026/10/01 09:18:11 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=011102026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures11112026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)11122026/10/01 09:18:11 INFO Vacuumed table table=pending_closures11132026/10/01 09:18:11 INFO Vacuumed table table=pending_objects11142026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads11152026/10/01 09:18:11 INFO Vacuumed table table=closures11162026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.9ms)11172026/10/01 09:18:11 INFO Vacuumed table table=objects11182026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.03ms)1119--- PASS: TestSweepRechecksPendingAfterLocking (0.65s)1120=== CONT TestClientPushesUseOnePush11212026-10-01 09:18:11.427 UTC [495] ERROR: relation "goose_db_version" does not exist at character 3611222026-10-01 09:18:11.427 UTC [495] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11232026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (1.58ms)11242026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000011252026-10-01 09:18:11.427 UTC [496] ERROR: relation "goose_db_version" does not exist at character 3611262026-10-01 09:18:11.427 UTC [496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11272026-10-01 09:18:11.428 UTC [497] ERROR: relation "goose_db_version" does not exist at character 3611282026-10-01 09:18:11.428 UTC [497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11292026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.57ms)11302026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.75ms)11312026/10/01 09:18:11 OK 3_commit_push.sql (860.95µs)11322026/10/01 09:18:11 goose: up to current file version: 311332026/10/01 09:18:11 INFO Aborted multipart uploads count=01134=== RUN TestPush_RejectsBadRequests/no_roots1135=== PAUSE TestPush_RejectsBadRequests/no_roots1136=== RUN TestPush_RejectsBadRequests/no_objects1137=== PAUSE TestPush_RejectsBadRequests/no_objects1138=== RUN TestPush_RejectsBadRequests/bad_root1139=== PAUSE TestPush_RejectsBadRequests/bad_root1140=== RUN TestPush_RejectsBadRequests/root_not_in_objects1141=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1142=== CONT TestPinProtectsFromGC11432026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period11442026/10/01 09:18:11 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=011452026/10/01 09:18:11 INFO Vacuumed table table=pending_closures11462026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.72ms)11472026/10/01 09:18:11 OK 20241026095416_initial_model.sql (12.35ms)11482026/10/01 09:18:11 INFO Vacuumed table table=pending_objects11492026/10/01 09:18:11 OK 20241026095416_initial_model.sql (14.23ms)11502026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads11512026/10/01 09:18:11 INFO Vacuumed table table=closures11522026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)11532026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)11542026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)11552026/10/01 09:18:11 INFO Vacuumed table table=objects11562026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.78ms)11572026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.03ms)11582026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.1ms)11592026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures1160--- PASS: TestGCSweepSkipsPendingObjects (0.69s)1161=== CONT TestClientSharedPathCommittedMidPush11622026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)11632026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)11642026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)11652026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.41ms)11662026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.32ms)11672026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.26ms)11682026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.83ms)11692026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.92ms)11702026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.71ms)11712026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.78ms)11722026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000011732026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures11742026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.85ms)11752026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000011762026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.3ms)11772026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000011782026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.3ms)11792026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.39ms)11802026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.61ms)11812026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.12ms)11822026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.31ms)11832026/10/01 09:18:11 OK 3_commit_push.sql (1.32ms)11842026/10/01 09:18:11 goose: up to current file version: 311852026/10/01 09:18:11 OK 3_commit_push.sql (1.63ms)11862026/10/01 09:18:11 goose: up to current file version: 311872026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.23ms)11882026/10/01 09:18:11 OK 3_commit_push.sql (1.34ms)11892026/10/01 09:18:11 goose: up to current file version: 311902026-10-01 09:18:11.482 UTC [505] ERROR: relation "goose_db_version" does not exist at character 3611912026-10-01 09:18:11.482 UTC [505] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11922026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures11932026-10-01 09:18:11.500 UTC [506] ERROR: relation "goose_db_version" does not exist at character 3611942026-10-01 09:18:11.500 UTC [506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11952026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures11962026/10/01 09:18:11 OK 20241026095416_initial_model.sql (15.26ms)11972026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)11982026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.21ms)11992026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.58ms)12002026-10-01 09:18:11.515 UTC [507] ERROR: relation "goose_db_version" does not exist at character 3612012026-10-01 09:18:11.515 UTC [507] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12022026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.33ms)12032026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.4ms)12042026/10/01 09:18:11 INFO Received push request method=POST path=/api/pushes12052026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)12062026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.25ms)12072026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (1.42ms)12082026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000012092026/10/01 09:18:11 OK 20251218171726_add_pins.sql (2.56ms)12102026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.66ms)12112026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.43ms)12122026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (2.93ms)12132026/10/01 09:18:11 OK 3_commit_push.sql (936.59µs)12142026/10/01 09:18:11 goose: up to current file version: 312152026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.48ms)12162026/10/01 09:18:11 OK 20241026095416_initial_model.sql (9.57ms)12172026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.13ms)12182026-10-01 09:18:11.531 UTC [510] ERROR: relation "goose_db_version" does not exist at character 3612192026-10-01 09:18:11.531 UTC [510] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12202026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.4ms)12212026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (1.56ms)12222026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000012232026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.98ms)12242026/10/01 09:18:11 INFO Received complete push request method=POST path=/api/pushes/1/complete12252026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.17ms)12262026/10/01 09:18:11 OK 2_object_stats_trigger.sql (865.05µs)12272026/10/01 09:18:11 OK 3_commit_push.sql (687.41µs)12282026/10/01 09:18:11 goose: up to current file version: 312292026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (2.7ms)12302026/10/01 09:18:11 OK 20260905000000_add_claims.sql (2.66ms)12312026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (1.72ms)12322026/10/01 09:18:11 INFO Received push request method=POST path=/api/pushes12332026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (1.49ms)12342026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000012352026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.85ms)12362026/10/01 09:18:11 OK 20241026095416_initial_model.sql (9.61ms)12372026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.13ms)12382026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)12392026/10/01 09:18:11 OK 3_commit_push.sql (711.09µs)12402026/10/01 09:18:11 goose: up to current file version: 312412026/10/01 09:18:11 OK 20251218171726_add_pins.sql (2.97ms)12422026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (2.51ms)12432026/10/01 09:18:11 OK 20260905000000_add_claims.sql (2.75ms)12442026/10/01 09:18:11 INFO Aborted multipart uploads count=012452026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (1.83ms)12462026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (1.66ms)12472026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000012482026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period12492026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.79ms)12502026/10/01 09:18:11 OK 2_object_stats_trigger.sql (954.49µs)12512026/10/01 09:18:11 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=012522026/10/01 09:18:11 OK 3_commit_push.sql (578.81µs)12532026/10/01 09:18:11 goose: up to current file version: 312542026/10/01 09:18:11 INFO Vacuumed table table=pending_closures12552026/10/01 09:18:11 INFO Vacuumed table table=pending_objects12562026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads12572026/10/01 09:18:11 INFO Vacuumed table table=closures1258--- PASS: TestGetExistingObjectsLocksRows (0.79s)1259=== CONT TestClientWithDependencies12602026/10/01 09:18:11 INFO Vacuumed table table=objects12612026/10/01 09:18:11 INFO Aborted multipart uploads count=012622026/10/01 09:18:11 INFO Aborted multipart uploads count=012632026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period12642026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures12652026/10/01 09:18:11 INFO Aborted multipart uploads count=012662026/10/01 09:18:11 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=01267--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.81s)1268=== CONT TestClientMultipleUploads12692026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period12702026/10/01 09:18:11 INFO Vacuumed table table=pending_closures12712026/10/01 09:18:11 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=012722026/10/01 09:18:11 INFO Vacuumed table table=pending_closures12732026/10/01 09:18:11 INFO Vacuumed table table=pending_objects12742026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads12752026/10/01 09:18:11 INFO Vacuumed table table=closures12762026/10/01 09:18:11 INFO Vacuumed table table=pending_objects12772026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads12782026/10/01 09:18:11 INFO Vacuumed table table=objects12792026/10/01 09:18:11 INFO Vacuumed table table=closures1280--- PASS: TestSweepSkipsRowsLockedByPush (0.82s)1281=== CONT TestClientIntegration12822026/10/01 09:18:11 INFO Vacuumed table table=objects12832026/10/01 09:18:11 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12842026/10/01 09:18:11 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."12852026/10/01 09:18:11 INFO Aborted multipart uploads count=01286--- PASS: TestFailedS3DeleteKeepsTombstone (0.82s)1287=== CONT TestClientErrorHandling1288=== RUN TestClientErrorHandling/InvalidStorePath1289=== PAUSE TestClientErrorHandling/InvalidStorePath1290=== RUN TestClientErrorHandling/InvalidAuthToken1291=== PAUSE TestClientErrorHandling/InvalidAuthToken1292=== RUN TestClientErrorHandling/ServerNotAvailable1293=== PAUSE TestClientErrorHandling/ServerNotAvailable1294=== CONT TestClientCADerivations12952026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period12962026/10/01 09:18:11 INFO Received push request method=POST path=/api/pushes12972026/10/01 09:18:11 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=012982026/10/01 09:18:11 INFO Vacuumed table table=pending_closures12992026/10/01 09:18:11 INFO Aborted multipart uploads count=013002026/10/01 09:18:11 INFO Vacuumed table table=pending_objects13012026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads13022026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period13032026/10/01 09:18:11 INFO Vacuumed table table=closures13042026/10/01 09:18:11 INFO Vacuumed table table=objects1305--- PASS: TestPushDedupSurvivesConcurrentGC (0.83s)1306=== CONT TestCacheStatsHandler13072026/10/01 09:18:11 INFO Received complete push request method=POST path=/api/pushes/1/complete13082026/10/01 09:18:11 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=013092026/10/01 09:18:11 INFO Vacuumed table table=pending_closures13102026/10/01 09:18:11 INFO Vacuumed table table=pending_objects13112026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads1312--- PASS: TestPush_CompleteCommitsEveryRoot (0.85s)1313=== CONT TestUploadHandlersRejectOversizedBody13142026/10/01 09:18:11 INFO Vacuumed table table=closures13152026/10/01 09:18:11 INFO Vacuumed table table=objects13162026/10/01 09:18:11 INFO Received complete push request method=POST path=/api/pushes/2/complete13172026/10/01 09:18:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13182026-10-01 09:18:11.641 UTC [529] ERROR: relation "goose_db_version" does not exist at character 3613192026-10-01 09:18:11.641 UTC [529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13202026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures1321--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.87s)1322=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1323--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.88s)1324=== CONT TestCacheConfigHandler1325=== RUN TestCacheConfigHandler/full_config,_no_issuer1326=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1327=== RUN TestCacheConfigHandler/no_cache_url_configured1328=== PAUSE TestCacheConfigHandler/no_cache_url_configured1329=== RUN TestCacheConfigHandler/no_signing_keys1330=== PAUSE TestCacheConfigHandler/no_signing_keys1331=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1332=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1333=== CONT TestCompleteMultipartUnregistered13342026/10/01 09:18:11 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTY4OWRlZWEtZDEyNS00ZGJkLTliMmQtMWQwNGQxYTlmZmMxLjcxY2QxM2M3LTVlOGQtNGQ5NS1iMDMzLTBkZGZkOTE5NGEyMngxNzkwODQ2MjkxMTA5NzUzMTc0 parts=1213352026/10/01 09:18:11 INFO Received uploads request method=POST path=/api/pending_closures13362026/10/01 09:18:11 INFO Aborted multipart uploads count=01337--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.89s)1338=== CONT TestService_ReadScope_PublicByDefault13392026-10-01 09:18:11.660 UTC [552] ERROR: relation "goose_db_version" does not exist at character 3613402026-10-01 09:18:11.660 UTC [552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13412026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period13422026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.89ms)13432026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)1344--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.89s)1345=== CONT TestService_verifyS3Integrity13462026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.42ms)13472026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.45ms)13482026-10-01 09:18:11.672 UTC [557] ERROR: relation "goose_db_version" does not exist at character 3613492026-10-01 09:18:11.672 UTC [557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13502026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.63ms)13512026/10/01 09:18:11 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=013522026-10-01 09:18:11.678 UTC [560] ERROR: relation "goose_db_version" does not exist at character 3613532026-10-01 09:18:11.678 UTC [560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13542026/10/01 09:18:11 INFO Vacuumed table table=pending_closures13552026/10/01 09:18:11 INFO Vacuumed table table=pending_objects13562026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads13572026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.55ms)13582026/10/01 09:18:11 INFO Vacuumed table table=closures13592026/10/01 09:18:11 OK 20241026095416_initial_model.sql (13.29ms)13602026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.36ms)13612026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000013622026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)13632026/10/01 09:18:11 INFO Vacuumed table table=objects1364--- PASS: TestGCSweepDeliversEachKeyOnce (0.91s)1365=== CONT TestService_RequireScope_OIDC13662026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.78ms)13672026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.23ms)13682026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.19ms)13692026/10/01 09:18:11 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1370--- PASS: TestService_AuthMiddleware (0.91s)1371=== CONT TestService_createPendingClosureHandler13722026/10/01 09:18:11 OK 20241026095416_initial_model.sql (10.1ms)13732026-10-01 09:18:11.694 UTC [561] ERROR: relation "goose_db_version" does not exist at character 3613742026-10-01 09:18:11.694 UTC [561] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13752026/10/01 09:18:11 OK 3_commit_push.sql (8.02ms)13762026/10/01 09:18:11 goose: up to current file version: 313772026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (10.09ms)13782026/10/01 09:18:11 OK 20241026095416_initial_model.sql (12.68ms)13792026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (8.43ms)13802026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)13812026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.8ms)13822026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.17ms)13832026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.24ms)13842026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.11ms)13852026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)13862026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)13872026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.21ms)13882026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000013892026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.08ms)13902026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.47ms)13912026/10/01 09:18:11 OK 20260905000000_add_claims.sql (4.31ms)13922026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.34ms)13932026/10/01 09:18:11 OK 2_object_stats_trigger.sql (2.02ms)13942026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.95ms)13952026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.68ms)13962026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)13972026/10/01 09:18:11 OK 3_commit_push.sql (2.07ms)13982026/10/01 09:18:11 goose: up to current file version: 313992026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.29ms)14002026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000014012026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.51ms)14022026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000014032026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.43ms)14042026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.11ms)14052026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.43ms)14062026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.51ms)14072026-10-01 09:18:11.719 UTC [564] ERROR: relation "goose_db_version" does not exist at character 3614082026-10-01 09:18:11.719 UTC [564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14092026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.52ms)14102026/10/01 09:18:11 OK 3_commit_push.sql (1.32ms)14112026/10/01 09:18:11 goose: up to current file version: 314122026/10/01 09:18:11 OK 3_commit_push.sql (1.13ms)14132026/10/01 09:18:11 goose: up to current file version: 314142026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.11ms)14152026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.33ms)14162026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.56ms)14172026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.05ms)14182026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000014192026/10/01 09:18:11 OK 1_commit_pending_closure.sql (1.95ms)14202026/10/01 09:18:11 OK 20241026095416_initial_model.sql (8.53ms)14212026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.52ms)14222026-10-01 09:18:11.734 UTC [565] ERROR: relation "goose_db_version" does not exist at character 3614232026-10-01 09:18:11.734 UTC [565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14242026/10/01 09:18:11 OK 3_commit_push.sql (679.81µs)14252026/10/01 09:18:11 goose: up to current file version: 314262026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.42ms)14272026-10-01 09:18:11.737 UTC [568] ERROR: relation "goose_db_version" does not exist at character 3614282026-10-01 09:18:11.737 UTC [568] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14292026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.3ms)14302026/10/01 09:18:11 INFO Aborted multipart uploads count=014312026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.73ms)14322026/10/01 09:18:11 INFO Aborted multipart uploads count=014332026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period14342026-10-01 09:18:11.745 UTC [571] ERROR: relation "goose_db_version" does not exist at character 3614352026-10-01 09:18:11.745 UTC [571] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14362026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.49ms)14372026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period14382026/10/01 09:18:11 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=014392026/10/01 09:18:11 OK 20241026095416_initial_model.sql (9.12ms)14402026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.79ms)14412026/10/01 09:18:11 INFO Vacuumed table table=pending_closures14422026/10/01 09:18:11 INFO Vacuumed table table=pending_objects14432026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads14442026/10/01 09:18:11 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=014452026/10/01 09:18:11 INFO Vacuumed table table=closures14462026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)14472026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.52ms)14482026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000014492026/10/01 09:18:11 INFO Vacuumed table table=objects14502026/10/01 09:18:11 INFO Vacuumed table table=pending_closures14512026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.99ms)14522026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.52ms)14532026/10/01 09:18:11 OK 20241026095416_initial_model.sql (12.28ms)1454--- PASS: TestGCMetrics (0.65s)1455=== CONT TestService_AuthMiddleware_OIDC14562026/10/01 09:18:11 OK 2_object_stats_trigger.sql (15.73ms)14572026/10/01 09:18:11 INFO Vacuumed table table=pending_objects14582026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads14592026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (17.41ms)14602026/10/01 09:18:11 OK 20241026095416_initial_model.sql (20.51ms)14612026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (17.12ms)14622026/10/01 09:18:11 OK 3_commit_push.sql (2.11ms)14632026/10/01 09:18:11 goose: up to current file version: 314642026/10/01 09:18:11 INFO Vacuumed table table=closures14652026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.25ms)14662026/10/01 09:18:11 INFO Vacuumed table table=objects14672026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.88ms)14682026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.97ms)1469=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1470=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1471=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1472=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1473=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1474=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1475=== CONT TestService_cleanupPendingClosuresHandler14762026/10/01 09:18:11 OK 20251218171726_add_pins.sql (4.64ms)14772026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (4.18ms)14782026-10-01 09:18:11.784 UTC [572] ERROR: relation "goose_db_version" does not exist at character 3614792026-10-01 09:18:11.784 UTC [572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14802026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (5.24ms)14812026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000014822026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (9.18ms)14832026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (7.9ms)1484--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.02s)1485=== CONT TestService_ReadAuthMiddleware14862026/10/01 09:18:11 OK 1_commit_pending_closure.sql (3.88ms)14872026/10/01 09:18:11 OK 20260905000000_add_claims.sql (5.95ms)14882026/10/01 09:18:11 OK 2_object_stats_trigger.sql (11.76ms)14892026/10/01 09:18:11 OK 20260905000000_add_claims.sql (14.31ms)14902026/10/01 09:18:11 OK 20241026095416_initial_model.sql (10.07ms)14912026/10/01 09:18:11 OK 3_commit_push.sql (1.21ms)14922026/10/01 09:18:11 goose: up to current file version: 314932026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (11.54ms)14942026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.93ms)14952026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)14962026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.55ms)14972026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000014982026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.33ms)14992026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000015002026/10/01 09:18:11 OK 20251218171726_add_pins.sql (2.99ms)15012026/10/01 09:18:11 INFO lead: acquired remote=192.0.2.1:123415022026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.3ms)15032026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.48ms)15042026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.83ms)15052026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.78ms)15062026/10/01 09:18:11 OK 3_commit_push.sql (1.08ms)15072026/10/01 09:18:11 goose: up to current file version: 315082026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)15092026/10/01 09:18:11 OK 3_commit_push.sql (615.75µs)15102026/10/01 09:18:11 goose: up to current file version: 315112026/10/01 09:18:11 OK 20260905000000_add_claims.sql (2.98ms)15122026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.69ms)15132026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.22ms)15142026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000015152026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.45ms)15162026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.52ms)15172026/10/01 09:18:11 OK 3_commit_push.sql (1.23ms)15182026/10/01 09:18:11 goose: up to current file version: 315192026/10/01 09:18:11 INFO lead: acquired remote=192.0.2.1:123415202026/10/01 09:18:11 INFO lead: released remote=192.0.2.1:12341521--- PASS: TestLeadEndsOnShutdown (0.67s)1522=== CONT TestService_AuthMiddleware_MTLSProxyHeader15232026/10/01 09:18:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44513/oidc15242026/10/01 09:18:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15252026/10/01 09:18:11 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTY4OWRlZWEtZDEyNS00ZGJkLTliMmQtMWQwNGQxYTlmZmMxLmNjY2Q2NmJjLTJlN2EtNDE0My05OGMzLWRlNTc0MzM3MWY2M3gxNzkwODQ2MjkxNDYzNTQ4NzYy parts=121526--- PASS: TestRedundantMultipartUpload (1.08s)1527=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15282026-10-01 09:18:11.874 UTC [584] ERROR: relation "goose_db_version" does not exist at character 3615292026-10-01 09:18:11.874 UTC [584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15302026-10-01 09:18:11.877 UTC [585] ERROR: relation "goose_db_version" does not exist at character 3615312026-10-01 09:18:11.877 UTC [585] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15322026/10/01 09:18:11 OK 20241026095416_initial_model.sql (10.79ms)15332026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)15342026/10/01 09:18:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36247/oidc1535--- PASS: TestPushWaitsForSweepHoldingRow (1.13s)1536=== CONT TestOrphanedObjectsGCStressTest15372026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.63ms)15382026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.57ms)15392026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)15402026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)15412026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.63ms)15422026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.4ms)15432026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)15442026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.59ms)15452026-10-01 09:18:11.917 UTC [608] ERROR: relation "goose_db_version" does not exist at character 3615462026-10-01 09:18:11.917 UTC [608] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15472026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.64ms)15482026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (3.39ms)15492026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000015502026-10-01 09:18:11.919 UTC [610] ERROR: relation "goose_db_version" does not exist at character 3615512026-10-01 09:18:11.919 UTC [610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15522026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.88ms)15532026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.78ms)15542026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.61ms)15552026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.35ms)15562026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000015572026/10/01 09:18:11 OK 3_commit_push.sql (1.28ms)15582026/10/01 09:18:11 goose: up to current file version: 315592026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.32ms)15602026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.64ms)15612026/10/01 09:18:11 OK 3_commit_push.sql (1.5ms)15622026/10/01 09:18:11 goose: up to current file version: 315632026/10/01 09:18:11 OK 20241026095416_initial_model.sql (10.04ms)15642026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)15652026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.76ms)15662026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.6ms)15672026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)15682026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)15692026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.37ms)15702026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.05ms)15712026-10-01 09:18:11.947 UTC [662] ERROR: relation "goose_db_version" does not exist at character 3615722026-10-01 09:18:11.947 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15732026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.22ms)15742026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)15752026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.12ms)15762026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000015772026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.65ms)15782026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.17ms)15792026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.77ms)15802026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (2.72ms)15812026/10/01 09:18:11 OK 3_commit_push.sql (1.22ms)15822026/10/01 09:18:11 goose: up to current file version: 315832026/10/01 09:18:11 INFO lead: released remote=192.0.2.1:123415842026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (8.31ms)15852026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000015862026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.95ms)15872026/10/01 09:18:11 OK 20241026095416_initial_model.sql (11.8ms)15882026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.56ms)15892026/10/01 09:18:11 OK 3_commit_push.sql (997.27µs)15902026/10/01 09:18:11 goose: up to current file version: 315912026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)15922026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.5ms)15932026-10-01 09:18:11.973 UTC [699] ERROR: relation "goose_db_version" does not exist at character 3615942026-10-01 09:18:11.973 UTC [699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15952026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.91ms)1596=== NAME TestPinProtectsFromGC1597 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC33165818/001/store/d8y8h639qkryaa6zan78jq93lbrpqz13-pinned-file.txt1598 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC33165818/001/store/xj3zl1ms609pqbaqa8l11rj3c2c4h6z5-unpinned-file.txt15992026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.58ms)16002026/10/01 09:18:11 OK 20260920000000_drop_claims.sql (3.11ms)16012026-10-01 09:18:11.983 UTC [733] ERROR: relation "goose_db_version" does not exist at character 3616022026-10-01 09:18:11.983 UTC [733] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16032026/10/01 09:18:11 OK 20260923120000_add_pushes.sql (2.28ms)16042026/10/01 09:18:11 goose: successfully migrated database to version: 2026092312000016052026/10/01 09:18:11 OK 20241026095416_initial_model.sql (8.2ms)16062026/10/01 09:18:11 OK 1_commit_pending_closure.sql (2.3ms)16072026/10/01 09:18:11 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)16082026/10/01 09:18:11 OK 2_object_stats_trigger.sql (1.17ms)16092026/10/01 09:18:11 OK 3_commit_push.sql (1.08ms)16102026/10/01 09:18:11 goose: up to current file version: 316112026/10/01 09:18:11 OK 20251218171726_add_pins.sql (3.72ms)16122026/10/01 09:18:11 OK 20260628120000_add_object_size_and_stats.sql (3.38ms)16132026/10/01 09:18:11 OK 20260905000000_add_claims.sql (3.46ms)16142026/10/01 09:18:11 OK 20241026095416_initial_model.sql (10.47ms)16152026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)16162026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (1.89ms)1617--- PASS: TestGCBugBareHashReferences (0.87s)1618=== CONT TestCacheConfigHandlerMaxNarSize16192026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.18ms)16202026/10/01 09:18:12 goose: successfully migrated database to version: 202609231200001621--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1622=== CONT TestReadRedirectUsesPublicS3URL16232026/10/01 09:18:12 OK 20251218171726_add_pins.sql (2.79ms)16242026/10/01 09:18:12 OK 1_commit_pending_closure.sql (1.61ms)16252026/10/01 09:18:12 OK 2_object_stats_trigger.sql (778.45µs)16262026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (2.56ms)16272026/10/01 09:18:12 OK 3_commit_push.sql (941.13µs)16282026/10/01 09:18:12 goose: up to current file version: 316292026/10/01 09:18:12 INFO lead: acquired remote=192.0.2.1:123416302026/10/01 09:18:12 OK 20260905000000_add_claims.sql (2.89ms)16312026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.34ms)16322026/10/01 09:18:12 INFO lead: released remote=192.0.2.1:123416332026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.4ms)16342026/10/01 09:18:12 goose: successfully migrated database to version: 202609231200001635--- PASS: TestLeadElectsOneAndHandsOver (0.86s)1636=== CONT TestOrphanedObjectsGC16372026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.28ms)1638=== NAME TestClientMultipleUploads1639 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads1946553689/001/store/4x9cihplvdmsg1mlsnswjdd066khsmbh-test-file-0.txt16402026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.88ms)16412026/10/01 09:18:12 OK 3_commit_push.sql (1.38ms)16422026/10/01 09:18:12 goose: up to current file version: 31643=== NAME TestClientWithDependencies1644 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1587208985/001/store/i9adpwlyv0a4qn4f629k9ym1gg4rykmy-test-script1645=== NAME TestClientIntegration1646 client_integration_test.go:286: Created store path: /build/TestClientIntegration1573725489/002/store/dlww4dmjwh3fj5qknj7kfmxla86cxl3p-test-file.txt1647=== NAME TestClientMultipleUploads1648 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads1946553689/001/store/a2mkvyx7sh5wy94n0s1x3yh8vcj0b823-test-file-1.txt1649--- PASS: TestCacheStatsHandler (0.44s)1650=== CONT TestReadProxyRangeRequest16512026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures16522026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes16532026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures16542026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures16552026/10/01 09:18:12 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16562026/10/01 09:18:12 INFO Uploading g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy-shared-dep (136B)16572026/10/01 09:18:12 INFO Uploading ixzms7s1vdj1wn2n71jq2x7zv0qcd167-b (216B)16582026/10/01 09:18:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16592026/10/01 09:18:12 INFO Uploading d8y8h639qkryaa6zan78jq93lbrpqz13-pinned-file.txt (128B)16602026/10/01 09:18:12 WARN Failed to register uploaded object key=a7b404xzszmkf2wp5qzqih8i5bqwrpd8.ls error="server returned 404: 404 page not found\n"16612026/10/01 09:18:12 WARN Failed to register uploaded object key=d8y8h639qkryaa6zan78jq93lbrpqz13.ls error="server returned 404: 404 page not found\n"16622026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16632026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16642026/10/01 09:18:12 WARN Failed to register uploaded object key=g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy.ls error="server returned 404: 404 page not found\n"16652026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16662026/10/01 09:18:12 WARN Failed to register uploaded object key=ixzms7s1vdj1wn2n71jq2x7zv0qcd167.ls error="server returned 404: 404 page not found\n"16672026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16682026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1k26vz75978dcbidr064ww40mjrjkqdmwf0j7szxplv04qmvwwv5.nar.zst error="server returned 404: 404 page not found\n"16692026/10/01 09:18:12 INFO Signed narinfos id=1 count=116702026/10/01 09:18:12 INFO Signed narinfos id=1 count=216712026/10/01 09:18:12 INFO Uploading 1 narinfos16722026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16732026/10/01 09:18:12 INFO Signed narinfos id=2 count=216742026/10/01 09:18:12 INFO Uploading 4 narinfos1675=== NAME TestClientWithDependencies1676 client_integration_test.go:615: Found 1 dependencies (including self)1677--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.43s)1678=== CONT TestObjectStatsTrigger16792026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete16802026/10/01 09:18:12 WARN Failed to register uploaded object key=d8y8h639qkryaa6zan78jq93lbrpqz13.narinfo error="server returned 404: 404 page not found\n"16812026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes16822026-10-01 09:18:12.073 UTC [995] ERROR: relation "goose_db_version" does not exist at character 3616832026-10-01 09:18:12.073 UTC [995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16842026/10/01 09:18:12 WARN Failed to register uploaded object key=a7b404xzszmkf2wp5qzqih8i5bqwrpd8.narinfo error="server returned 404: 404 page not found\n"16852026/10/01 09:18:12 WARN Failed to register uploaded object key=ixzms7s1vdj1wn2n71jq2x7zv0qcd167.narinfo error="server returned 404: 404 page not found\n"16862026/10/01 09:18:12 WARN Failed to register uploaded object key=g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy.narinfo error="server returned 404: 404 page not found\n"16872026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes16882026/10/01 09:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16892026/10/01 09:18:12 WARN Failed to register uploaded object key=g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy.narinfo error="server returned 404: 404 page not found\n"16902026/10/01 09:18:12 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16912026/10/01 09:18:12 INFO Uploading cfj31pdcsr1c6d9k775dg7qccxc241jc-top (224B)16922026/10/01 09:18:12 INFO Uploading a4jkixals9lgmzbr98hh3xx5y47c1sdx-shared-dep (136B)16932026/10/01 09:18:12 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16942026/10/01 09:18:12 INFO Uploading wrly157f78gkxhhgcvhbzgrxyka4aj3a-shared-dep (136B)16952026/10/01 09:18:12 INFO Uploading 9460f3378rw1fy2jw5c4hnhmnikbqlx4-b (216B)16962026/10/01 09:18:12 INFO Upload complete. (65ms)16972026/10/01 09:18:12 INFO Completed upload id=116982026/10/01 09:18:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16992026/10/01 09:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17002026/10/01 09:18:12 INFO Completed upload id=217012026/10/01 09:18:12 INFO Upload complete. (72ms)17022026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17032026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/0fa2gjpl4axdrldc2z54raa1h29cqdy4i3zhvs4xmxscdi5p3x4x.nar.zst error="server returned 404: 404 page not found\n"17042026/10/01 09:18:12 WARN Failed to register uploaded object key=cfj31pdcsr1c6d9k775dg7qccxc241jc.ls error="server returned 404: 404 page not found\n"17052026/10/01 09:18:12 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst17062026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1707--- PASS: TestCompleteMultipartUnregistered (0.43s)17082026/10/01 09:18:12 WARN Failed to register uploaded object key=a4jkixals9lgmzbr98hh3xx5y47c1sdx.ls error="server returned 404: 404 page not found\n"1709=== CONT TestReadRedirectKeepsNarinfoProxied17102026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/0rxpq8sv8l7j1jvk18w889jm7av163hg6xv3a65fyq3irmvahijz.nar.zst error="server returned 404: 404 page not found\n"17112026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17122026/10/01 09:18:12 WARN Failed to register uploaded object key=wrly157f78gkxhhgcvhbzgrxyka4aj3a.ls error="server returned 404: 404 page not found\n"17132026/10/01 09:18:12 WARN Failed to register uploaded object key=5fkg0vk1k97h7ab739l3rby7sw81bzah.ls error="server returned 404: 404 page not found\n"17142026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17152026/10/01 09:18:12 INFO Signed narinfos id=1 count=217162026/10/01 09:18:12 WARN Failed to register uploaded object key=9460f3378rw1fy2jw5c4hnhmnikbqlx4.ls error="server returned 404: 404 page not found\n"17172026/10/01 09:18:12 INFO Uploading 2 narinfos1718=== NAME TestClientFallsBackToClosures1719 client_pushes_test.go:112: Retrieved narinfo from S3:1720 StorePath: /build/TestClientFallsBackToClosures1864825849/001/store/g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy-shared-dep1721 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1722 Compression: zstd1723 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821724 NarSize: 1361725 References: 1726 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17272026/10/01 09:18:12 INFO Signed narinfos id=1 count=317282026/10/01 09:18:12 INFO Uploading 3 narinfos1729 client_pushes_test.go:112: Retrieved narinfo from S3:1730 StorePath: /build/TestClientFallsBackToClosures1864825849/001/store/a7b404xzszmkf2wp5qzqih8i5bqwrpd8-a1731 URL: nar/1k26vz75978dcbidr064ww40mjrjkqdmwf0j7szxplv04qmvwwv5.nar.zst1732 Compression: zstd1733 NarHash: sha256:1k26vz75978dcbidr064ww40mjrjkqdmwf0j7szxplv04qmvwwv51734 NarSize: 2161735 References: /build/TestClientFallsBackToClosures1864825849/001/store/g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy-shared-dep1736 CA: text:sha256:00vjrhjf3yrnplc75l6kx6z3pag9f3bbyjx09lkx9az72c7m15h717372026/10/01 09:18:12 WARN Failed to register uploaded object key=cfj31pdcsr1c6d9k775dg7qccxc241jc.narinfo error="server returned 404: 404 page not found\n"17382026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete17392026/10/01 09:18:12 WARN Failed to register uploaded object key=a4jkixals9lgmzbr98hh3xx5y47c1sdx.narinfo error="server returned 404: 404 page not found\n"17402026/10/01 09:18:12 WARN Failed to register uploaded object key=9460f3378rw1fy2jw5c4hnhmnikbqlx4.narinfo error="server returned 404: 404 page not found\n"17412026/10/01 09:18:12 WARN Failed to register uploaded object key=5fkg0vk1k97h7ab739l3rby7sw81bzah.narinfo error="server returned 404: 404 page not found\n"17422026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete17432026/10/01 09:18:12 WARN Failed to register uploaded object key=wrly157f78gkxhhgcvhbzgrxyka4aj3a.narinfo error="server returned 404: 404 page not found\n"1744=== NAME TestClientMultipleUploads1745 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads1946553689/001/store/yqm1dncjc3vk5k7azxal1lz5dm3a7wng-test-file-2.txt17462026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.3ms)1747=== NAME TestClientFallsBackToClosures1748 client_pushes_test.go:112: Retrieved narinfo from S3:1749 StorePath: /build/TestClientFallsBackToClosures1864825849/001/store/ixzms7s1vdj1wn2n71jq2x7zv0qcd167-b1750 URL: nar/1k26vz75978dcbidr064ww40mjrjkqdmwf0j7szxplv04qmvwwv5.nar.zst1751 Compression: zstd1752 NarHash: sha256:1k26vz75978dcbidr064ww40mjrjkqdmwf0j7szxplv04qmvwwv51753 NarSize: 2161754 References: /build/TestClientFallsBackToClosures1864825849/001/store/g9dlyz2bqkmvawdj3qhgjjcfh1xl1vgy-shared-dep1755 CA: text:sha256:00vjrhjf3yrnplc75l6kx6z3pag9f3bbyjx09lkx9az72c7m15h71756--- PASS: TestClientFallsBackToClosures (0.70s)1757=== CONT TestMultipartCleanup17582026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (8.75ms)17592026/10/01 09:18:12 INFO Upload complete. (66ms)17602026/10/01 09:18:12 INFO Upload complete. (65ms)1761=== NAME TestClientSharedPathCommittedMidPush1762 client_integration_test.go:680: Retrieved narinfo from S3:1763 StorePath: /build/TestClientSharedPathCommittedMidPush3043821008/001/store/a4jkixals9lgmzbr98hh3xx5y47c1sdx-shared-dep1764 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1765 Compression: zstd1766 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821767 NarSize: 1361768 References: 1769 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1770=== NAME TestClientPushesUseOnePush1771 client_pushes_test.go:97: Retrieved narinfo from S3:1772 StorePath: /build/TestClientPushesUseOnePush3880101453/001/store/wrly157f78gkxhhgcvhbzgrxyka4aj3a-shared-dep1773 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1774 Compression: zstd1775 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821776 NarSize: 1361777 References: 1778 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1779--- PASS: TestService_ReadScope_PublicByDefault (0.45s)1780=== CONT TestReadRedirectNar17812026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.23ms)1782=== NAME TestClientPushesUseOnePush1783 client_pushes_test.go:97: Retrieved narinfo from S3:1784 StorePath: /build/TestClientPushesUseOnePush3880101453/001/store/5fkg0vk1k97h7ab739l3rby7sw81bzah-a1785 URL: nar/0rxpq8sv8l7j1jvk18w889jm7av163hg6xv3a65fyq3irmvahijz.nar.zst1786 Compression: zstd1787 NarHash: sha256:0rxpq8sv8l7j1jvk18w889jm7av163hg6xv3a65fyq3irmvahijz1788 NarSize: 2161789 References: /build/TestClientPushesUseOnePush3880101453/001/store/wrly157f78gkxhhgcvhbzgrxyka4aj3a-shared-dep1790 CA: text:sha256:0bl94vmdcsii7cqwmgfi236f05g1fyn3mzkiv7pd6hmhvb4qgi981791=== NAME TestClientSharedPathCommittedMidPush1792 client_integration_test.go:680: Retrieved narinfo from S3:1793 StorePath: /build/TestClientSharedPathCommittedMidPush3043821008/001/store/cfj31pdcsr1c6d9k775dg7qccxc241jc-top1794 URL: nar/0fa2gjpl4axdrldc2z54raa1h29cqdy4i3zhvs4xmxscdi5p3x4x.nar.zst1795 Compression: zstd1796 NarHash: sha256:0fa2gjpl4axdrldc2z54raa1h29cqdy4i3zhvs4xmxscdi5p3x4x1797 NarSize: 2241798 References: /build/TestClientSharedPathCommittedMidPush3043821008/001/store/a4jkixals9lgmzbr98hh3xx5y47c1sdx-shared-dep1799 CA: text:sha256:1lrbc58y7d0v4r2vg2iwrrbz3q4ysq08jcwxx0rzimvwlypwbgxv1800=== NAME TestClientPushesUseOnePush1801 client_pushes_test.go:97: Retrieved narinfo from S3:1802 StorePath: /build/TestClientPushesUseOnePush3880101453/001/store/9460f3378rw1fy2jw5c4hnhmnikbqlx4-b1803 URL: nar/0rxpq8sv8l7j1jvk18w889jm7av163hg6xv3a65fyq3irmvahijz.nar.zst18042026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)1805 Compression: zstd1806 NarHash: sha256:0rxpq8sv8l7j1jvk18w889jm7av163hg6xv3a65fyq3irmvahijz1807 NarSize: 2161808 References: /build/TestClientPushesUseOnePush3880101453/001/store/wrly157f78gkxhhgcvhbzgrxyka4aj3a-shared-dep1809 CA: text:sha256:0bl94vmdcsii7cqwmgfi236f05g1fyn3mzkiv7pd6hmhvb4qgi981810--- PASS: TestClientSharedPathCommittedMidPush (0.65s)1811=== CONT TestServerTLSConfig1812=== RUN TestServerTLSConfig/no_client_CA1813=== PAUSE TestServerTLSConfig/no_client_CA1814=== RUN TestServerTLSConfig/missing_CA_file1815=== PAUSE TestServerTLSConfig/missing_CA_file1816=== RUN TestServerTLSConfig/not_a_PEM_file1817=== PAUSE TestServerTLSConfig/not_a_PEM_file1818=== CONT TestReadProxyDisabled18192026-10-01 09:18:12.111 UTC [1131] ERROR: relation "goose_db_version" does not exist at character 3618202026-10-01 09:18:12.111 UTC [1131] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18212026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.4ms)1822--- PASS: TestClientPushesUseOnePush (0.69s)1823=== CONT TestService_NativeMTLS18242026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes1825=== NAME TestClientCADerivations1826 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2581485555/001/store/f0xyk2k7ki4mv2vrycdwssp6zsrlzpbx-ca-test18272026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.82ms)18282026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (4.02ms)18292026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000018302026/10/01 09:18:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18312026/10/01 09:18:12 INFO Uploading dlww4dmjwh3fj5qknj7kfmxla86cxl3p-test-file.txt (152B)18322026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.52ms)18332026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.79ms)18342026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18352026/10/01 09:18:12 WARN Failed to register uploaded object key=dlww4dmjwh3fj5qknj7kfmxla86cxl3p.ls error="server returned 404: 404 page not found\n"18362026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18372026/10/01 09:18:12 OK 3_commit_push.sql (1.42ms)18382026/10/01 09:18:12 goose: up to current file version: 318392026/10/01 09:18:12 INFO Signed narinfos id=1 count=118402026/10/01 09:18:12 INFO Uploading 1 narinfos18412026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures18422026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.23ms)18432026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete18442026/10/01 09:18:12 WARN Failed to register uploaded object key=dlww4dmjwh3fj5qknj7kfmxla86cxl3p.narinfo error="server returned 404: 404 page not found\n"18452026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.52ms)18462026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.77ms)18472026/10/01 09:18:12 INFO Upload complete. (63ms)18482026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes18492026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)18502026-10-01 09:18:12.143 UTC [1209] ERROR: relation "goose_db_version" does not exist at character 3618512026-10-01 09:18:12.143 UTC [1209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1852 client_ca_test.go:139: Found 1 dependencies (including self)18532026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.9ms)18542026/10/01 09:18:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18552026/10/01 09:18:12 INFO Uploading i9adpwlyv0a4qn4f629k9ym1gg4rykmy-test-script (136B)18562026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes18572026/10/01 09:18:12 WARN Failed to register uploaded object key=log/8n0kh081rn5jq34iqpn2lgg1kmycagw9-test-script.drv error="server returned 404: 404 page not found\n"18582026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18592026/10/01 09:18:12 WARN Failed to register uploaded object key=i9adpwlyv0a4qn4f629k9ym1gg4rykmy.ls error="server returned 404: 404 page not found\n"18602026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18612026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures18622026/10/01 09:18:12 INFO Signed narinfos id=1 count=118632026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures18642026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures18652026/10/01 09:18:12 INFO Uploading 1 narinfos18662026-10-01 09:18:12.152 UTC [1245] ERROR: relation "goose_db_version" does not exist at character 3618672026-10-01 09:18:12.152 UTC [1245] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18682026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (9.34ms)18692026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete18702026/10/01 09:18:12 WARN Failed to register uploaded object key=i9adpwlyv0a4qn4f629k9ym1gg4rykmy.narinfo error="server returned 404: 404 page not found\n"18712026/10/01 09:18:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18722026/10/01 09:18:12 INFO Uploading xj3zl1ms609pqbaqa8l11rj3c2c4h6z5-unpinned-file.txt (128B)18732026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.46ms)18742026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000018752026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.68ms)18762026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18772026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.77ms)18782026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18792026/10/01 09:18:12 WARN Failed to register uploaded object key=xj3zl1ms609pqbaqa8l11rj3c2c4h6z5.ls error="server returned 404: 404 page not found\n"18802026/10/01 09:18:12 INFO Signed narinfos id=2 count=118812026/10/01 09:18:12 INFO Uploading 1 narinfos18822026/10/01 09:18:12 INFO Upload complete. (59ms)18832026/10/01 09:18:12 OK 3_commit_push.sql (1.68ms)18842026/10/01 09:18:12 goose: up to current file version: 318852026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes1886=== NAME TestClientWithDependencies1887 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1587208985/001/store) requires matching store prefix18882026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/2/complete18892026/10/01 09:18:12 WARN Failed to register uploaded object key=xj3zl1ms609pqbaqa8l11rj3c2c4h6z5.narinfo error="server returned 404: 404 page not found\n"1890--- PASS: TestClientWithDependencies (0.60s)1891=== CONT TestMetricsInventory18922026/10/01 09:18:12 OK 20241026095416_initial_model.sql (13.91ms)18932026/10/01 09:18:12 INFO Upload complete. (55ms)18942026/10/01 09:18:12 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18952026/10/01 09:18:12 INFO Uploading 4x9cihplvdmsg1mlsnswjdd066khsmbh-test-file-0.txt (160B)18962026/10/01 09:18:12 INFO Uploading a2mkvyx7sh5wy94n0s1x3yh8vcj0b823-test-file-1.txt (160B)18972026/10/01 09:18:12 INFO Uploading yqm1dncjc3vk5k7azxal1lz5dm3a7wng-test-file-2.txt (160B)18982026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)18992026/10/01 09:18:12 OK 20241026095416_initial_model.sql (13.38ms)19002026/10/01 09:18:12 INFO All 1 paths already cached19012026/10/01 09:18:12 INFO Received cleanup request method=DELETE path=/api/pending_closures19022026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)1903=== NAME TestClientIntegration1904 client_integration_test.go:312: Retrieved narinfo from S3:1905 StorePath: /build/TestClientIntegration1573725489/002/store/dlww4dmjwh3fj5qknj7kfmxla86cxl3p-test-file.txt1906 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1907 Compression: zstd1908 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11909 NarSize: 1521910 References: 1911 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk119122026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.88ms)19132026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19142026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19152026/10/01 09:18:12 WARN Failed to register uploaded object key=yqm1dncjc3vk5k7azxal1lz5dm3a7wng.ls error="server returned 404: 404 page not found\n"19162026/10/01 09:18:12 WARN Failed to register uploaded object key=4x9cihplvdmsg1mlsnswjdd066khsmbh.ls error="server returned 404: 404 page not found\n"19172026/10/01 09:18:12 WARN Failed to register uploaded object key=a2mkvyx7sh5wy94n0s1x3yh8vcj0b823.ls error="server returned 404: 404 page not found\n"19182026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19192026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19202026/10/01 09:18:12 INFO Signed narinfos id=1 count=319212026/10/01 09:18:12 INFO Uploading 3 narinfos19222026/10/01 09:18:12 INFO Aborted multipart uploads count=019232026-10-01 09:18:12.178 UTC [1284] ERROR: relation "goose_db_version" does not exist at character 3619242026-10-01 09:18:12.178 UTC [1284] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1925 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1926 client_integration_test.go:313: Decompressed .ls content (64 bytes):1927 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1928 client_integration_test.go:316: Testing garbage collection...19292026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.46ms)19302026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures19312026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.34ms)19322026-10-01 09:18:12.181 UTC [1286] ERROR: relation "goose_db_version" does not exist at character 3619332026-10-01 09:18:12.181 UTC [1286] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19342026/10/01 09:18:12 WARN Failed to register uploaded object key=4x9cihplvdmsg1mlsnswjdd066khsmbh.narinfo error="server returned 404: 404 page not found\n"19352026/10/01 09:18:12 WARN Failed to register uploaded object key=a2mkvyx7sh5wy94n0s1x3yh8vcj0b823.narinfo error="server returned 404: 404 page not found\n"19362026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete19372026/10/01 09:18:12 WARN Failed to register uploaded object key=yqm1dncjc3vk5k7azxal1lz5dm3a7wng.narinfo error="server returned 404: 404 page not found\n"19382026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)19392026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.96ms)19402026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (3.04ms)19412026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.43ms)19422026/10/01 09:18:12 INFO Upload complete. (64ms)1943=== NAME TestClientMultipleUploads1944 client_integration_test.go:369: Uploaded 3 paths in 98.679178ms19452026/10/01 09:18:12 INFO Received cleanup request method=DELETE path=/api/pending_closures19462026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.47ms)19472026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000019482026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.94ms)19492026/10/01 09:18:12 INFO Aborted multipart uploads count=119502026-10-01 09:18:12.192 UTC [1305] ERROR: relation "goose_db_version" does not exist at character 3619512026-10-01 09:18:12.192 UTC [1305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19522026-10-01 09:18:12.192 UTC [1306] ERROR: relation "goose_db_version" does not exist at character 3619532026-10-01 09:18:12.192 UTC [1306] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19542026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.68ms)19552026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.83ms)19562026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000019572026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.45ms)19582026/10/01 09:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19592026-10-01 09:18:12.195 UTC [584] ERROR: Closure does not exist: id=119602026-10-01 09:18:12.195 UTC [584] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE19612026-10-01 09:18:12.195 UTC [584] STATEMENT: -- name: CommitPendingClosure :exec1962 SELECT commit_pending_closure($1::bigint)1963 19642026-10-01 09:18:12.195 UTC [1308] ERROR: relation "goose_db_version" does not exist at character 3619652026-10-01 09:18:12.195 UTC [1308] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1966--- PASS: TestService_cleanupPendingClosuresHandler (0.42s)1967=== CONT TestReadProxyRootRedirectsToIndexHTML19682026/10/01 09:18:12 OK 3_commit_push.sql (1.62ms)19692026/10/01 09:18:12 goose: up to current file version: 319702026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.65ms)19712026/10/01 09:18:12 OK 20241026095416_initial_model.sql (13.48ms)1972--- PASS: TestClientMultipleUploads (0.62s)1973=== CONT TestNARDeduplicationMetadataUploadBug19742026/10/01 09:18:12 OK 2_object_stats_trigger.sql (2.43ms)1975--- PASS: TestService_ReadAuthMiddleware (0.41s)19762026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.45ms)1977=== CONT TestReadProxyConditionalGet19782026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)19792026/10/01 09:18:12 OK 3_commit_push.sql (1.27ms)19802026/10/01 09:18:12 goose: up to current file version: 319812026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)19822026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.32ms)19832026/10/01 09:18:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures19842026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.22ms)19852026/10/01 09:18:12 INFO Garbage collection started19862026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.62ms)19872026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)19882026/10/01 09:18:12 OK 20241026095416_initial_model.sql (12.63ms)19892026/10/01 09:18:12 OK 20241026095416_initial_model.sql (12.71ms)19902026/10/01 09:18:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures19912026/10/01 09:18:12 INFO Garbage collection started19922026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (7.45ms)19932026/10/01 09:18:12 OK 20241026095416_initial_model.sql (18.23ms)19942026/10/01 09:18:12 OK 20260905000000_add_claims.sql (9.12ms)19952026/10/01 09:18:12 OK 20260905000000_add_claims.sql (10.65ms)19962026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (8.39ms)19972026/10/01 09:18:12 INFO Aborted multipart uploads count=019982026/10/01 09:18:12 INFO Aborted multipart uploads count=019992026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.99ms)20002026/10/01 09:18:12 OK 20251218171726_add_pins.sql (5.02ms)20012026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (4.44ms)20022026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.22ms)20032026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (4.36ms)2004--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.40s)2005=== CONT TestCreatePendingClosureRejectsOversizedNAR20062026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures2007--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2008=== CONT TestReadProxyHead20092026/10/01 09:18:12 WARN Force mode enabled - objects will be deleted immediately without grace period20102026/10/01 09:18:12 WARN Force mode enabled - objects will be deleted immediately without grace period20112026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.85ms)20122026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000020132026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.35ms)20142026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (3.62ms)20152026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000020162026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.7ms)20172026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.59ms)20182026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.75ms)20192026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.68ms)20202026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.46ms)20212026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.12ms)20222026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (5.1ms)20232026/10/01 09:18:12 OK 3_commit_push.sql (1.48ms)20242026/10/01 09:18:12 goose: up to current file version: 320252026/10/01 09:18:12 OK 2_object_stats_trigger.sql (2.21ms)20262026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.07ms)20272026/10/01 09:18:12 OK 3_commit_push.sql (2.25ms)20282026/10/01 09:18:12 goose: up to current file version: 320292026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (3.23ms)20302026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.99ms)20312026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.5ms)20322026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.44ms)20332026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000020342026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.51ms)20352026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000020362026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.47ms)20372026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.36ms)20382026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.35ms)20392026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000020402026/10/01 09:18:12 OK 1_commit_pending_closure.sql (3ms)20412026/10/01 09:18:12 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=020422026/10/01 09:18:12 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=020432026/10/01 09:18:12 OK 2_object_stats_trigger.sql (2.74ms)20442026/10/01 09:18:12 OK 2_object_stats_trigger.sql (2.14ms)20452026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.97ms)20462026/10/01 09:18:12 OK 3_commit_push.sql (2.31ms)20472026/10/01 09:18:12 goose: up to current file version: 320482026/10/01 09:18:12 OK 3_commit_push.sql (1.79ms)20492026/10/01 09:18:12 goose: up to current file version: 320502026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.72ms)20512026/10/01 09:18:12 INFO Vacuumed table table=pending_closures20522026/10/01 09:18:12 INFO Vacuumed table table=pending_closures20532026/10/01 09:18:12 OK 3_commit_push.sql (1.36ms)20542026/10/01 09:18:12 goose: up to current file version: 320552026/10/01 09:18:12 INFO Vacuumed table table=pending_objects20562026/10/01 09:18:12 INFO Vacuumed table table=pending_objects20572026-10-01 09:18:12.250 UTC [1372] ERROR: relation "goose_db_version" does not exist at character 3620582026-10-01 09:18:12.250 UTC [1372] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2059=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2060=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2061=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2062=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2063=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2064=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2065=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2066=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2067=== CONT TestReadProxyInvalidPath20682026/10/01 09:18:12 INFO Vacuumed table table=multipart_uploads20692026/10/01 09:18:12 INFO Vacuumed table table=multipart_uploads20702026/10/01 09:18:12 INFO Vacuumed table table=closures20712026/10/01 09:18:12 INFO Vacuumed table table=closures20722026/10/01 09:18:12 INFO Vacuumed table table=objects20732026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes20742026/10/01 09:18:12 INFO Vacuumed table table=objects20752026/10/01 09:18:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20762026/10/01 09:18:12 INFO Uploading f0xyk2k7ki4mv2vrycdwssp6zsrlzpbx-ca-test (144B)20772026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.1ms)20782026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)20792026/10/01 09:18:12 WARN Failed to register uploaded object key=f0xyk2k7ki4mv2vrycdwssp6zsrlzpbx.ls error="server returned 404: 404 page not found\n"20802026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20812026/10/01 09:18:12 WARN Failed to register uploaded object key=log/7md296ph92zaa7fl4fgn6vanlzsrhc1v-ca-test.drv error="server returned 404: 404 page not found\n"20822026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20832026/10/01 09:18:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20842026/10/01 09:18:12 WARN mTLS auth: bound subjects configured but subject DN unavailable20852026/10/01 09:18:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2086--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.42s)2087=== CONT TestUploadHandlersRejectInvalidKeys2088=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2089=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2090=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2091=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20922026/10/01 09:18:12 INFO Signed narinfos id=1 count=12093=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2094=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2095=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2096=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20972026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.13ms)2098=== CONT TestReadProxy40420992026/10/01 09:18:12 INFO Uploading 1 narinfos21002026-10-01 09:18:12.278 UTC [1392] ERROR: relation "goose_db_version" does not exist at character 3621012026-10-01 09:18:12.278 UTC [1392] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21022026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete21032026/10/01 09:18:12 WARN Failed to register uploaded object key=f0xyk2k7ki4mv2vrycdwssp6zsrlzpbx.narinfo error="server returned 404: 404 page not found\n"21042026-10-01 09:18:12.278 UTC [1393] ERROR: relation "goose_db_version" does not exist at character 3621052026-10-01 09:18:12.278 UTC [1393] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21062026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.92ms)2107--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.99s)2108=== CONT TestProxyWriteTimeout2109=== RUN TestProxyWriteTimeout/narinfo2110=== PAUSE TestProxyWriteTimeout/narinfo2111=== RUN TestProxyWriteTimeout/1_GiB_nar2112=== PAUSE TestProxyWriteTimeout/1_GiB_nar2113=== RUN TestProxyWriteTimeout/10_GiB_nar2114=== PAUSE TestProxyWriteTimeout/10_GiB_nar2115=== RUN TestProxyWriteTimeout/unknown_size2116=== PAUSE TestProxyWriteTimeout/unknown_size2117=== CONT TestReadProxyNarStreaming21182026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.95ms)21192026-10-01 09:18:12.284 UTC [1395] ERROR: relation "goose_db_version" does not exist at character 3621202026-10-01 09:18:12.284 UTC [1395] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21212026/10/01 09:18:12 INFO Upload complete. (103ms)21222026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (3.73ms)21232026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (3.15ms)21242026/10/01 09:18:12 goose: successfully migrated database to version: 202609231200002125=== NAME TestClientCADerivations2126 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2581485555/001/store/f0xyk2k7ki4mv2vrycdwssp6zsrlzpbx-ca-test2127 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2128 Compression: zstd2129 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2130 NarSize: 1442131 References: 2132 Deriver: /build/TestClientCADerivations2581485555/001/store/7md296ph92zaa7fl4fgn6vanlzsrhc1v-ca-test.drv2133 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2134 client_ca_test.go:185: Checking for realisation files in S3...21352026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.36ms)2136 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2137 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21382026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.58ms)21392026/10/01 09:18:12 OK 3_commit_push.sql (1.31ms)21402026/10/01 09:18:12 goose: up to current file version: 321412026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.84ms)21422026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.47ms)21432026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)21442026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)21452026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.23ms)21462026/10/01 09:18:12 OK 20241026095416_initial_model.sql (13.07ms)21472026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.06ms)21482026-10-01 09:18:12.304 UTC [1400] ERROR: relation "goose_db_version" does not exist at character 3621492026-10-01 09:18:12.304 UTC [1400] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21502026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)21512026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)21522026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.72ms)21532026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.93ms)21542026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.58ms)21552026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.51ms)21562026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.6ms)21572026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)21582026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.52ms)21592026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.19ms)21602026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000021612026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.51ms)21622026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000021632026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.86ms)21642026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.91ms)21652026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.28ms)21662026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.37ms)21672026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.68ms)21682026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.83ms)21692026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.72ms)21702026/10/01 09:18:12 OK 3_commit_push.sql (1.11ms)21712026/10/01 09:18:12 goose: up to current file version: 321722026/10/01 09:18:12 OK 3_commit_push.sql (1.64ms)21732026/10/01 09:18:12 goose: up to current file version: 321742026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.26ms)21752026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000021762026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)21772026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.05ms)21782026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.08ms)21792026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.83ms)21802026/10/01 09:18:12 OK 3_commit_push.sql (1.22ms)21812026/10/01 09:18:12 goose: up to current file version: 321822026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)21832026-10-01 09:18:12.338 UTC [1419] ERROR: relation "goose_db_version" does not exist at character 3621842026-10-01 09:18:12.338 UTC [1419] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21852026/10/01 09:18:12 OK 20260905000000_add_claims.sql (8.01ms)21862026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.76ms)2187=== RUN TestService_RequireScope_OIDC/builder_may_write2188=== PAUSE TestService_RequireScope_OIDC/builder_may_write2189=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2190=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2191=== RUN TestService_RequireScope_OIDC/ops_may_admin2192=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2193=== RUN TestService_RequireScope_OIDC/ops_may_not_write2194=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2195=== RUN TestService_RequireScope_OIDC/reader_may_not_write2196=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2197=== RUN TestService_RequireScope_OIDC/static_token_may_admin2198=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2199=== RUN TestService_RequireScope_OIDC/static_token_may_write2200=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2201=== RUN TestService_RequireScope_OIDC/reader_may_read2202=== PAUSE TestService_RequireScope_OIDC/reader_may_read2203=== RUN TestService_RequireScope_OIDC/writer_implies_read2204=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2205=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2206=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2207=== CONT TestReadProxyNarinfoAlreadyDecompressed22082026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.68ms)22092026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000022102026/10/01 09:18:12 OK 1_commit_pending_closure.sql (1.9ms)22112026/10/01 09:18:12 OK 2_object_stats_trigger.sql (934.55µs)22122026/10/01 09:18:12 OK 3_commit_push.sql (579.55µs)22132026/10/01 09:18:12 goose: up to current file version: 322142026/10/01 09:18:12 OK 20241026095416_initial_model.sql (9.23ms)22152026-10-01 09:18:12.354 UTC [1421] ERROR: relation "goose_db_version" does not exist at character 3622162026-10-01 09:18:12.354 UTC [1421] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22172026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)22182026-10-01 09:18:12.357 UTC [1423] ERROR: relation "goose_db_version" does not exist at character 3622192026-10-01 09:18:12.357 UTC [1423] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22202026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.18ms)22212026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)2222--- PASS: TestReadRedirectUsesPublicS3URL (0.36s)2223=== CONT TestProxyHeadersOnlyTrustedOnSocket22242026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.74ms)22252026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.7ms)22262026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.45ms)22272026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000022282026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.78ms)22292026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2ms)22302026/10/01 09:18:12 OK 1_commit_pending_closure.sql (3.23ms)22312026/10/01 09:18:12 OK 20241026095416_initial_model.sql (12.3ms)22322026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.26ms)22332026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.19ms)22342026/10/01 09:18:12 OK 3_commit_push.sql (1.98ms)22352026/10/01 09:18:12 goose: up to current file version: 322362026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.91ms)22372026/10/01 09:18:12 OK 20251218171726_add_pins.sql (4.13ms)22382026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.02ms)2239=== NAME TestClientCADerivations2240 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2241 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2242 error: binary cache 's3://bucket39?endpoint=http://localhost:38369®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2581485555/001/store'2243 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12244--- PASS: TestClientCADerivations (0.79s)2245=== CONT TestIsValidUploadKey2246=== RUN TestIsValidUploadKey/narinfo2247=== PAUSE TestIsValidUploadKey/narinfo2248=== RUN TestIsValidUploadKey/nar_zst2249=== PAUSE TestIsValidUploadKey/nar_zst2250=== RUN TestIsValidUploadKey/nar_xz2251=== PAUSE TestIsValidUploadKey/nar_xz2252=== RUN TestIsValidUploadKey/nar_plain2253=== PAUSE TestIsValidUploadKey/nar_plain2254=== RUN TestIsValidUploadKey/listing2255=== PAUSE TestIsValidUploadKey/listing2256=== RUN TestIsValidUploadKey/build_log2257=== PAUSE TestIsValidUploadKey/build_log2258=== RUN TestIsValidUploadKey/build_log_home-manager_file2259=== PAUSE TestIsValidUploadKey/build_log_home-manager_file2260=== RUN TestIsValidUploadKey/build_log_plus_in_name2261=== PAUSE TestIsValidUploadKey/build_log_plus_in_name2262=== RUN TestIsValidUploadKey/build_log_question_mark2263=== PAUSE TestIsValidUploadKey/build_log_question_mark2264=== RUN TestIsValidUploadKey/build_log_equals2265=== PAUSE TestIsValidUploadKey/build_log_equals2266=== RUN TestIsValidUploadKey/realisation2267=== PAUSE TestIsValidUploadKey/realisation2268=== RUN TestIsValidUploadKey/realisation_plus_in_output2269=== PAUSE TestIsValidUploadKey/realisation_plus_in_output22702026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)2271=== RUN TestIsValidUploadKey/nix-cache-info2272=== PAUSE TestIsValidUploadKey/nix-cache-info2273=== RUN TestIsValidUploadKey/index.html2274=== PAUSE TestIsValidUploadKey/index.html2275=== RUN TestIsValidUploadKey/narinfo_key,_nar_type2276=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type2277=== RUN TestIsValidUploadKey/nar_key,_narinfo_type2278=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type2279=== RUN TestIsValidUploadKey/listing_key,_narinfo_type2280=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type2281=== RUN TestIsValidUploadKey/traversal2282=== PAUSE TestIsValidUploadKey/traversal2283=== RUN TestIsValidUploadKey/traversal_nar2284=== PAUSE TestIsValidUploadKey/traversal_nar2285=== RUN TestIsValidUploadKey/absolute2286=== PAUSE TestIsValidUploadKey/absolute2287=== RUN TestIsValidUploadKey/empty_key2288=== PAUSE TestIsValidUploadKey/empty_key2289=== RUN TestIsValidUploadKey/unknown_type2290=== PAUSE TestIsValidUploadKey/unknown_type2291=== CONT TestReadProxyNarinfo22922026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.93ms)22932026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.52ms)22942026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.89ms)22952026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.45ms)22962026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000022972026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.61ms)22982026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.31ms)22992026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000023002026/10/01 09:18:12 OK 1_commit_pending_closure.sql (3.12ms)23012026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.54ms)23022026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.98ms)23032026/10/01 09:18:12 OK 3_commit_push.sql (1.43ms)23042026/10/01 09:18:12 goose: up to current file version: 323052026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.65ms)23062026/10/01 09:18:12 OK 3_commit_push.sql (1.38ms)23072026/10/01 09:18:12 goose: up to current file version: 32308--- PASS: TestReadProxyRangeRequest (0.35s)2309=== CONT TestParseSingleRange2310=== RUN TestParseSingleRange/none2311=== PAUSE TestParseSingleRange/none2312=== RUN TestParseSingleRange/unknown_unit2313=== PAUSE TestParseSingleRange/unknown_unit2314=== RUN TestParseSingleRange/multi-range_ignored2315=== PAUSE TestParseSingleRange/multi-range_ignored2316=== RUN TestParseSingleRange/malformed_no_dash2317=== PAUSE TestParseSingleRange/malformed_no_dash2318=== RUN TestParseSingleRange/malformed_both_empty2319=== PAUSE TestParseSingleRange/malformed_both_empty2320=== RUN TestParseSingleRange/malformed_end_before_start2321=== PAUSE TestParseSingleRange/malformed_end_before_start2322=== RUN TestParseSingleRange/closed2323=== PAUSE TestParseSingleRange/closed2324=== RUN TestParseSingleRange/open-ended2325=== PAUSE TestParseSingleRange/open-ended2326=== RUN TestParseSingleRange/end_clamped_to_size2327=== PAUSE TestParseSingleRange/end_clamped_to_size2328=== RUN TestParseSingleRange/suffix2329=== PAUSE TestParseSingleRange/suffix2330=== RUN TestParseSingleRange/suffix_exceeds_size2331=== PAUSE TestParseSingleRange/suffix_exceeds_size2332=== RUN TestParseSingleRange/single_byte2333=== PAUSE TestParseSingleRange/single_byte2334=== RUN TestParseSingleRange/start_past_EOF2335=== PAUSE TestParseSingleRange/start_past_EOF2336=== RUN TestParseSingleRange/start_far_past_EOF2337=== PAUSE TestParseSingleRange/start_far_past_EOF2338=== CONT TestIsValidCachePath2339=== RUN TestIsValidCachePath/narinfo2340=== PAUSE TestIsValidCachePath/narinfo2341=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2342=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2343=== RUN TestIsValidCachePath/nar_zst2344=== PAUSE TestIsValidCachePath/nar_zst2345=== RUN TestIsValidCachePath/nar_xz2346=== PAUSE TestIsValidCachePath/nar_xz2347=== RUN TestIsValidCachePath/nar_bz22348=== PAUSE TestIsValidCachePath/nar_bz22349=== RUN TestIsValidCachePath/nar_uncompressed2350=== PAUSE TestIsValidCachePath/nar_uncompressed2351=== RUN TestIsValidCachePath/ls2352=== PAUSE TestIsValidCachePath/ls2353=== RUN TestIsValidCachePath/log2354=== PAUSE TestIsValidCachePath/log2355=== RUN TestIsValidCachePath/realisation2356=== PAUSE TestIsValidCachePath/realisation2357=== RUN TestIsValidCachePath/nix-cache-info2358=== PAUSE TestIsValidCachePath/nix-cache-info2359=== RUN TestIsValidCachePath/index.html2360=== PAUSE TestIsValidCachePath/index.html2361=== RUN TestIsValidCachePath/traversal_parent2362=== PAUSE TestIsValidCachePath/traversal_parent2363=== RUN TestIsValidCachePath/traversal_in_middle2364=== PAUSE TestIsValidCachePath/traversal_in_middle2365=== RUN TestIsValidCachePath/invalid_char_e2366=== PAUSE TestIsValidCachePath/invalid_char_e2367=== RUN TestIsValidCachePath/invalid_char_u2368=== PAUSE TestIsValidCachePath/invalid_char_u2369=== RUN TestIsValidCachePath/random_path2370=== PAUSE TestIsValidCachePath/random_path2371=== RUN TestIsValidCachePath/empty2372=== PAUSE TestIsValidCachePath/empty2373=== RUN TestIsValidCachePath/leading_slash2374=== PAUSE TestIsValidCachePath/leading_slash2375=== RUN TestIsValidCachePath/wrong_extension2376=== PAUSE TestIsValidCachePath/wrong_extension2377=== RUN TestIsValidCachePath/short_hash2378=== PAUSE TestIsValidCachePath/short_hash2379=== CONT TestCreatePin_ReservedPins23802026-10-01 09:18:12.417 UTC [1525] ERROR: relation "goose_db_version" does not exist at character 3623812026-10-01 09:18:12.417 UTC [1525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2382--- PASS: TestObjectStatsTrigger (0.36s)2383=== CONT TestGCTaskStore_Fail2384--- PASS: TestGCTaskStore_Fail (0.00s)2385=== CONT TestSkippedUploadsHandler23862026/10/01 09:18:12 INFO Client skipped oversized paths paths=3 nar_bytes=500000000023872026-10-01 09:18:12.428 UTC [1526] ERROR: relation "goose_db_version" does not exist at character 3623882026-10-01 09:18:12.428 UTC [1526] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2389--- PASS: TestSkippedUploadsHandler (0.00s)2390=== CONT TestGCTaskStore_CompletedAllowsNewTask2391--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)2392=== CONT TestGenerateLandingPage2393--- PASS: TestGenerateLandingPage (0.00s)2394=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle23952026/10/01 09:18:12 OK 20241026095416_initial_model.sql (10.67ms)23962026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)23972026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.57ms)2398--- PASS: TestReadRedirectKeepsNarinfoProxied (0.36s)2399=== CONT TestGCTaskStore_PhaseUpdates2400--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)2401=== CONT TestService_readinessHandler24022026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.38ms)24032026/10/01 09:18:12 OK 20241026095416_initial_model.sql (10.21ms)24042026/10/01 09:18:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24052026/10/01 09:18:12 OK 20260905000000_add_claims.sql (8.27ms)24062026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures24072026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (7.04ms)24082026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (1.92ms)24092026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.23ms)24102026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000024112026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.7ms)24122026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.37ms)24132026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.92ms)24142026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.55ms)24152026/10/01 09:18:12 OK 3_commit_push.sql (1.67ms)24162026/10/01 09:18:12 goose: up to current file version: 324172026-10-01 09:18:12.462 UTC [1531] ERROR: relation "goose_db_version" does not exist at character 3624182026-10-01 09:18:12.462 UTC [1531] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24192026/10/01 09:18:12 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTY4OWRlZWEtZDEyNS00ZGJkLTliMmQtMWQwNGQxYTlmZmMxLmUxN2I1YjM3LTdhZmEtNDIwYS1iYWYyLWEwZjc3YjFmZDI2NXgxNzkwODQ2MjkyMTM3MDkzMTc1 parts=1024202026/10/01 09:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24212026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.17ms)24222026/10/01 09:18:12 INFO Completed upload id=124232026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.49ms)24242026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures24252026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.71ms)24262026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000024272026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures24282026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.43ms)24292026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.29ms)24302026/10/01 09:18:12 OK 3_commit_push.sql (1.08ms)24312026/10/01 09:18:12 goose: up to current file version: 324322026/10/01 09:18:12 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo24332026/10/01 09:18:12 WARN Found objects in DB but missing from S3, will re-upload count=12434--- PASS: TestReadProxyDisabled (0.36s)2435=== CONT TestService_healthCheckHandler2436=== CONT TestParseSize2437=== CONT TestGracefulShutdownDrainsInflight2438--- PASS: TestService_verifyS3Integrity (0.81s)2439--- PASS: TestParseSize (0.00s)24402026/10/01 09:18:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24412026/10/01 09:18:12 INFO Starting HTTP server address=127.0.0.1:4042924422026/10/01 09:18:12 INFO Shutdown signal received, draining in-flight requests timeout=10s24432026/10/01 09:18:12 OK 20241026095416_initial_model.sql (10.78ms)24442026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)24452026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.21ms)24462026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)24472026/10/01 09:18:12 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTY4OWRlZWEtZDEyNS00ZGJkLTliMmQtMWQwNGQxYTlmZmMxLmFiYmY4OGRmLTBmZGQtNGEyZi1iNjAzLTI5ZGJlY2IxNmYzN3gxNzkwODQ2MjkyMTU5MTQ0NDcx parts=1024482026/10/01 09:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24492026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.02ms)24502026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.55ms)24512026/10/01 09:18:12 INFO Completed upload id=124522026/10/01 09:18:12 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000024532026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures24542026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.27ms)24552026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000024562026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.46ms)24572026/10/01 09:18:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures24582026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.41ms)2459--- PASS: TestReadRedirectNar (0.40s)2460=== CONT TestGCTaskStore_GetReturnsLatest2461--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)2462=== CONT TestGCTaskStore_GetEmpty2463--- PASS: TestGCTaskStore_GetEmpty (0.00s)2464=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows24652026/10/01 09:18:12 OK 3_commit_push.sql (1.6ms)24662026/10/01 09:18:12 goose: up to current file version: 324672026-10-01 09:18:12.508 UTC [1536] ERROR: relation "goose_db_version" does not exist at character 3624682026-10-01 09:18:12.508 UTC [1536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24692026/10/01 09:18:12 INFO Aborted multipart uploads count=024702026/10/01 09:18:12 WARN mTLS auth: subject not in bound subjects subject="CN=reader"24712026/10/01 09:18:12 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2472--- PASS: TestService_NativeMTLS (0.40s)2473=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check24742026/10/01 09:18:12 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=024752026/10/01 09:18:12 INFO Vacuumed table table=pending_closures24762026-10-01 09:18:12.519 UTC [1539] ERROR: relation "goose_db_version" does not exist at character 3624772026-10-01 09:18:12.519 UTC [1539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24782026/10/01 09:18:12 INFO Vacuumed table table=pending_objects24792026/10/01 09:18:12 INFO Vacuumed table table=multipart_uploads24802026/10/01 09:18:12 OK 20241026095416_initial_model.sql (11.25ms)24812026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)24822026/10/01 09:18:12 INFO Vacuumed table table=closures24832026/10/01 09:18:12 INFO Vacuumed table table=objects24842026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.81ms)24852026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4ms)24862026/10/01 09:18:12 OK 20241026095416_initial_model.sql (17.13ms)24872026/10/01 09:18:12 OK 20260905000000_add_claims.sql (9.6ms)2488--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2489=== CONT TestResolveDBConnectionString/flag_wins2490=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2491=== CONT TestResolveDBConnectionString/missing_file_is_an_error2492=== CONT TestResolveDBConnectionString/file_when_flag_empty2493=== CONT TestResolveDBConnectionString/nothing_configured2494=== CONT TestPush_RejectsBadRequests/no_roots24952026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes2496=== CONT TestPush_RejectsBadRequests/root_not_in_objects24972026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes2498=== CONT TestPush_RejectsBadRequests/bad_root24992026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes2500=== CONT TestPush_RejectsBadRequests/no_objects25012026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)25022026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes2503--- PASS: TestResolveDBConnectionString (0.00s)2504 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2505 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2506 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2507 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2508 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2509=== CONT TestClientErrorHandling/InvalidStorePath2510--- PASS: TestPush_RejectsBadRequests (0.66s)2511 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2512 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2513 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2514 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)25152026/10/01 09:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46549/oidc25162026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.81ms)2517--- PASS: TestMetricsInventory (0.38s)2518=== CONT TestClientErrorHandling/InvalidAuthToken25192026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.9ms)25202026/10/01 09:18:12 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000025212026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.54ms)25222026/10/01 09:18:12 goose: successfully migrated database to version: 202609231200002523--- PASS: TestService_createPendingClosureHandler (0.86s)2524=== CONT TestClientErrorHandling/ServerNotAvailable25252026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.53ms)25262026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)25272026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.41ms)25282026-10-01 09:18:12.554 UTC [1543] ERROR: relation "goose_db_version" does not exist at character 3625292026-10-01 09:18:12.554 UTC [1543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25302026/10/01 09:18:12 OK 3_commit_push.sql (1.41ms)25312026/10/01 09:18:12 goose: up to current file version: 325322026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.73ms)25332026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.55ms)25342026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.13ms)25352026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000025362026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.53ms)25372026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.18ms)25382026/10/01 09:18:12 OK 3_commit_push.sql (1.04ms)25392026/10/01 09:18:12 goose: up to current file version: 325402026/10/01 09:18:12 INFO Received cleanup request method=DELETE path=/api/pending_closures25412026/10/01 09:18:12 INFO Aborted multipart uploads count=125422026/10/01 09:18:12 OK 20241026095416_initial_model.sql (12.9ms)25432026-10-01 09:18:12.575 UTC [1550] ERROR: relation "goose_db_version" does not exist at character 3625442026-10-01 09:18:12.575 UTC [1550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2545--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.38s)2546=== CONT TestCacheConfigHandler/full_config,_no_issuer2547=== CONT TestCacheConfigHandler/no_signing_keys25482026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)2549--- PASS: TestMultipartCleanup (0.48s)2550=== CONT TestCacheConfigHandler/no_cache_url_configured2551=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2552=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure25532026/10/01 09:18:12 INFO Received uploads request method=POST path=/2554--- PASS: TestCacheConfigHandler (0.00s)2555 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2556 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2557 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2558 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2559=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25602026/10/01 09:18:12 INFO Received request for more parts method=POST path=/25612026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.98ms)25622026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.38ms)25632026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.77ms)25642026/10/01 09:18:12 OK 20241026095416_initial_model.sql (8.28ms)25652026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (951.63µs)25662026-10-01 09:18:12.590 UTC [1568] ERROR: relation "goose_db_version" does not exist at character 3625672026-10-01 09:18:12.590 UTC [1568] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25682026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.64ms)25692026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (1.82ms)25702026/10/01 09:18:12 goose: successfully migrated database to version: 202609231200002571=== NAME TestNARDeduplicationMetadataUploadBug2572 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3022805504/001/store/3mwgc928hhlgv0hpb2mld3fcp6i0b8w7-file1.txt25732026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.1ms)25742026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.37ms)25752026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.32ms)25762026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.49ms)25772026/10/01 09:18:12 OK 3_commit_push.sql (1.58ms)25782026/10/01 09:18:12 goose: up to current file version: 32579--- PASS: TestReadProxyConditionalGet (0.40s)2580=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25812026/10/01 09:18:12 INFO Received complete multipart upload request method=POST path=/25822026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.29ms)25832026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.27ms)25842026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (2.21ms)25852026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000025862026/10/01 09:18:12 OK 1_commit_pending_closure.sql (10.32ms)25872026/10/01 09:18:12 OK 20241026095416_initial_model.sql (19.39ms)25882026/10/01 09:18:12 OK 2_object_stats_trigger.sql (1.58ms)25892026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)25902026/10/01 09:18:12 OK 3_commit_push.sql (1.17ms)25912026/10/01 09:18:12 goose: up to current file version: 32592--- PASS: TestReadProxyHead (0.39s)2593=== CONT TestServerTLSConfig/no_client_CA2594=== CONT TestServerTLSConfig/not_a_PEM_file2595=== CONT TestServerTLSConfig/missing_CA_file2596--- PASS: TestServerTLSConfig (0.00s)2597 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2598 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2599 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2600=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token26012026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.67ms)26022026/10/01 09:18:12 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/present2603=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26042026/10/01 09:18:12 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]2605=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26062026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (4.94ms)26072026/10/01 09:18:12 WARN Authentication failed token_preview=eyJhbGciOi...AAkzd2E0gg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2608=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2609=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info26102026/10/01 09:18:12 INFO Received uploads request method=POST path=/2611=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26122026/10/01 09:18:12 INFO Received complete multipart upload request method=POST path=/2613=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26142026/10/01 09:18:12 INFO Received request for more parts method=POST path=/2615=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal26162026/10/01 09:18:12 INFO Received uploads request method=POST path=/2617--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2618 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2619 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2620 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2621 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2622=== CONT TestProxyWriteTimeout/narinfo2623=== CONT TestProxyWriteTimeout/unknown_size2624=== CONT TestProxyWriteTimeout/10_GiB_nar2625=== CONT TestProxyWriteTimeout/1_GiB_nar2626--- PASS: TestService_AuthMiddleware_OIDC (0.50s)2627 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2628 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2629 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2630 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2631=== CONT TestService_RequireScope_OIDC/builder_may_write2632--- PASS: TestProxyWriteTimeout (0.00s)2633 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2634 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2635 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2636 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2637=== CONT TestService_RequireScope_OIDC/static_token_may_admin2638=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2639=== CONT TestService_RequireScope_OIDC/writer_implies_read2640=== CONT TestService_RequireScope_OIDC/reader_may_read2641=== CONT TestService_RequireScope_OIDC/static_token_may_write2642=== CONT TestService_RequireScope_OIDC/ops_may_not_write26432026/10/01 09:18:12 OK 20260905000000_add_claims.sql (4.14ms)2644=== CONT TestService_RequireScope_OIDC/reader_may_not_write2645=== CONT TestService_RequireScope_OIDC/ops_may_admin2646=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2647=== CONT TestIsValidUploadKey/narinfo2648=== CONT TestIsValidUploadKey/listing_key,_narinfo_type26492026-10-01 09:18:12.638 UTC [1621] ERROR: relation "goose_db_version" does not exist at character 3626502026-10-01 09:18:12.638 UTC [1621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26512026-10-01 09:18:12.638 UTC [1622] ERROR: relation "goose_db_version" does not exist at character 3626522026-10-01 09:18:12.638 UTC [1622] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2653=== CONT TestIsValidUploadKey/traversal26542026-10-01 09:18:12.638 UTC [1620] ERROR: relation "goose_db_version" does not exist at character 3626552026-10-01 09:18:12.638 UTC [1620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2656=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2657=== CONT TestIsValidUploadKey/index.html2658=== CONT TestIsValidUploadKey/nix-cache-info2659=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2660=== CONT TestIsValidUploadKey/realisation2661--- PASS: TestService_RequireScope_OIDC (0.66s)2662 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2663 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2664 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2665 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2666 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2667 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2668 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2669 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2670 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2671 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.01s)2672=== CONT TestIsValidUploadKey/realisation_plus_in_output2673=== CONT TestIsValidUploadKey/build_log_question_mark2674=== CONT TestIsValidUploadKey/build_log_plus_in_name2675=== CONT TestIsValidUploadKey/build_log_equals2676=== CONT TestIsValidUploadKey/traversal_nar2677=== CONT TestIsValidUploadKey/build_log_home-manager_file2678=== CONT TestIsValidUploadKey/build_log2679=== CONT TestIsValidUploadKey/nar_plain2680=== CONT TestIsValidUploadKey/listing2681=== CONT TestIsValidUploadKey/nar_zst2682=== CONT TestIsValidUploadKey/nar_xz2683=== CONT TestIsValidUploadKey/empty_key2684=== CONT TestIsValidUploadKey/absolute2685=== CONT TestIsValidUploadKey/unknown_type2686=== CONT TestParseSingleRange/single_byte2687=== CONT TestParseSingleRange/none2688=== CONT TestParseSingleRange/suffix2689=== CONT TestParseSingleRange/end_clamped_to_size2690=== CONT TestParseSingleRange/open-ended2691=== CONT TestParseSingleRange/closed2692=== CONT TestParseSingleRange/malformed_end_before_start2693--- PASS: TestIsValidUploadKey (0.00s)2694 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2695 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2696 --- PASS: TestIsValidUploadKey/traversal (0.00s)2697 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2698 --- PASS: TestIsValidUploadKey/index.html (0.00s)2699 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2700 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2701 --- PASS: TestIsValidUploadKey/realisation (0.00s)2702 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2703 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2704 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2705 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2706 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2707 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2708 --- PASS: TestIsValidUploadKey/build_log (0.00s)2709 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2710 --- PASS: TestIsValidUploadKey/listing (0.00s)2711 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2712 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2713 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2714 --- PASS: TestIsValidUploadKey/absolute (0.00s)2715 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2716=== CONT TestParseSingleRange/suffix_exceeds_size2717=== CONT TestParseSingleRange/malformed_no_dash2718=== CONT TestParseSingleRange/malformed_both_empty2719=== CONT TestParseSingleRange/unknown_unit2720=== CONT TestParseSingleRange/multi-range_ignored2721=== CONT TestParseSingleRange/start_past_EOF2722=== CONT TestParseSingleRange/start_far_past_EOF2723--- PASS: TestParseSingleRange (0.00s)2724 --- PASS: TestParseSingleRange/single_byte (0.00s)2725 --- PASS: TestParseSingleRange/none (0.00s)2726 --- PASS: TestParseSingleRange/suffix (0.00s)2727 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2728 --- PASS: TestParseSingleRange/open-ended (0.00s)2729 --- PASS: TestParseSingleRange/closed (0.00s)2730 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2731 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2732 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2733 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2734 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2735 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2736 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2737 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2738=== CONT TestIsValidCachePath/random_path2739=== CONT TestIsValidCachePath/invalid_char_u2740=== CONT TestIsValidCachePath/invalid_char_e2741=== CONT TestIsValidCachePath/narinfo2742=== CONT TestIsValidCachePath/traversal_in_middle2743=== CONT TestIsValidCachePath/index.html2744=== CONT TestIsValidCachePath/nix-cache-info2745=== CONT TestIsValidCachePath/empty2746=== CONT TestIsValidCachePath/realisation2747=== CONT TestIsValidCachePath/traversal_parent2748=== CONT TestIsValidCachePath/ls2749=== CONT TestIsValidCachePath/nar_uncompressed2750=== CONT TestIsValidCachePath/nar_bz22751=== CONT TestIsValidCachePath/nar_xz2752=== CONT TestIsValidCachePath/nar_zst2753=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2754=== CONT TestIsValidCachePath/log2755=== CONT TestIsValidCachePath/wrong_extension2756=== CONT TestIsValidCachePath/leading_slash2757=== CONT TestIsValidCachePath/short_hash2758--- PASS: TestIsValidCachePath (0.00s)2759 --- PASS: TestIsValidCachePath/random_path (0.00s)2760 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2761 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2762 --- PASS: TestIsValidCachePath/narinfo (0.00s)2763 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2764 --- PASS: TestIsValidCachePath/index.html (0.00s)2765 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2766 --- PASS: TestIsValidCachePath/empty (0.00s)2767 --- PASS: TestIsValidCachePath/realisation (0.00s)2768 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2769 --- PASS: TestIsValidCachePath/ls (0.00s)2770 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2771 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2772 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2773 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2774 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2775 --- PASS: TestIsValidCachePath/log (0.00s)2776 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2777 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2778 --- PASS: TestIsValidCachePath/short_hash (0.00s)27792026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (9.76ms)27802026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (3.68ms)27812026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000027822026/10/01 09:18:12 OK 1_commit_pending_closure.sql (3.32ms)27832026/10/01 09:18:12 OK 2_object_stats_trigger.sql (8.05ms)27842026/10/01 09:18:12 OK 20241026095416_initial_model.sql (10.55ms)27852026/10/01 09:18:12 OK 20241026095416_initial_model.sql (10.87ms)27862026/10/01 09:18:12 OK 3_commit_push.sql (1.57ms)27872026/10/01 09:18:12 goose: up to current file version: 32788--- PASS: TestReadProxyInvalidPath (0.41s)27892026/10/01 09:18:12 OK 20241026095416_initial_model.sql (12.31ms)27902026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)27912026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)27922026/10/01 09:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)27932026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.33ms)27942026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.69ms)27952026/10/01 09:18:12 OK 20251218171726_add_pins.sql (3.14ms)27962026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)27972026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)27982026/10/01 09:18:12 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)27992026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.11ms)28002026/10/01 09:18:12 OK 20260905000000_add_claims.sql (3.22ms)28012026/10/01 09:18:12 OK 20260905000000_add_claims.sql (2.98ms)28022026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (1.71ms)28032026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes28042026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.07ms)28052026/10/01 09:18:12 OK 20260920000000_drop_claims.sql (2.07ms)28062026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (1.77ms)28072026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000028082026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (1.7ms)28092026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000028102026/10/01 09:18:12 OK 20260923120000_add_pushes.sql (1.83ms)28112026/10/01 09:18:12 goose: successfully migrated database to version: 2026092312000028122026/10/01 09:18:12 OK 1_commit_pending_closure.sql (1.99ms)28132026/10/01 09:18:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28142026/10/01 09:18:12 OK 1_commit_pending_closure.sql (1.57ms)28152026/10/01 09:18:12 INFO Uploading 3mwgc928hhlgv0hpb2mld3fcp6i0b8w7-file1.txt (160B)28162026/10/01 09:18:12 OK 2_object_stats_trigger.sql (854.27µs)28172026/10/01 09:18:12 OK 2_object_stats_trigger.sql (935.29µs)28182026/10/01 09:18:12 OK 1_commit_pending_closure.sql (2.14ms)2819--- PASS: TestReadProxy404 (0.40s)28202026/10/01 09:18:12 OK 3_commit_push.sql (860.63µs)28212026/10/01 09:18:12 goose: up to current file version: 328222026/10/01 09:18:12 OK 3_commit_push.sql (903.97µs)28232026/10/01 09:18:12 goose: up to current file version: 328242026/10/01 09:18:12 OK 2_object_stats_trigger.sql (928.35µs)28252026/10/01 09:18:12 OK 3_commit_push.sql (834.13µs)28262026/10/01 09:18:12 goose: up to current file version: 328272026/10/01 09:18:12 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"28282026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28292026/10/01 09:18:12 WARN Failed to register uploaded object key=3mwgc928hhlgv0hpb2mld3fcp6i0b8w7.ls error="server returned 404: 404 page not found\n"28302026/10/01 09:18:12 INFO Signed narinfos id=1 count=128312026/10/01 09:18:12 INFO Uploading 1 narinfos28322026/10/01 09:18:12 WARN Failed to register uploaded object key=3mwgc928hhlgv0hpb2mld3fcp6i0b8w7.narinfo error="server returned 404: 404 page not found\n"28332026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/1/complete28342026/10/01 09:18:12 INFO Upload complete. (63ms)2835=== NAME TestNARDeduplicationMetadataUploadBug2836 metadata_upload_test.go:54: Retrieved narinfo from S3:2837 StorePath: /build/TestNARDeduplicationMetadataUploadBug3022805504/001/store/3mwgc928hhlgv0hpb2mld3fcp6i0b8w7-file1.txt2838 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2839 Compression: zstd2840 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2841 NarSize: 1602842 References: 2843 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2844 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2845 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2846 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2847=== NAME TestOrphanedObjectsGC2848 orphaned_objects_gc_test.go:290: GC Test Summary:2849 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2850 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2851 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2852 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2853 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2854--- PASS: TestOrphanedObjectsGC (0.68s)2855--- PASS: TestReadProxyNarStreaming (0.42s)2856--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.37s)28572026/10/01 09:18:12 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.89651ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28582026/10/01 09:18:12 INFO Starting HTTP server address=127.0.0.1:3938528592026/10/01 09:18:12 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket1990708800/001/proxy.sock28602026/10/01 09:18:12 WARN mTLS auth: subject not in bound subjects subject="CN=someone"28612026/10/01 09:18:12 INFO Shutdown signal received, draining in-flight requests timeout=10s2862--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.36s)2863=== NAME TestNARDeduplicationMetadataUploadBug2864 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3022805504/001/store/q51njljdan7ss2nlxb9j9bdjgpf8g613-file2.txt2865--- PASS: TestReadProxyNarinfo (0.37s)28662026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures28672026/10/01 09:18:12 WARN readiness check failed error="closed pool"2868--- PASS: TestService_readinessHandler (0.34s)2869--- PASS: TestService_healthCheckHandler (0.32s)28702026/10/01 09:18:12 INFO Received push request method=POST path=/api/pushes28712026/10/01 09:18:12 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)28722026/10/01 09:18:12 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign28732026/10/01 09:18:12 INFO Signed narinfos id=2 count=128742026/10/01 09:18:12 WARN Failed to register uploaded object key=q51njljdan7ss2nlxb9j9bdjgpf8g613.ls error="server returned 404: 404 page not found\n"28752026/10/01 09:18:12 INFO Uploading 1 narinfos28762026/10/01 09:18:12 INFO Received complete push request method=POST path=/api/pushes/2/complete28772026/10/01 09:18:12 WARN Failed to register uploaded object key=q51njljdan7ss2nlxb9j9bdjgpf8g613.narinfo error="server returned 404: 404 page not found\n"28782026/10/01 09:18:12 INFO Upload complete. (48ms)2879=== NAME TestNARDeduplicationMetadataUploadBug2880 metadata_upload_test.go:76: Retrieved narinfo from S3:2881 StorePath: /build/TestNARDeduplicationMetadataUploadBug3022805504/001/store/q51njljdan7ss2nlxb9j9bdjgpf8g613-file2.txt2882 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2883 Compression: zstd2884 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2885 NarSize: 1602886 References: 2887 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2888 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2889 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2890 {"version":1,"root":{"type":"regular","size":44}}2891--- PASS: TestNARDeduplicationMetadataUploadBug (0.62s)28922026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures28932026/10/01 09:18:12 INFO Aborted multipart uploads count=028942026/10/01 09:18:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete28952026/10/01 09:18:12 WARN Force mode enabled - objects will be deleted immediately without grace period28962026/10/01 09:18:12 INFO Received uploads request method=POST path=/api/pending_closures28972026/10/01 09:18:12 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=028982026/10/01 09:18:12 INFO Vacuumed table table=pending_closures28992026/10/01 09:18:12 INFO Vacuumed table table=pending_objects29002026/10/01 09:18:12 INFO Vacuumed table table=multipart_uploads29012026/10/01 09:18:12 INFO Vacuumed table table=closures29022026/10/01 09:18:12 INFO Vacuumed table table=objects29032026/10/01 09:18:12 INFO Aborted multipart uploads count=029042026/10/01 09:18:12 WARN Force mode enabled - objects will be deleted immediately without grace period29052026/10/01 09:18:12 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=029062026/10/01 09:18:12 INFO Vacuumed table table=pending_closures29072026/10/01 09:18:12 INFO Vacuumed table table=pending_objects29082026/10/01 09:18:12 INFO Vacuumed table table=multipart_uploads29092026/10/01 09:18:12 INFO Vacuumed table table=closures29102026/10/01 09:18:12 INFO Vacuumed table table=objects2911--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2912 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.36s)2913 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.35s)29142026/10/01 09:18:12 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux29152026/10/01 09:18:12 WARN Refused reserved pin name=worker-x86_64-linux29162026/10/01 09:18:12 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux29172026/10/01 09:18:12 INFO Received create pin request method=POST path=/api/pins/my-app29182026/10/01 09:18:12 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2919--- PASS: TestCreatePin_ReservedPins (0.47s)29202026/10/01 09:18:12 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=413.489134ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29212026/10/01 09:18:12 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29222026/10/01 09:18:12 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29232026/10/01 09:18:13 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=820.856802ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2924=== NAME TestOrphanedObjectsGCStressTest2925 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2926 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2927--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2928 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)2929 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2930 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.99s)2931=== NAME TestOrphanedObjectsGCStressTest2932 orphaned_objects_gc_test.go:509: Stress test completed successfully:2933 orphaned_objects_gc_test.go:510: - Active objects preserved: 202934 orphaned_objects_gc_test.go:511: - Objects deleted: 2102935 orphaned_objects_gc_test.go:512: - Total GC'd: 2102936--- PASS: TestOrphanedObjectsGCStressTest (1.73s)29372026/10/01 09:18:14 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.74954216s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29382026/10/01 09:18:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=029392026/10/01 09:18:14 INFO Received create pin request method=POST path=/api/pins/myapp29402026/10/01 09:18:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=029412026/10/01 09:18:14 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC33165818/001/store/d8y8h639qkryaa6zan78jq93lbrpqz13-pinned-file.txt narinfo_key=d8y8h639qkryaa6zan78jq93lbrpqz13.narinfo2942=== NAME TestClientIntegration2943 client_integration_test.go:323: Objects in database after GC:2944 client_integration_test.go:323: Successfully deleted all objects with GC --force29452026/10/01 09:18:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures29462026/10/01 09:18:14 INFO Garbage collection started2947--- PASS: TestClientIntegration (2.63s)29482026/10/01 09:18:14 INFO Aborted multipart uploads count=029492026/10/01 09:18:14 WARN Force mode enabled - objects will be deleted immediately without grace period29502026/10/01 09:18:14 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=029512026/10/01 09:18:14 INFO Vacuumed table table=pending_closures29522026/10/01 09:18:14 INFO Vacuumed table table=pending_objects29532026/10/01 09:18:14 INFO Vacuumed table table=multipart_uploads29542026/10/01 09:18:14 INFO Vacuumed table table=closures29552026/10/01 09:18:14 INFO Vacuumed table table=objects29562026/10/01 09:18:15 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-config29572026/10/01 09:18:16 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.183982ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2958=== NAME TestPinProtectsFromGC2959 client_integration_test.go:840: Pin successfully protected closure from garbage collection2960--- PASS: TestPinProtectsFromGC (4.79s)29612026/10/01 09:18:16 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=435.56177ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29622026/10/01 09:18:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=836.374973ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29632026/10/01 09:18:16 WARN Rate limiter enabled after throttle name=s3-test rate=529642026/10/01 09:18:16 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2965=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2966 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102967 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002968--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.33s)29692026/10/01 09:18:17 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.451271515s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29702026/10/01 09:18:19 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"29712026/10/01 09:18:19 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-config29722026/10/01 09:18:19 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.269191ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29732026/10/01 09:18:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=405.386488ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29742026/10/01 09:18:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=742.038247ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29752026/10/01 09:18:20 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.758696233s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29762026/10/01 09:18:22 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_closures29772026/10/01 09:18:22 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=206.230231ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29782026/10/01 09:18:22 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=360.609725ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29792026/10/01 09:18:22 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=765.176859ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29802026/10/01 09:18:23 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.504902484s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2981--- PASS: TestClientErrorHandling (0.00s)2982 --- PASS: TestClientErrorHandling/InvalidStorePath (0.34s)2983 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.44s)2984 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.59s)2985PASS2986{"timestamp":"2026-10-01T09:18:25.145883496Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:37300","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(195)"}29872026-10-01 09:18:25.365 UTC [128] LOG: received smart shutdown request29882026-10-01 09:18:25.369 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 129892026-10-01 09:18:25.380 UTC [133] LOG: shutting down29902026-10-01 09:18:25.380 UTC [133] LOG: checkpoint starting: shutdown immediate29912026-10-01 09:18:25.891 UTC [133] LOG: checkpoint complete: wrote 10998 buffers (67.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 23 recycled; write=0.180 s, sync=0.312 s, total=0.512 s; sync files=26968, longest=0.005 s, average=0.001 s; distance=373716 kB, estimate=373716 kB; lsn=0/1845B068, redo lsn=0/1845B06829922026-10-01 09:18:25.960 UTC [128] LOG: database system is shut down2993Running OIDC tests...2994=== RUN TestAudienceForIssuer2995=== PAUSE TestAudienceForIssuer2996=== RUN TestGlobMatch2997=== PAUSE TestGlobMatch2998=== RUN TestValidateToken_ValidToken2999=== PAUSE TestValidateToken_ValidToken3000=== RUN TestValidateToken_WrongAudience3001=== PAUSE TestValidateToken_WrongAudience3002=== RUN TestValidateToken_Expired3003=== PAUSE TestValidateToken_Expired3004=== RUN TestValidateToken_BoundClaimsMismatch3005=== PAUSE TestValidateToken_BoundClaimsMismatch3006=== RUN TestValidateToken_BoundSubjectMismatch3007=== PAUSE TestValidateToken_BoundSubjectMismatch3008=== RUN TestValidateToken_MultipleProviders3009=== PAUSE TestValidateToken_MultipleProviders3010=== RUN TestValidateToken_NoMatchingProvider3011=== PAUSE TestValidateToken_NoMatchingProvider3012=== RUN TestValidateToken_KubernetesServiceAccount3013=== PAUSE TestValidateToken_KubernetesServiceAccount3014=== RUN TestNewValidator_KubernetesRequiresCA3015=== PAUSE TestNewValidator_KubernetesRequiresCA3016=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3017=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3018=== RUN TestPins_ReservedForMatchingRule3019=== PAUSE TestPins_ReservedForMatchingRule3020=== RUN TestPins_TopLevelShorthand3021=== PAUSE TestPins_TopLevelShorthand3022=== RUN TestPins_ConfigValidation3023=== PAUSE TestPins_ConfigValidation3024=== RUN TestScopes_LegacyProviderDefaultsToWrite3025=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3026=== RUN TestScopes_Rules3027=== PAUSE TestScopes_Rules3028=== RUN TestScopes_ConfigValidation3029=== PAUSE TestScopes_ConfigValidation3030=== CONT TestAudienceForIssuer3031=== CONT TestValidateToken_KubernetesServiceAccount3032=== CONT TestValidateToken_NoMatchingProvider3033=== CONT TestPins_ConfigValidation3034=== CONT TestPins_ReservedForMatchingRule3035=== CONT TestValidateToken_Expired3036=== CONT TestValidateToken_BoundSubjectMismatch3037=== CONT TestValidateToken_ValidToken3038=== CONT TestValidateToken_MultipleProviders3039=== CONT TestScopes_Rules3040=== CONT TestScopes_ConfigValidation3041=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3042=== CONT TestValidateToken_WrongAudience3043=== CONT TestNewValidator_KubernetesRequiresCA3044=== CONT TestPins_TopLevelShorthand3045=== CONT TestScopes_LegacyProviderDefaultsToWrite3046=== CONT TestGlobMatch3047--- PASS: TestAudienceForIssuer (0.00s)3048--- PASS: TestPins_ConfigValidation (0.00s)3049--- PASS: TestScopes_ConfigValidation (0.00s)3050=== RUN TestGlobMatch/foo_foo3051=== CONT TestValidateToken_BoundClaimsMismatch3052=== PAUSE TestGlobMatch/foo_foo3053=== RUN TestGlobMatch/foo_bar3054=== PAUSE TestGlobMatch/foo_bar3055=== RUN TestGlobMatch/*_3056=== PAUSE TestGlobMatch/*_3057=== RUN TestGlobMatch/*_anything3058=== PAUSE TestGlobMatch/*_anything3059=== RUN TestGlobMatch/foo*_foo3060=== PAUSE TestGlobMatch/foo*_foo3061=== RUN TestGlobMatch/foo*_foobar3062=== PAUSE TestGlobMatch/foo*_foobar3063=== RUN TestGlobMatch/foo*_bar3064=== PAUSE TestGlobMatch/foo*_bar3065=== RUN TestGlobMatch/*bar_bar3066=== PAUSE TestGlobMatch/*bar_bar3067=== RUN TestGlobMatch/*bar_foobar3068=== PAUSE TestGlobMatch/*bar_foobar3069=== RUN TestGlobMatch/*bar_foo3070=== PAUSE TestGlobMatch/*bar_foo3071=== RUN TestGlobMatch/foo*bar_foobar3072=== PAUSE TestGlobMatch/foo*bar_foobar3073=== RUN TestGlobMatch/foo*bar_foo123bar3074=== PAUSE TestGlobMatch/foo*bar_foo123bar3075=== RUN TestGlobMatch/foo*bar_foobarbaz3076=== PAUSE TestGlobMatch/foo*bar_foobarbaz3077=== RUN TestGlobMatch/*/*_foo/bar3078=== PAUSE TestGlobMatch/*/*_foo/bar3079=== RUN TestGlobMatch/*/*_foo3080=== PAUSE TestGlobMatch/*/*_foo3081=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3082=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3083=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03084=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03085=== RUN TestGlobMatch/refs/*/main_refs/heads/main3086=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3087=== RUN TestGlobMatch/fo?_foo3088=== PAUSE TestGlobMatch/fo?_foo3089=== RUN TestGlobMatch/fo?_fo3090=== PAUSE TestGlobMatch/fo?_fo3091=== RUN TestGlobMatch/fo?_fooo3092=== PAUSE TestGlobMatch/fo?_fooo3093=== RUN TestGlobMatch/?oo_foo3094=== PAUSE TestGlobMatch/?oo_foo3095=== RUN TestGlobMatch/?oo_boo3096=== PAUSE TestGlobMatch/?oo_boo3097=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3098=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3099=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3100=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3101=== CONT TestGlobMatch/foo_foo3102=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3103=== CONT TestGlobMatch/?oo_boo3104=== CONT TestGlobMatch/?oo_foo3105=== CONT TestGlobMatch/fo?_fooo3106=== CONT TestGlobMatch/fo?_fo3107=== CONT TestGlobMatch/fo?_foo3108=== CONT TestGlobMatch/refs/*/main_refs/heads/main3109=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03110=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3111=== CONT TestGlobMatch/*/*_foo3112=== CONT TestGlobMatch/foo*bar_foo123bar3113=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3114=== CONT TestGlobMatch/*bar_foo3115=== CONT TestGlobMatch/foo*bar_foobar3116=== CONT TestGlobMatch/*bar_foobar3117=== CONT TestGlobMatch/*bar_bar3118=== CONT TestGlobMatch/*/*_foo/bar3119=== CONT TestGlobMatch/foo*bar_foobarbaz3120=== CONT TestGlobMatch/foo*_bar3121=== CONT TestGlobMatch/foo*_foobar3122=== CONT TestGlobMatch/foo*_foo3123=== CONT TestGlobMatch/*_anything3124=== CONT TestGlobMatch/*_3125=== CONT TestGlobMatch/foo_bar3126--- PASS: TestGlobMatch (0.00s)3127 --- PASS: TestGlobMatch/foo_foo (0.00s)3128 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3129 --- PASS: TestGlobMatch/?oo_boo (0.00s)3130 --- PASS: TestGlobMatch/?oo_foo (0.00s)3131 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3132 --- PASS: TestGlobMatch/fo?_fo (0.00s)3133 --- PASS: TestGlobMatch/fo?_foo (0.00s)3134 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3135 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3136 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3137 --- PASS: TestGlobMatch/*/*_foo (0.00s)3138 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3139 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3140 --- PASS: TestGlobMatch/*bar_foo (0.00s)3141 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3142 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3143 --- PASS: TestGlobMatch/*bar_bar (0.00s)3144 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3145 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3146 --- PASS: TestGlobMatch/foo*_bar (0.00s)3147 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3148 --- PASS: TestGlobMatch/foo*_foo (0.00s)3149 --- PASS: TestGlobMatch/*_anything (0.00s)3150 --- PASS: TestGlobMatch/*_ (0.00s)3151 --- PASS: TestGlobMatch/foo_bar (0.00s)31522026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46715/oidc31532026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33171/oidc31542026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35599/oidc3155--- PASS: TestValidateToken_Expired (0.07s)31562026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41309/oidc3157--- PASS: TestPins_TopLevelShorthand (0.07s)3158--- PASS: TestValidateToken_WrongAudience (0.08s)3159--- PASS: TestPins_ReservedForMatchingRule (0.08s)31602026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43921/oidc3161--- PASS: TestValidateToken_ValidToken (0.09s)31622026/10/01 09:18:27 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40321/oidc3163--- PASS: TestValidateToken_NoMatchingProvider (0.10s)31642026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33973/oidc3165--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)31662026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46497/oidc3167--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.13s)31682026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38675/oidc31692026/10/01 09:18:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43387/oidc3170--- PASS: TestScopes_Rules (0.15s)3171--- PASS: TestValidateToken_BoundSubjectMismatch (0.15s)31722026/10/01 09:18:27 http: TLS handshake error from 127.0.0.1:51866: remote error: tls: bad certificate3173--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)31742026/10/01 09:18:27 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233175--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.23s)31762026/10/01 09:18:27 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:455973177--- PASS: TestValidateToken_KubernetesServiceAccount (0.26s)31782026/10/01 09:18:27 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:34577/oidc31792026/10/01 09:18:27 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:38421/oidc3180--- PASS: TestValidateToken_MultipleProviders (0.29s)3181PASS3182Running hook tests...3183=== RUN TestSendPathsEmpty3184=== PAUSE TestSendPathsEmpty3185=== RUN TestQueueEnqueueAndFetch3186=== PAUSE TestQueueEnqueueAndFetch3187=== RUN TestQueueDeduplication3188=== PAUSE TestQueueDeduplication3189=== RUN TestQueueRemove3190=== PAUSE TestQueueRemove3191=== RUN TestQueueFetchBatchLimit3192=== PAUSE TestQueueFetchBatchLimit3193=== RUN TestQueueRetryMovesToBack3194=== PAUSE TestQueueRetryMovesToBack3195=== RUN TestQueueFetchRemoveLifecycle3196=== PAUSE TestQueueFetchRemoveLifecycle3197=== RUN TestQueueConcurrentWriters3198=== PAUSE TestQueueConcurrentWriters3199=== RUN TestQueueRemoveLargeClosure3200=== PAUSE TestQueueRemoveLargeClosure3201=== RUN TestServerClientIntegration3202=== PAUSE TestServerClientIntegration3203=== RUN TestServerQueueError3204=== PAUSE TestServerQueueError3205=== RUN TestGetListenerSocketActivation3206 server_test.go:210: === RUN TestGetListenerSocketActivation3207 --- PASS: TestGetListenerSocketActivation (0.00s)3208 PASS3209 3210--- PASS: TestGetListenerSocketActivation (0.01s)3211=== RUN TestDrainIsolatesPoisonPath3212=== PAUSE TestDrainIsolatesPoisonPath3213=== RUN TestRunNotBlockedByPoisonHead3214=== PAUSE TestRunNotBlockedByPoisonHead3215=== RUN TestDrainGivesUpWhenServerDown3216=== PAUSE TestDrainGivesUpWhenServerDown3217=== RUN TestFailedPathPrunedByLaterClosure3218=== PAUSE TestFailedPathPrunedByLaterClosure3219=== RUN TestWorkerUploadsAndRemoves3220=== PAUSE TestWorkerUploadsAndRemoves3221=== RUN TestWorkerSkipsGCdPaths3222=== PAUSE TestWorkerSkipsGCdPaths3223=== RUN TestWorkerPrunesClosureDeps3224=== PAUSE TestWorkerPrunesClosureDeps3225=== RUN TestDrainTimeout3226=== PAUSE TestDrainTimeout3227=== CONT TestSendPathsEmpty3228=== CONT TestDrainIsolatesPoisonPath3229=== CONT TestQueueFetchBatchLimit3230--- PASS: TestSendPathsEmpty (0.00s)3231=== CONT TestServerQueueError3232=== CONT TestWorkerUploadsAndRemoves3233=== CONT TestDrainTimeout3234=== CONT TestServerClientIntegration3235=== CONT TestWorkerPrunesClosureDeps3236=== CONT TestQueueRemoveLargeClosure3237=== CONT TestQueueConcurrentWriters3238=== CONT TestWorkerSkipsGCdPaths32392026/10/01 09:18:27 ERROR Failed to queue paths error="permission denied" count=13240=== CONT TestQueueRemove3241--- PASS: TestServerQueueError (0.00s)3242=== CONT TestQueueDeduplication3243=== CONT TestQueueFetchRemoveLifecycle3244=== CONT TestQueueEnqueueAndFetch3245=== CONT TestDrainGivesUpWhenServerDown3246--- PASS: TestServerClientIntegration (0.00s)3247=== CONT TestQueueRetryMovesToBack3248=== CONT TestFailedPathPrunedByLaterClosure3249=== CONT TestRunNotBlockedByPoisonHead32502026/10/01 09:18:27 INFO Upload queue status pending=232512026/10/01 09:18:27 INFO Uploading batch count=432522026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=432532026/10/01 09:18:27 INFO Upload queue status pending=23254--- PASS: TestQueueEnqueueAndFetch (0.01s)32552026/10/01 09:18:27 INFO Uploading batch count=23256--- PASS: TestQueueRetryMovesToBack (0.01s)32572026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1250054649/002/bbb3258--- PASS: TestQueueRemove (0.01s)32592026/10/01 09:18:27 INFO Upload queue status pending=332602026/10/01 09:18:27 INFO Uploading batch count=232612026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=232622026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2190723916/002/a32632026/10/01 09:18:27 INFO Uploading batch count=132642026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132652026/10/01 09:18:27 INFO Uploading batch count=132662026/10/01 09:18:27 INFO Uploading batch count=13267--- PASS: TestQueueFetchBatchLimit (0.01s)32682026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132692026/10/01 09:18:27 INFO Uploading batch count=232702026/10/01 09:18:27 INFO Upload queue status pending=232712026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2190723916/002/b32722026/10/01 09:18:27 INFO Uploading batch count=132732026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132742026/10/01 09:18:27 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths460339988/002/nonexistent3275--- PASS: TestQueueDeduplication (0.01s)32762026/10/01 09:18:27 INFO Uploading batch count=232772026/10/01 09:18:27 INFO Uploading batch count=132782026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=232792026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2190723916/002/c3280--- PASS: TestQueueFetchRemoveLifecycle (0.01s)32812026/10/01 09:18:27 INFO Uploading batch count=132822026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132832026/10/01 09:18:27 INFO Uploading batch count=132842026/10/01 09:18:27 INFO Uploading batch count=132852026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132862026/10/01 09:18:27 INFO Uploading batch count=132872026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2190723916/002/d32882026/10/01 09:18:27 ERROR Drain finished with paths left in queue remaining=132892026/10/01 09:18:27 INFO Uploading batch count=232902026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=232912026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2190723916/002/e32922026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2190723916/002/f3293--- PASS: TestDrainIsolatesPoisonPath (0.02s)32942026/10/01 09:18:27 ERROR Drain finished with paths left in queue remaining=103295--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)3296--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3297--- PASS: TestWorkerPrunesClosureDeps (0.03s)3298--- PASS: TestWorkerUploadsAndRemoves (0.03s)3299--- PASS: TestWorkerSkipsGCdPaths (0.04s)3300--- PASS: TestQueueRemoveLargeClosure (0.14s)3301--- PASS: TestQueueConcurrentWriters (0.20s)33022026/10/01 09:18:27 ERROR Upload failed error="context deadline exceeded" count=233032026/10/01 09:18:27 ERROR Drain finished with paths left in queue remaining=43304--- PASS: TestDrainTimeout (0.21s)33052026/10/01 09:18:28 INFO Uploading batch count=133062026/10/01 09:18:28 INFO Uploading batch count=133072026/10/01 09:18:28 INFO Uploading batch count=133082026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133092026/10/01 09:18:28 INFO Uploading batch count=133102026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133112026/10/01 09:18:28 INFO Uploading batch count=133122026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133132026/10/01 09:18:28 INFO Uploading batch count=133142026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133152026/10/01 09:18:28 ERROR Drain finished with paths left in queue remaining=13316--- PASS: TestRunNotBlockedByPoisonHead (1.02s)3317PASS