niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #337
· 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 TestDoServerRequestAttachesToken96=== CONT TestScriptTokenEmptyCommand97--- PASS: TestScriptTokenEmptyCommand (0.00s)98=== CONT TestPathInfoCACompatibility99=== CONT TestShellSplit100=== CONT TestSetClientTLSErrors101=== CONT TestSetClientTLSDoesNotMutateDefaultTransport102=== CONT TestScriptTokenScriptFails103=== CONT TestSetClientTLS104=== CONT TestScriptTokenBadJSON105=== CONT TestClientSignaturesByStorePath106=== CONT TestDoWithRetry_BodyReplayedViaGetBody107=== CONT TestScriptTokenEmptyToken108=== CONT TestStreamPushReportsSignatures109=== CONT TestScriptTokenCachesUntilRefresh110=== CONT TestStreamPushRequestLine111=== CONT TestScriptTokenNoExpiryRerunsEveryCall112=== CONT TestStreamPushGivesUpOnDeadServer113=== CONT TestFileTokenEmpty114=== CONT TestStreamPushIsolatesFailures115=== CONT TestFileTokenMissing116=== CONT TestStreamPushBatchesUnderLoad117=== CONT TestStreamPushReportsEveryPath118=== CONT TestFileTokenReadsAndCaches119=== CONT TestShellSplitErrors120=== CONT TestStaticToken121=== CONT TestEncodeNixBase32WithRealHash122=== RUN TestPathInfoCACompatibility/null_ca_field123--- PASS: TestShellSplit (0.00s)124--- PASS: TestClientSignaturesByStorePath (0.00s)125=== CONT TestUploadMultipart_SupersededByPeer126=== CONT TestEncodeNixBase32127=== RUN TestEncodeNixBase32/test_string_hash128--- PASS: TestScriptTokenScriptFails (0.00s)129--- PASS: TestFileTokenReadsAndCaches (0.00s)130=== CONT TestResolveStorePath1312026/10/01 10:22:04 ERROR Upload failed error=boom count=11322026/10/01 10:22:04 ERROR Upload failed error=boom count=1133--- PASS: TestResolveStorePath (0.00s)1342026/10/01 10:22:04 ERROR Upload failed error="connection refused" count=20135=== CONT TestDumpPathWriterError136=== CONT TestGetStorePathHash1372026/10/01 10:22:04 WARN Rate limiter enabled after throttle name=server-test rate=5138--- PASS: TestStreamPushReportsSignatures (0.00s)139--- PASS: TestScriptTokenEmptyToken (0.00s)1402026/10/01 10:22:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:33861141=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1422026/10/01 10:22:04 ERROR Server seems unavailable, giving up on batch untried=17143=== RUN TestGetStorePathHash/valid_store_path144=== RUN TestSetClientTLSErrors/missing_cert_file145=== PAUSE TestGetStorePathHash/valid_store_path146=== PAUSE TestSetClientTLSErrors/missing_cert_file1472026/10/01 10:22:04 WARN Rate limiter enabled after throttle name=server-test rate=5148=== RUN TestGetStorePathHash/basename_without_hyphen_should_error149=== CONT TestConvertHashToNix32150=== CONT TestDumpPathSingleFile151=== CONT TestParsePathInfoJSON152=== RUN TestUploadMultipart_SupersededByPeer/exists153=== RUN TestParsePathInfoJSON/Nix_format154=== PAUSE TestParsePathInfoJSON/Nix_format155=== PAUSE TestEncodeNixBase32/test_string_hash156=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error157=== CONT TestParsePathInfoJSONMultiplePaths158=== RUN TestEncodeNixBase32/empty_input159=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths160=== RUN TestSetClientTLSErrors/missing_key_file161=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error1622026/10/01 10:22:04 WARN Rate limiter backed off name=server-test rate=5163=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error1642026/10/01 10:22:04 ERROR Upload failed error="bad path" count=3165=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error166=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error1672026/10/01 10:22:04 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:33861168=== PAUSE TestSetClientTLSErrors/missing_key_file169=== RUN TestConvertHashToNix32/SRI_format_to_Nix32170=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32171=== CONT TestDumpPathMatchesNix172=== PAUSE TestPathInfoCACompatibility/null_ca_field173=== PAUSE TestUploadMultipart_SupersededByPeer/exists174=== RUN TestParsePathInfoJSON/Lix_format175=== CONT TestFilterOversizedClosures176=== PAUSE TestEncodeNixBase32/empty_input177=== CONT TestRateLimiterFeedback178=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths179=== CONT TestPartSizeForNAR180--- PASS: TestShellSplitErrors (0.00s)181=== CONT TestCaseHackSuffix182=== RUN TestSetClientTLS/rejects_connection_without_client_cert183=== CONT TestUploadMultipart_PartsInParallel184=== CONT TestRegisterUploadedObjectReusesConnections185=== RUN TestSetClientTLSErrors/missing_ca_file186=== CONT TestPathInfoHashCompatibility187=== RUN TestConvertHashToNix32/already_Nix32_format188--- PASS: TestStaticToken (0.00s)189=== RUN TestPathInfoCACompatibility/old_string_format_-_text190=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)191=== RUN TestUploadMultipart_SupersededByPeer/missing192=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)193=== PAUSE TestConvertHashToNix32/already_Nix32_format194=== RUN TestConvertHashToNix32/invalid_format195=== PAUSE TestConvertHashToNix32/invalid_format196=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths197=== PAUSE TestUploadMultipart_SupersededByPeer/missing198=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths199=== PAUSE TestParsePathInfoJSON/Lix_format200=== RUN TestParsePathInfoJSON/empty_input201=== PAUSE TestParsePathInfoJSON/empty_input202=== RUN TestParsePathInfoJSON/whitespace_only203=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error204=== CONT TestEncodeNixBase32/test_string_hash205=== PAUSE TestParsePathInfoJSON/whitespace_only206=== RUN TestFilterOversizedClosures/no_limit_keeps_everything207--- PASS: TestFileTokenMissing (0.00s)208--- PASS: TestEncodeNixBase32WithRealHash (0.00s)209=== CONT TestGetStorePathHash/valid_store_path210=== RUN TestRateLimiterFeedback/429_enables_limiter211=== RUN TestPartSizeForNAR/zero_stays_at_minimum212=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text213=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert214=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon215=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error216=== CONT TestGetStorePathHash/basename_without_hyphen_should_error217=== PAUSE TestSetClientTLSErrors/missing_ca_file218=== RUN TestParsePathInfoJSON/invalid_JSON219=== CONT TestConvertHashToNix32/SRI_format_to_Nix32220=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths221=== RUN TestSetClientTLSErrors/invalid_ca_file222=== PAUSE TestSetClientTLSErrors/invalid_ca_file223=== CONT TestSetClientTLSErrors/missing_cert_file224=== CONT TestUploadMultipart_SupersededByPeer/missing225=== CONT TestSetClientTLSErrors/invalid_ca_file226=== CONT TestConvertHashToNix32/invalid_format227=== CONT TestSetClientTLSErrors/missing_key_file228=== PAUSE TestParsePathInfoJSON/invalid_JSON229=== CONT TestParsePathInfoJSON/Nix_format230--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)231--- PASS: TestStreamPushReportsEveryPath (0.00s)232--- PASS: TestFileTokenEmpty (0.00s)233--- PASS: TestScriptTokenBadJSON (0.01s)234--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)235--- PASS: TestStreamPushIsolatesFailures (0.00s)236=== CONT TestParsePathInfoJSON/empty_input237=== CONT TestParsePathInfoJSON/invalid_JSON238--- PASS: TestDoServerRequestAttachesToken (0.01s)239=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive240=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive241=== RUN TestPathInfoCACompatibility/new_structured_format_-_text242=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text243=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method244--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)245--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)246=== CONT TestUploadMultipart_SupersededByPeer/exists247--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)248=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon249=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI250=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI251=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512252=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA253=== CONT TestEncodeNixBase32/empty_input254=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything255=== CONT TestSetClientTLSErrors/missing_ca_file256=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA257=== RUN TestSetClientTLS/preserves_debug_logging_transport258=== PAUSE TestSetClientTLS/preserves_debug_logging_transport259=== CONT TestSetClientTLS/rejects_connection_without_client_cert260=== CONT TestSetClientTLS/preserves_debug_logging_transport261=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA262=== CONT TestParsePathInfoJSON/Lix_format263=== PAUSE TestRateLimiterFeedback/429_enables_limiter264=== RUN TestRateLimiterFeedback/503_enables_limiter265=== PAUSE TestRateLimiterFeedback/503_enables_limiter266=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter267=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter268=== CONT TestParsePathInfoJSON/whitespace_only269=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum270=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method271=== CONT TestPathInfoCACompatibility/null_ca_field272=== CONT TestPathInfoCACompatibility/old_string_format_-_text273=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped274=== CONT TestPathInfoCACompatibility/new_structured_format_-_text275--- PASS: TestGetStorePathHash (0.00s)276 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)277 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)278 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)279 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)280=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter281=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter282=== CONT TestRateLimiterFeedback/429_enables_limiter283=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512284=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)285=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths286--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)287 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)288 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)289=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512290=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI291=== RUN TestPartSizeForNAR/small_stays_at_minimum292=== PAUSE TestPartSizeForNAR/small_stays_at_minimum293=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum294=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum295=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts296=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts297=== RUN TestPartSizeForNAR/1_TiB298=== PAUSE TestPartSizeForNAR/1_TiB299=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive300=== CONT TestRateLimiterFeedback/503_enables_limiter301=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped302=== RUN TestFilterOversizedClosures/all_closures_skipped303=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon3042026/10/01 10:22:04 WARN Rate limiter enabled after throttle name=server-test rate=5305=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3062026/10/01 10:22:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:41027307=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3082026/10/01 10:22:04 WARN Rate limiter enabled after throttle name=server-test rate=53092026/10/01 10:22:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:384793102026/10/01 10:22:04 WARN Rate limiter backed off name=server-test rate=5311=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3122026/10/01 10:22:04 WARN Rate limiter backed off name=server-test rate=5313=== RUN TestPartSizeForNAR/5_TiB_S3_max_object314--- PASS: TestEncodeNixBase32 (0.01s)315 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)316 --- PASS: TestEncodeNixBase32/empty_input (0.00s)317=== PAUSE TestFilterOversizedClosures/all_closures_skipped318--- PASS: TestParsePathInfoJSON (0.04s)319 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)320 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)321 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)322 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)323 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)324--- PASS: TestPathInfoHashCompatibility (0.03s)325 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)326 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)327 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)328 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)329=== CONT TestFilterOversizedClosures/no_limit_keeps_everything330=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object331=== RUN TestPartSizeForNAR/capped_at_5_GiB332=== CONT TestFilterOversizedClosures/all_closures_skipped3332026/10/01 10:22:04 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=50334=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3352026/10/01 10:22:04 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=2000336--- PASS: TestPathInfoCACompatibility (0.05s)337 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)338 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)339 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)340 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)341 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)342=== PAUSE TestPartSizeForNAR/capped_at_5_GiB343--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)344 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)345 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)346=== CONT TestPartSizeForNAR/zero_stays_at_minimum347=== CONT TestPartSizeForNAR/capped_at_5_GiB348=== CONT TestPartSizeForNAR/5_TiB_S3_max_object349=== CONT TestPartSizeForNAR/1_TiB350=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts351=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum352=== CONT TestPartSizeForNAR/small_stays_at_minimum353--- PASS: TestRateLimiterFeedback (0.03s)354 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)355 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)356 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)357 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)358--- PASS: TestFilterOversizedClosures (0.03s)359 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)360 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)361 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)362--- PASS: TestSetClientTLSErrors (0.04s)363 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)364 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)365 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)366 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)367--- PASS: TestPartSizeForNAR (0.03s)368 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)369 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)370 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)371 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)372 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)373 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)375=== CONT TestConvertHashToNix32/already_Nix32_format376--- PASS: TestConvertHashToNix32 (0.01s)377 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)378 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)379 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)380--- PASS: TestDumpPathSingleFile (0.04s)3812026/10/01 10:22:04 http: TLS handshake error from 127.0.0.1:42466: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.05s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)386--- PASS: TestRegisterUploadedObjectReusesConnections (0.06s)387--- PASS: TestDumpPathWriterError (0.07s)388--- PASS: TestCaseHackSuffix (0.06s)389--- PASS: TestStreamPushRequestLine (0.08s)390--- PASS: TestStreamPushBatchesUnderLoad (0.11s)391--- PASS: TestDumpPathMatchesNix (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/postgres1336061490/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/postgres1336061490/data -l logfile start422423/build/postgres1336061490:5432 - no response4242026-10-01 10:22:05.937 UTC [128] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 10:22:05.938 UTC [128] LOG: listening on Unix socket "/build/postgres1336061490/.s.PGSQL.5432"4262026-10-01 10:22:05.942 UTC [135] LOG: database system was shut down at 2026-10-01 10:22:05 UTC4272026-10-01 10:22:05.945 UTC [128] LOG: database system is ready to accept connections428/build/postgres1336061490:5432 - accepting connections429{"timestamp":"2026-10-01T10:22:06.137362238Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2c1b285e-3138-4285-a873-c043c9a41660","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(194)"}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 10:22:06.315 UTC [370] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 10:22:06.315 UTC [370] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 10:22:06 OK 20241026095416_initial_model.sql (10.57ms)4762026/10/01 10:22:06 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)4772026/10/01 10:22:06 OK 20251218171726_add_pins.sql (2.8ms)4782026/10/01 10:22:06 OK 20260628120000_add_object_size_and_stats.sql (2.62ms)4792026/10/01 10:22:06 OK 20260905000000_add_claims.sql (2.83ms)4802026/10/01 10:22:06 OK 20260920000000_drop_claims.sql (1.75ms)4812026/10/01 10:22:06 OK 20260923120000_add_pushes.sql (1.34ms)4822026/10/01 10:22:06 goose: successfully migrated database to version: 202609231200004832026/10/01 10:22:06 OK 1_commit_pending_closure.sql (1.72ms)4842026/10/01 10:22:06 OK 2_object_stats_trigger.sql (702.89µs)4852026/10/01 10:22:06 OK 3_commit_push.sql (991.41µs)4862026/10/01 10:22:06 goose: up to current file version: 34872026/10/01 10:22:06 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 10:22:06 INFO lead: released remote=192.0.2.1:12344892026/10/01 10:22:07 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 10:22:07 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.78s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 10:22:07.084 UTC [382] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 10:22:07.084 UTC [382] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 10:22:07 OK 20241026095416_initial_model.sql (9.33ms)4982026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)4992026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.06ms)5002026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (3.08ms)5012026/10/01 10:22:07 OK 20260905000000_add_claims.sql (2.68ms)5022026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (1.66ms)5032026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (1.28ms)5042026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200005052026/10/01 10:22:07 OK 1_commit_pending_closure.sql (1.73ms)5062026/10/01 10:22:07 OK 2_object_stats_trigger.sql (711.53µs)5072026/10/01 10:22:07 OK 3_commit_push.sql (532.83µs)5082026/10/01 10:22:07 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 TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 10:22:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"669--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)670=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== RUN TestProxyWriteTimeout673=== PAUSE TestProxyWriteTimeout674=== RUN TestPendingClosureWriteTimeout675=== PAUSE TestPendingClosureWriteTimeout676=== RUN TestIsValidUploadKey677=== PAUSE TestIsValidUploadKey678=== RUN TestUploadHandlersRejectInvalidKeys679=== PAUSE TestUploadHandlersRejectInvalidKeys680=== RUN TestUploadHandlersRejectOversizedBody681=== PAUSE TestUploadHandlersRejectOversizedBody682=== RUN TestService_cleanupPendingClosuresHandler683=== PAUSE TestService_cleanupPendingClosuresHandler684=== RUN TestService_createPendingClosureHandler685=== PAUSE TestService_createPendingClosureHandler686=== RUN TestService_verifyS3Integrity687=== PAUSE TestService_verifyS3Integrity688=== RUN TestCompleteMultipartUnregistered689=== PAUSE TestCompleteMultipartUnregistered690=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT691=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT692=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle693=== CONT TestService_AuthMiddleware694=== CONT TestSkippedUploadsHandler695=== CONT TestParseSize696=== CONT TestService_Rustfstest697=== CONT TestGCTaskStore_PhaseUpdates6982026/10/01 10:22:07 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000699=== CONT TestPresentNotReportedWhileGCDeletesClosure700=== CONT TestGCTaskStore_CompletedAllowsNewTask701=== CONT TestPresentReportsOnlyClosureRoots702=== CONT TestGCTaskStore_GetReturnsLatest703=== CONT TestForceGCDuringPushOffersSweptObject704=== CONT TestGCTaskStore_GetEmpty705=== CONT TestGCTaskStore_ConflictDifferentParams706=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows707=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows708=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check709=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check710=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection711=== CONT TestGCTaskStore_StartNew712=== CONT TestProxyHeadersOnlyTrustedOnSocket713=== CONT TestGCEndsOnShutdown714=== CONT TestCommitRacingPendingCleanupKeepsObjects715=== CONT TestPushWaitsForSweepHoldingRow716=== CONT TestGCTaskStore_Fail717=== CONT TestSweepRechecksPendingAfterLocking718=== CONT TestGetExistingObjectsLocksRows719=== CONT TestPresignedUploadRegisteredBeforeCommit720=== CONT TestRegisterCompletedObjectNeedsPendingRow721=== CONT TestCompletedNarNotReofferedAcrossClosures722=== CONT TestSweepSkipsRowsLockedByPush723=== CONT TestCompleteMultipartUpload_ErrorButObjectExists724=== CONT TestFailedS3DeleteKeepsTombstone725--- PASS: TestParseSize (0.00s)726=== CONT TestParseSingleRange727=== CONT TestCreatePin_ReservedPins728=== CONT TestOrphanedObjectsGC729=== RUN TestParseSingleRange/none730--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)731--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)732=== CONT TestGCTaskStore_DeduplicateSameParams733=== PAUSE TestParseSingleRange/none734=== CONT TestOrphanedObjectsGCStressTest735--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)736--- PASS: TestGCTaskStore_GetEmpty (0.00s)737=== CONT TestGCSweepDeliversEachKeyOnce738=== RUN TestParseSingleRange/unknown_unit739--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)740=== PAUSE TestParseSingleRange/unknown_unit741--- PASS: TestGCTaskStore_StartNew (0.00s)742--- PASS: TestGCTaskStore_Fail (0.00s)743--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)744=== RUN TestParseSingleRange/multi-range_ignored745=== PAUSE TestParseSingleRange/multi-range_ignored746=== RUN TestParseSingleRange/malformed_no_dash747=== PAUSE TestParseSingleRange/malformed_no_dash748=== RUN TestParseSingleRange/malformed_both_empty749=== PAUSE TestParseSingleRange/malformed_both_empty750=== RUN TestParseSingleRange/malformed_end_before_start751=== PAUSE TestParseSingleRange/malformed_end_before_start752=== RUN TestParseSingleRange/closed753=== PAUSE TestParseSingleRange/closed754=== RUN TestParseSingleRange/open-ended755=== PAUSE TestParseSingleRange/open-ended756=== RUN TestParseSingleRange/end_clamped_to_size757=== PAUSE TestParseSingleRange/end_clamped_to_size758=== RUN TestParseSingleRange/suffix759=== PAUSE TestParseSingleRange/suffix760=== RUN TestParseSingleRange/suffix_exceeds_size761=== PAUSE TestParseSingleRange/suffix_exceeds_size762=== RUN TestParseSingleRange/single_byte763=== PAUSE TestParseSingleRange/single_byte764=== RUN TestParseSingleRange/start_past_EOF765=== PAUSE TestParseSingleRange/start_past_EOF766=== RUN TestParseSingleRange/start_far_past_EOF767=== PAUSE TestParseSingleRange/start_far_past_EOF768=== CONT TestRedundantMultipartUpload769--- PASS: TestSkippedUploadsHandler (0.00s)770=== CONT TestTombstonedObjectOfferedWithoutWaiting7712026-10-01 10:22:07.445 UTC [445] ERROR: relation "goose_db_version" does not exist at character 367722026-10-01 10:22:07.445 UTC [445] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7732026-10-01 10:22:07.448 UTC [446] ERROR: relation "goose_db_version" does not exist at character 367742026-10-01 10:22:07.448 UTC [446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7752026-10-01 10:22:07.516 UTC [452] ERROR: relation "goose_db_version" does not exist at character 367762026-10-01 10:22:07.516 UTC [452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7772026-10-01 10:22:07.518 UTC [453] ERROR: relation "goose_db_version" does not exist at character 367782026-10-01 10:22:07.518 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7792026/10/01 10:22:07 OK 20241026095416_initial_model.sql (19.11ms)7802026-10-01 10:22:07.521 UTC [454] ERROR: relation "goose_db_version" does not exist at character 367812026-10-01 10:22:07.521 UTC [454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026-10-01 10:22:07.525 UTC [455] ERROR: relation "goose_db_version" does not exist at character 367832026-10-01 10:22:07.525 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026/10/01 10:22:07 OK 20241026095416_initial_model.sql (23.33ms)7852026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (7.16ms)7862026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.24ms)7872026/10/01 10:22:07 OK 20251218171726_add_pins.sql (8ms)7882026-10-01 10:22:07.540 UTC [456] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 10:22:07.540 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026-10-01 10:22:07.540 UTC [457] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 10:22:07.540 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 10:22:07.541 UTC [458] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 10:22:07.541 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026/10/01 10:22:07 OK 20251218171726_add_pins.sql (8.99ms)7952026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (14.31ms)7962026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (12.39ms)7972026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.09ms)7982026/10/01 10:22:07 OK 20241026095416_initial_model.sql (26.17ms)7992026/10/01 10:22:07 OK 20241026095416_initial_model.sql (26.13ms)8002026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.82ms)8012026/10/01 10:22:07 OK 20241026095416_initial_model.sql (23.08ms)8022026/10/01 10:22:07 OK 20241026095416_initial_model.sql (22.04ms)8032026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.39ms)8042026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (6.17ms)8052026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.52ms)8062026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (5.12ms)8072026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.87ms)8082026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (5.24ms)8092026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.45ms)8102026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200008112026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.46ms)8122026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200008132026/10/01 10:22:07 OK 20251218171726_add_pins.sql (6.69ms)8142026/10/01 10:22:07 OK 20251218171726_add_pins.sql (13.18ms)8152026/10/01 10:22:07 OK 1_commit_pending_closure.sql (11.88ms)8162026/10/01 10:22:07 OK 20251218171726_add_pins.sql (13.38ms)8172026/10/01 10:22:07 OK 20251218171726_add_pins.sql (13.27ms)8182026/10/01 10:22:07 OK 1_commit_pending_closure.sql (10.97ms)8192026/10/01 10:22:07 OK 20241026095416_initial_model.sql (22.95ms)8202026/10/01 10:22:07 OK 20241026095416_initial_model.sql (18.82ms)8212026/10/01 10:22:07 OK 20241026095416_initial_model.sql (22.95ms)8222026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (10.34ms)8232026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.16ms)8242026/10/01 10:22:07 OK 3_commit_push.sql (595.05µs)8252026/10/01 10:22:07 goose: up to current file version: 38262026/10/01 10:22:07 OK 2_object_stats_trigger.sql (4.43ms)8272026/10/01 10:22:07 OK 20260905000000_add_claims.sql (5.24ms)8282026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)8292026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.78ms)8302026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.14ms)8312026/10/01 10:22:07 OK 3_commit_push.sql (1.7ms)8322026/10/01 10:22:07 goose: up to current file version: 38332026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (6.59ms)8342026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)8352026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.93ms)8362026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.78ms)8372026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.12ms)8382026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.32ms)8392026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.39ms)8402026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.18ms)8412026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200008422026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.28ms)8432026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.12ms)8442026-10-01 10:22:07.591 UTC [459] ERROR: relation "goose_db_version" does not exist at character 368452026-10-01 10:22:07.591 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8462026-10-01 10:22:07.591 UTC [460] ERROR: relation "goose_db_version" does not exist at character 368472026-10-01 10:22:07.591 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8482026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.13ms)8492026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.79ms)8502026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.41ms)8512026-10-01 10:22:07.594 UTC [463] ERROR: relation "goose_db_version" does not exist at character 368522026-10-01 10:22:07.594 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8532026-10-01 10:22:07.594 UTC [461] ERROR: relation "goose_db_version" does not exist at character 368542026-10-01 10:22:07.594 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8552026-10-01 10:22:07.594 UTC [462] ERROR: relation "goose_db_version" does not exist at character 368562026-10-01 10:22:07.594 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8572026-10-01 10:22:07.594 UTC [464] ERROR: relation "goose_db_version" does not exist at character 368582026-10-01 10:22:07.594 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8592026-10-01 10:22:07.594 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368602026-10-01 10:22:07.594 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8612026-10-01 10:22:07.594 UTC [465] ERROR: relation "goose_db_version" does not exist at character 368622026-10-01 10:22:07.594 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8632026-10-01 10:22:07.595 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368642026-10-01 10:22:07.595 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8652026-10-01 10:22:07.595 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368662026-10-01 10:22:07.595 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8672026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.9ms)8682026-10-01 10:22:07.595 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368692026-10-01 10:22:07.595 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8702026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (6.14ms)8712026-10-01 10:22:07.596 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368722026-10-01 10:22:07.596 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8732026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (7.61ms)8742026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.71ms)8752026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200008762026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.79ms)8772026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.68ms)8782026-10-01 10:22:07.597 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368792026-10-01 10:22:07.597 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8802026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200008812026-10-01 10:22:07.597 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368822026-10-01 10:22:07.597 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8832026/10/01 10:22:07 OK 2_object_stats_trigger.sql (3.13ms)8842026/10/01 10:22:07 OK 3_commit_push.sql (2.74ms)8852026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (4ms)8862026/10/01 10:22:07 goose: up to current file version: 38872026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.86ms)8882026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.68ms)8892026/10/01 10:22:07 OK 20260905000000_add_claims.sql (5.09ms)8902026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.51ms)8912026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.81ms)8922026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.55ms)8932026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (3.45ms)8942026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200008952026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.55ms)8962026/10/01 10:22:07 OK 3_commit_push.sql (1.34ms)8972026/10/01 10:22:07 goose: up to current file version: 38982026/10/01 10:22:07 OK 3_commit_push.sql (2.45ms)8992026/10/01 10:22:07 goose: up to current file version: 39002026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.81ms)9012026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (4.32ms)9022026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (4.05ms)9032026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.2ms)9042026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.69ms)9052026/10/01 10:22:07 goose: successfully migrated database to version: 20260923120000906--- PASS: TestService_Rustfstest (0.25s)907=== CONT TestPush_SignsNarinfosOfItsPendingObjects9082026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.91ms)9092026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (3.35ms)9102026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200009112026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (3.74ms)9122026/10/01 10:22:07 goose: successfully migrated database to version: 202609231200009132026/10/01 10:22:07 OK 3_commit_push.sql (1.53ms)9142026/10/01 10:22:07 goose: up to current file version: 39152026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.25ms)9162026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.05ms)9172026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.55ms)9182026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.64ms)9192026/10/01 10:22:07 OK 20241026095416_initial_model.sql (12.08ms)9202026/10/01 10:22:07 OK 20241026095416_initial_model.sql (13.33ms)9212026/10/01 10:22:07 OK 3_commit_push.sql (1.65ms)9222026/10/01 10:22:07 goose: up to current file version: 39232026/10/01 10:22:07 OK 1_commit_pending_closure.sql (4.81ms)9242026/10/01 10:22:07 OK 3_commit_push.sql (1.73ms)9252026/10/01 10:22:07 goose: up to current file version: 39262026/10/01 10:22:07 OK 20241026095416_initial_model.sql (14.43ms)9272026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.19ms)9282026/10/01 10:22:07 OK 20241026095416_initial_model.sql (16.28ms)9292026/10/01 10:22:07 OK 20241026095416_initial_model.sql (14.59ms)9302026/10/01 10:22:07 OK 20241026095416_initial_model.sql (17.28ms)9312026/10/01 10:22:07 OK 20241026095416_initial_model.sql (15.21ms)9322026/10/01 10:22:07 OK 20241026095416_initial_model.sql (14.68ms)9332026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.27ms)9342026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.35ms)9352026/10/01 10:22:07 OK 20241026095416_initial_model.sql (15.74ms)9362026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)9372026/10/01 10:22:07 OK 3_commit_push.sql (1.41ms)9382026/10/01 10:22:07 goose: up to current file version: 39392026/10/01 10:22:07 OK 20241026095416_initial_model.sql (15.73ms)9402026/10/01 10:22:07 OK 20241026095416_initial_model.sql (15.95ms)9412026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)9422026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.24ms)9432026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.28ms)9442026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)9452026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.15ms)9462026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.37ms)9472026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (3.17ms)9482026/10/01 10:22:07 OK 20241026095416_initial_model.sql (16.04ms)9492026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.93ms)9502026/10/01 10:22:07 OK 20241026095416_initial_model.sql (16.23ms)9512026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)9522026/10/01 10:22:07 OK 20241026095416_initial_model.sql (15.55ms)9532026/10/01 10:22:07 OK 20251218171726_add_pins.sql (5.44ms)9542026/10/01 10:22:07 OK 20251218171726_add_pins.sql (5.51ms)9552026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)9562026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures9572026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)9582026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)9592026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.24ms)9602026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.38ms)9612026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.18ms)9622026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.2ms)9632026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.7ms)9642026/10/01 10:22:07 OK 20251218171726_add_pins.sql (5.01ms)9652026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.82ms)9662026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.71ms)9672026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)9682026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.02ms)9692026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.08ms)9702026/10/01 10:22:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33649/oidc9712026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.31ms)9722026/10/01 10:22:07 OK 20251218171726_add_pins.sql (5.04ms)9732026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.59ms)9742026/10/01 10:22:07 OK 20251218171726_add_pins.sql (5.26ms)9752026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.35ms)9762026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.43ms)9772026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.93ms)9782026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (6.5ms)9792026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (6.99ms)9802026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.53ms)9812026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (6.43ms)9822026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (6.93ms)9832026/10/01 10:22:07 OK 20260905000000_add_claims.sql (6.34ms)9842026/10/01 10:22:07 OK 20260905000000_add_claims.sql (6.32ms)9852026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.71ms)9862026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)9872026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.56ms)9882026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.88ms)9892026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.51ms)9902026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.66ms)9912026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.17ms)9922026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (5.95ms)9932026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.26ms)9942026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.55ms)9952026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.69ms)9962026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.94ms)9972026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.4ms)9982026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.3ms)9992026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.33ms)10002026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.46ms)10012026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.57ms)10022026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.64ms)10032026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.14ms)10042026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010052026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.12ms)10062026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.62ms)10072026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.28ms)10082026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.47ms)10092026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.95ms)10102026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010112026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.65ms)10122026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.46ms)10132026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.01ms)10142026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.08ms)10152026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.76ms)10162026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010172026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.64ms)10182026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010192026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.72ms)10202026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010212026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.16ms)10222026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (3.1ms)10232026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010242026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (3.3ms)10252026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010262026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (3.65ms)10272026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010282026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.55ms)10292026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010302026/10/01 10:22:07 OK 1_commit_pending_closure.sql (4.5ms)10312026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.24ms)10322026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3ms)10332026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.15ms)10342026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010352026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.58ms)10362026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010372026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.77ms)10382026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.33ms)10392026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.97ms)10402026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.28ms)10412026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010422026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (4.77ms)10432026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010442026/10/01 10:22:07 OK 2_object_stats_trigger.sql (3.86ms)10452026/10/01 10:22:07 OK 2_object_stats_trigger.sql (3.14ms)10462026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.21ms)10472026/10/01 10:22:07 OK 1_commit_pending_closure.sql (4.78ms)10482026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.99ms)10492026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000010502026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.23ms)10512026/10/01 10:22:07 OK 3_commit_push.sql (1.68ms)10522026/10/01 10:22:07 goose: up to current file version: 310532026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.59ms)10542026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures10552026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.79ms)10562026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.52ms)10572026/10/01 10:22:07 OK 3_commit_push.sql (1.83ms)10582026/10/01 10:22:07 goose: up to current file version: 310592026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.73ms)10602026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.25ms)10612026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.67ms)10622026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.81ms)10632026/10/01 10:22:07 OK 3_commit_push.sql (991.71µs)10642026/10/01 10:22:07 goose: up to current file version: 310652026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.94ms)10662026/10/01 10:22:07 OK 3_commit_push.sql (1.16ms)10672026/10/01 10:22:07 goose: up to current file version: 310682026/10/01 10:22:07 OK 3_commit_push.sql (1.5ms)10692026/10/01 10:22:07 goose: up to current file version: 310702026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.47ms)10712026/10/01 10:22:07 OK 3_commit_push.sql (1.35ms)10722026/10/01 10:22:07 goose: up to current file version: 310732026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.11ms)10742026/10/01 10:22:07 OK 3_commit_push.sql (1.67ms)10752026/10/01 10:22:07 goose: up to current file version: 310762026/10/01 10:22:07 OK 3_commit_push.sql (1.8ms)10772026/10/01 10:22:07 goose: up to current file version: 310782026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.71ms)10792026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.94ms)10802026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.77ms)10812026/10/01 10:22:07 OK 3_commit_push.sql (1.32ms)10822026/10/01 10:22:07 goose: up to current file version: 310832026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.42ms)10842026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.61ms)10852026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.41ms)10862026/10/01 10:22:07 OK 3_commit_push.sql (1.93ms)10872026/10/01 10:22:07 goose: up to current file version: 310882026/10/01 10:22:07 OK 3_commit_push.sql (1.38ms)10892026/10/01 10:22:07 goose: up to current file version: 310902026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.41ms)10912026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.6ms)10922026/10/01 10:22:07 OK 3_commit_push.sql (1.9ms)10932026/10/01 10:22:07 goose: up to current file version: 310942026/10/01 10:22:07 OK 3_commit_push.sql (1.46ms)10952026/10/01 10:22:07 goose: up to current file version: 310962026/10/01 10:22:07 OK 3_commit_push.sql (987.37µs)10972026/10/01 10:22:07 goose: up to current file version: 31098--- PASS: TestGCEndsOnShutdown (0.31s)1099=== CONT TestGCSweepSkipsPendingObjects11002026-10-01 10:22:07.695 UTC [480] ERROR: relation "goose_db_version" does not exist at character 3611012026-10-01 10:22:07.695 UTC [480] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11022026-10-01 10:22:07.702 UTC [482] ERROR: relation "goose_db_version" does not exist at character 3611032026-10-01 10:22:07.702 UTC [482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11042026/10/01 10:22:07 INFO Starting HTTP server address=127.0.0.1:3372111052026/10/01 10:22:07 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3984828062/001/proxy.sock11062026/10/01 10:22:07 WARN mTLS auth: subject not in bound subjects subject="CN=someone"11072026/10/01 10:22:07 INFO Shutdown signal received, draining in-flight requests timeout=10s1108--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.35s)1109=== CONT TestPush_RejectsBadRequests11102026/10/01 10:22:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11112026/10/01 10:22:07 OK 20241026095416_initial_model.sql (11.34ms)11122026/10/01 10:22:07 OK 20241026095416_initial_model.sql (11.09ms)11132026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)11142026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)11152026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.78ms)11162026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.86ms)11172026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)11182026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)11192026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.27ms)11202026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.2ms)11212026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.31ms)1122--- PASS: TestPresentReportsOnlyClosureRoots (0.37s)1123=== CONT TestDeduplicatedObjectsRecordedAsPending11242026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.06ms)11252026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.28ms)11262026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000011272026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.24ms)11282026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000011292026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.32ms)11302026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.04ms)11312026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.36ms)11322026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.64ms)11332026/10/01 10:22:07 OK 3_commit_push.sql (1.43ms)11342026/10/01 10:22:07 goose: up to current file version: 311352026/10/01 10:22:07 OK 3_commit_push.sql (612.85µs)11362026/10/01 10:22:07 goose: up to current file version: 311372026-10-01 10:22:07.751 UTC [487] ERROR: relation "goose_db_version" does not exist at character 3611382026-10-01 10:22:07.751 UTC [487] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11392026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/01 10:22:07 OK 20241026095416_initial_model.sql (10.5ms)11412026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)11422026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.29ms)11432026/10/01 10:22:07 INFO Aborted multipart uploads count=0 kept=011442026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures11452026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)11462026/10/01 10:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period11472026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.52ms)11482026/10/01 10:22:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011492026-10-01 10:22:07.785 UTC [491] ERROR: relation "goose_db_version" does not exist at character 3611502026-10-01 10:22:07.785 UTC [491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11512026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.91ms)11522026/10/01 10:22:07 INFO Vacuumed table table=pending_closures11532026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.12ms)11542026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000011552026/10/01 10:22:07 INFO Vacuumed table table=pending_objects11562026/10/01 10:22:07 INFO Vacuumed table table=multipart_uploads11572026/10/01 10:22:07 INFO Vacuumed table table=closures11582026/10/01 10:22:07 INFO Vacuumed table table=objects11592026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.81ms)11602026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.28ms)11612026/10/01 10:22:07 OK 3_commit_push.sql (732.15µs)11622026/10/01 10:22:07 goose: up to current file version: 31163--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.43s)1164=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11652026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures11662026/10/01 10:22:07 OK 20241026095416_initial_model.sql (9.05ms)11672026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.58ms)11682026-10-01 10:22:07.803 UTC [492] ERROR: relation "goose_db_version" does not exist at character 3611692026-10-01 10:22:07.803 UTC [492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1170--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.44s)1171=== CONT TestPush_CompleteCommitsEveryRoot11722026/10/01 10:22:07 OK 20251218171726_add_pins.sql (2.8ms)11732026/10/01 10:22:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11742026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)11752026/10/01 10:22:07 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLmIxNmM5OTU4LTE4YTYtNGI4MS1iM2E5LWZjMjU2ZWFiMjQwNngxNzkwODUwMTI3Nzg0OTc5NTk011762026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.23ms)11772026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.05ms)11782026/10/01 10:22:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLmIxNmM5OTU4LTE4YTYtNGI4MS1iM2E5LWZjMjU2ZWFiMjQwNngxNzkwODUwMTI3Nzg0OTc5NTk0 parts=11179--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.45s)1180=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11812026/10/01 10:22:07 OK 20241026095416_initial_model.sql (10.14ms)11822026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.68ms)11832026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000011842026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.55ms)11852026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)11862026/10/01 10:22:07 OK 2_object_stats_trigger.sql (2.22ms)11872026/10/01 10:22:07 OK 3_commit_push.sql (1.3ms)11882026/10/01 10:22:07 goose: up to current file version: 311892026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.42ms)11902026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (9.14ms)11912026/10/01 10:22:07 INFO Aborted multipart uploads count=0 kept=011922026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.2ms)11932026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.32ms)11942026/10/01 10:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period11952026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.27ms)11962026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000011972026/10/01 10:22:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011982026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.32ms)11992026/10/01 10:22:07 INFO Vacuumed table table=pending_closures12002026/10/01 10:22:07 INFO Vacuumed table table=pending_objects12012026/10/01 10:22:07 INFO Vacuumed table table=multipart_uploads12022026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.19ms)12032026/10/01 10:22:07 INFO Vacuumed table table=closures12042026/10/01 10:22:07 INFO Aborted multipart uploads count=0 kept=012052026/10/01 10:22:07 OK 3_commit_push.sql (1.49ms)12062026/10/01 10:22:07 goose: up to current file version: 312072026/10/01 10:22:07 INFO Vacuumed table table=objects12082026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures12092026/10/01 10:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period12102026/10/01 10:22:07 INFO Aborted multipart uploads count=0 kept=012112026/10/01 10:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period1212--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.50s)1213=== CONT TestReadRedirectUsesPublicS3URL12142026/10/01 10:22:07 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=012152026/10/01 10:22:07 INFO Vacuumed table table=pending_closures12162026/10/01 10:22:07 INFO Vacuumed table table=pending_objects12172026/10/01 10:22:07 INFO Vacuumed table table=multipart_uploads12182026/10/01 10:22:07 INFO Vacuumed table table=closures12192026/10/01 10:22:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012202026/10/01 10:22:07 INFO Vacuumed table table=objects12212026-10-01 10:22:07.870 UTC [505] ERROR: relation "goose_db_version" does not exist at character 3612222026-10-01 10:22:07.870 UTC [505] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12232026/10/01 10:22:07 INFO Vacuumed table table=pending_closures1224--- PASS: TestSweepSkipsRowsLockedByPush (0.51s)1225=== CONT TestReadProxyRangeRequest12262026/10/01 10:22:07 INFO Vacuumed table table=pending_objects12272026/10/01 10:22:07 INFO Vacuumed table table=multipart_uploads12282026/10/01 10:22:07 INFO Vacuumed table table=closures12292026/10/01 10:22:07 INFO Vacuumed table table=objects1230--- PASS: TestSweepRechecksPendingAfterLocking (0.51s)1231=== CONT TestPushDedupSurvivesConcurrentGC12322026-10-01 10:22:07.879 UTC [507] ERROR: relation "goose_db_version" does not exist at character 3612332026-10-01 10:22:07.879 UTC [507] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12342026/10/01 10:22:07 OK 20241026095416_initial_model.sql (10.84ms)12352026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)12362026-10-01 10:22:07.892 UTC [511] ERROR: relation "goose_db_version" does not exist at character 3612372026-10-01 10:22:07.892 UTC [511] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12382026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.59ms)12392026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.56ms)12402026/10/01 10:22:07 OK 20241026095416_initial_model.sql (11.76ms)12412026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)12422026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.73ms)12432026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.16ms)12442026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.52ms)12452026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (8.44ms)12462026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000012472026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (9.78ms)12482026/10/01 10:22:07 OK 20241026095416_initial_model.sql (14.98ms)12492026/10/01 10:22:07 OK 1_commit_pending_closure.sql (3.01ms)12502026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.68ms)12512026/10/01 10:22:07 OK 20260905000000_add_claims.sql (4.14ms)12522026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures12532026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)12542026/10/01 10:22:07 OK 3_commit_push.sql (1.47ms)12552026/10/01 10:22:07 goose: up to current file version: 312562026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.58ms)12572026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.75ms)12582026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.59ms)12592026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000012602026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.36ms)12612026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)12622026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.35ms)12632026/10/01 10:22:07 OK 3_commit_push.sql (1.51ms)12642026/10/01 10:22:07 goose: up to current file version: 312652026/10/01 10:22:07 INFO Aborted multipart uploads count=0 kept=012662026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.85ms)12672026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.72ms)12682026/10/01 10:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period12692026-10-01 10:22:07.935 UTC [516] ERROR: relation "goose_db_version" does not exist at character 3612702026-10-01 10:22:07.935 UTC [516] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12712026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.2ms)12722026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000012732026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.3ms)12742026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.43ms)12752026/10/01 10:22:07 OK 3_commit_push.sql (786.89µs)12762026/10/01 10:22:07 goose: up to current file version: 312772026/10/01 10:22:07 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12782026/10/01 10:22:07 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1279--- PASS: TestFailedS3DeleteKeepsTombstone (0.58s)1280=== CONT TestReadRedirectKeepsNarinfoProxied12812026-10-01 10:22:07.947 UTC [517] ERROR: relation "goose_db_version" does not exist at character 3612822026-10-01 10:22:07.947 UTC [517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12832026/10/01 10:22:07 OK 20241026095416_initial_model.sql (9.48ms)12842026-10-01 10:22:07.950 UTC [518] ERROR: relation "goose_db_version" does not exist at character 3612852026-10-01 10:22:07.950 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12862026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)12872026/10/01 10:22:07 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1288--- PASS: TestService_AuthMiddleware (0.59s)1289=== CONT TestGCMetrics12902026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.09ms)12912026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (3.53ms)12922026/10/01 10:22:07 INFO Aborted multipart uploads count=0 kept=012932026/10/01 10:22:07 OK 20260905000000_add_claims.sql (3.97ms)12942026/10/01 10:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period12952026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.54ms)12962026/10/01 10:22:07 OK 20241026095416_initial_model.sql (12.27ms)12972026/10/01 10:22:07 OK 20241026095416_initial_model.sql (11.06ms)12982026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)12992026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.95ms)13002026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000013012026/10/01 10:22:07 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)13022026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.7ms)13032026/10/01 10:22:07 OK 20251218171726_add_pins.sql (3.82ms)13042026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.64ms)13052026/10/01 10:22:07 OK 20251218171726_add_pins.sql (4.36ms)13062026/10/01 10:22:07 OK 3_commit_push.sql (1.63ms)13072026/10/01 10:22:07 goose: up to current file version: 313082026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (3.8ms)13092026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures13102026/10/01 10:22:07 OK 20260628120000_add_object_size_and_stats.sql (3.41ms)13112026/10/01 10:22:07 OK 20260905000000_add_claims.sql (2.95ms)13122026/10/01 10:22:07 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=013132026/10/01 10:22:07 INFO Vacuumed table table=pending_closures13142026/10/01 10:22:07 INFO Vacuumed table table=pending_objects13152026/10/01 10:22:07 INFO Vacuumed table table=multipart_uploads13162026/10/01 10:22:07 OK 20260905000000_add_claims.sql (5.06ms)13172026/10/01 10:22:07 INFO Vacuumed table table=closures13182026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (3.99ms)13192026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.03ms)13202026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000013212026/10/01 10:22:07 OK 20260920000000_drop_claims.sql (2.91ms)13222026/10/01 10:22:07 INFO Vacuumed table table=objects1323--- PASS: TestGCSweepDeliversEachKeyOnce (0.62s)1324=== CONT TestObjectStatsTrigger13252026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.28ms)13262026/10/01 10:22:07 OK 20260923120000_add_pushes.sql (2.71ms)13272026/10/01 10:22:07 goose: successfully migrated database to version: 2026092312000013282026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.39ms)13292026/10/01 10:22:07 OK 3_commit_push.sql (1.18ms)13302026/10/01 10:22:07 goose: up to current file version: 313312026/10/01 10:22:07 OK 1_commit_pending_closure.sql (2.65ms)13322026/10/01 10:22:07 OK 2_object_stats_trigger.sql (1.21ms)13332026/10/01 10:22:07 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13342026/10/01 10:22:07 INFO Received uploads request method=POST path=/api/pending_closures13352026/10/01 10:22:07 OK 3_commit_push.sql (1.5ms)13362026/10/01 10:22:07 goose: up to current file version: 31337--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.63s)1338=== CONT TestGCBugBareHashReferences1339--- PASS: TestGetExistingObjectsLocksRows (0.65s)1340=== CONT TestPendingCleanupUsesOneCutoff13412026-10-01 10:22:08.020 UTC [529] ERROR: relation "goose_db_version" does not exist at character 3613422026-10-01 10:22:08.020 UTC [529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1343--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.66s)1344=== CONT TestLeadEndsOnShutdown13452026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures13462026-10-01 10:22:08.034 UTC [534] ERROR: relation "goose_db_version" does not exist at character 3613472026-10-01 10:22:08.034 UTC [534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13482026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.66ms)13492026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)13502026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.64ms)13512026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (273.69ms)13522026/10/01 10:22:08 OK 20241026095416_initial_model.sql (277.56ms)13532026-10-01 10:22:08.329 UTC [535] ERROR: relation "goose_db_version" does not exist at character 3613542026-10-01 10:22:08.329 UTC [535] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1355--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.97s)1356=== CONT TestReadRedirectNar13572026/10/01 10:22:08 INFO Received push request method=POST path=/api/pushes13582026/10/01 10:22:08 OK 20260905000000_add_claims.sql (24.61ms)13592026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (22.2ms)13602026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures13612026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.16ms)13622026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.27ms)13632026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.68ms)13642026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000013652026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.44ms)13662026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.99ms)13672026-10-01 10:22:08.351 UTC [538] ERROR: relation "goose_db_version" does not exist at character 3613682026-10-01 10:22:08.351 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13692026/10/01 10:22:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13702026/10/01 10:22:08 INFO Signed narinfos id=1 count=113712026/10/01 10:22:08 OK 2_object_stats_trigger.sql (5.6ms)1372--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.75s)1373=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded13742026/10/01 10:22:08 OK 20260905000000_add_claims.sql (5.83ms)13752026/10/01 10:22:08 OK 3_commit_push.sql (1.66ms)13762026/10/01 10:22:08 goose: up to current file version: 313772026/10/01 10:22:08 OK 20241026095416_initial_model.sql (13.2ms)13782026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.87ms)13792026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.12ms)13802026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000013812026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)13822026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.86ms)13832026-10-01 10:22:08.365 UTC [541] ERROR: relation "goose_db_version" does not exist at character 3613842026-10-01 10:22:08.365 UTC [541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13852026-10-01 10:22:08.365 UTC [542] ERROR: relation "goose_db_version" does not exist at character 3613862026-10-01 10:22:08.365 UTC [542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13872026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.64ms)13882026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.14ms)13892026/10/01 10:22:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13902026/10/01 10:22:08 WARN Refused reserved pin name=worker-x86_64-linux13912026/10/01 10:22:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13922026/10/01 10:22:08 INFO Received create pin request method=POST path=/api/pins/my-app13932026/10/01 10:22:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13942026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.1ms)13952026/10/01 10:22:08 OK 3_commit_push.sql (1.72ms)13962026/10/01 10:22:08 goose: up to current file version: 31397--- PASS: TestCreatePin_ReservedPins (1.01s)1398=== CONT TestLeadElectsOneAndHandsOver13992026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)14002026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)14012026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.91ms)14022026/10/01 10:22:08 OK 20260905000000_add_claims.sql (4.31ms)14032026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.05ms)14042026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (5.02ms)14052026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.58ms)14062026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000014072026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures14082026/10/01 10:22:08 OK 20241026095416_initial_model.sql (12.37ms)14092026/10/01 10:22:08 OK 20241026095416_initial_model.sql (13.1ms)14102026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.85ms)14112026/10/01 10:22:08 OK 20260905000000_add_claims.sql (4.77ms)14122026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)14132026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)14142026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.3ms)14152026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.13ms)14162026/10/01 10:22:08 OK 3_commit_push.sql (1.89ms)14172026/10/01 10:22:08 goose: up to current file version: 314182026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.63ms)14192026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.84ms)14202026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.04ms)14212026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000014222026/10/01 10:22:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14232026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.34ms)14242026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.25ms)14252026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.2ms)14262026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.29ms)14272026/10/01 10:22:08 OK 3_commit_push.sql (1.31ms)14282026/10/01 10:22:08 goose: up to current file version: 314292026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.79ms)14302026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.86ms)14312026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.26ms)14322026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.96ms)14332026/10/01 10:22:08 INFO Aborted multipart uploads count=0 kept=01434=== RUN TestPush_RejectsBadRequests/no_objects1435=== PAUSE TestPush_RejectsBadRequests/no_objects1436=== RUN TestPush_RejectsBadRequests/bad_root1437=== PAUSE TestPush_RejectsBadRequests/bad_root1438=== RUN TestPush_RejectsBadRequests/root_not_in_objects1439=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1440=== RUN TestPush_RejectsBadRequests/no_roots1441=== PAUSE TestPush_RejectsBadRequests/no_roots1442=== CONT TestReadProxyDisabled14432026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.2ms)14442026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000014452026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.72ms)14462026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000014472026/10/01 10:22:08 WARN Force mode enabled - objects will be deleted immediately without grace period14482026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.75ms)14492026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.11ms)14502026-10-01 10:22:08.408 UTC [567] ERROR: relation "goose_db_version" does not exist at character 3614512026-10-01 10:22:08.408 UTC [567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14522026/10/01 10:22:08 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLjY5ZWEwMTg3LTIzNDMtNDgyZi05NTFjLTU3Yzg4YjgwODZlOXgxNzkwODUwMTI3NzY4OTE0OTI5 parts=1214532026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.41ms)14542026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures14552026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.4ms)14562026/10/01 10:22:08 OK 3_commit_push.sql (1.07ms)14572026/10/01 10:22:08 goose: up to current file version: 314582026/10/01 10:22:08 OK 3_commit_push.sql (692.25µs)14592026/10/01 10:22:08 goose: up to current file version: 314602026/10/01 10:22:08 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01461--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.05s)1462=== CONT TestMultipartCleanup14632026/10/01 10:22:08 INFO Vacuumed table table=pending_closures14642026/10/01 10:22:08 INFO Vacuumed table table=pending_objects14652026/10/01 10:22:08 INFO Vacuumed table table=multipart_uploads14662026/10/01 10:22:08 INFO Vacuumed table table=closures14672026/10/01 10:22:08 INFO Vacuumed table table=objects1468--- PASS: TestPushWaitsForSweepHoldingRow (1.06s)1469=== CONT TestReadProxyRootRedirectsToIndexHTML1470--- PASS: TestGCSweepSkipsPendingObjects (0.75s)1471=== CONT TestServerTLSConfig1472=== RUN TestServerTLSConfig/no_client_CA1473=== PAUSE TestServerTLSConfig/no_client_CA1474=== RUN TestServerTLSConfig/missing_CA_file1475=== PAUSE TestServerTLSConfig/missing_CA_file1476=== RUN TestServerTLSConfig/not_a_PEM_file1477=== PAUSE TestServerTLSConfig/not_a_PEM_file1478=== CONT TestReadProxyConditionalGet14792026/10/01 10:22:08 OK 20241026095416_initial_model.sql (17.54ms)1480=== NAME TestOrphanedObjectsGC1481 orphaned_objects_gc_test.go:290: GC Test Summary:1482 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1483 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1484 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1485 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)14862026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures1487 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1488--- PASS: TestOrphanedObjectsGC (1.07s)1489=== CONT TestResolveDBConnectionString1490=== RUN TestResolveDBConnectionString/flag_wins1491=== PAUSE TestResolveDBConnectionString/flag_wins1492=== RUN TestResolveDBConnectionString/file_when_flag_empty1493=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1494=== RUN TestResolveDBConnectionString/missing_file_is_an_error1495=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1496=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1497=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1498=== RUN TestResolveDBConnectionString/nothing_configured1499=== PAUSE TestResolveDBConnectionString/nothing_configured1500=== CONT TestReadProxyHead15012026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)15022026-10-01 10:22:08.439 UTC [584] ERROR: relation "goose_db_version" does not exist at character 3615032026-10-01 10:22:08.439 UTC [584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1504--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.70s)1505=== CONT TestService_NativeMTLS15062026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.22ms)15072026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.58ms)15082026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.91ms)15092026-10-01 10:22:08.451 UTC [590] ERROR: relation "goose_db_version" does not exist at character 3615102026-10-01 10:22:08.451 UTC [590] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15112026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.8ms)15122026/10/01 10:22:08 INFO Received push request method=POST path=/api/pushes15132026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.75ms)15142026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000015152026/10/01 10:22:08 OK 1_commit_pending_closure.sql (3.11ms)15162026/10/01 10:22:08 OK 20241026095416_initial_model.sql (13.31ms)15172026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.98ms)15182026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)15192026/10/01 10:22:08 OK 3_commit_push.sql (1.55ms)15202026/10/01 10:22:08 goose: up to current file version: 315212026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.46ms)15222026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.88ms)15232026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.97ms)15242026/10/01 10:22:08 INFO Received complete push request method=POST path=/api/pushes/1/complete15252026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)15262026/10/01 10:22:08 INFO Received push request method=POST path=/api/pushes15272026/10/01 10:22:08 OK 20251218171726_add_pins.sql (9.3ms)15282026/10/01 10:22:08 OK 20260905000000_add_claims.sql (11.22ms)15292026/10/01 10:22:08 INFO Received push request method=POST path=/api/pushes15302026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.42ms)15312026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (5.63ms)15322026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.55ms)15332026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000015342026/10/01 10:22:08 OK 20260905000000_add_claims.sql (4.18ms)15352026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.92ms)15362026-10-01 10:22:08.494 UTC [592] ERROR: relation "goose_db_version" does not exist at character 3615372026-10-01 10:22:08.494 UTC [592] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15382026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.91ms)15392026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.07ms)15402026/10/01 10:22:08 OK 3_commit_push.sql (1.54ms)15412026/10/01 10:22:08 goose: up to current file version: 315422026/10/01 10:22:08 INFO Received push request method=POST path=/api/pushes15432026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.47ms)15442026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000015452026-10-01 10:22:08.498 UTC [595] ERROR: relation "goose_db_version" does not exist at character 3615462026-10-01 10:22:08.498 UTC [595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15472026/10/01 10:22:08 INFO Received complete push request method=POST path=/api/pushes/1/complete15482026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.38ms)15492026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.07ms)15502026/10/01 10:22:08 OK 3_commit_push.sql (1.32ms)15512026/10/01 10:22:08 goose: up to current file version: 315522026-10-01 10:22:08.508 UTC [596] ERROR: relation "goose_db_version" does not exist at character 3615532026-10-01 10:22:08.508 UTC [596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1554--- PASS: TestPush_CompleteCommitsEveryRoot (0.70s)1555=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock15562026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.44ms)15572026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)1558--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.70s)1559=== CONT TestMetricsInventory15602026/10/01 10:22:08 OK 20241026095416_initial_model.sql (12.58ms)15612026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.2ms)15622026-10-01 10:22:08.518 UTC [600] ERROR: relation "goose_db_version" does not exist at character 3615632026-10-01 10:22:08.518 UTC [600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15642026-10-01 10:22:08.519 UTC [601] ERROR: relation "goose_db_version" does not exist at character 3615652026-10-01 10:22:08.519 UTC [601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15662026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)15672026-10-01 10:22:08.522 UTC [603] ERROR: relation "goose_db_version" does not exist at character 3615682026-10-01 10:22:08.522 UTC [603] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)15702026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.79ms)15712026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.48ms)15722026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.91ms)15732026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)15742026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.83ms)15752026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.83ms)15762026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.83ms)15772026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.06ms)15782026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000015792026/10/01 10:22:08 OK 20260905000000_add_claims.sql (4.72ms)15802026/10/01 10:22:08 OK 20241026095416_initial_model.sql (9.5ms)1581--- PASS: TestReadRedirectUsesPublicS3URL (0.68s)1582=== CONT TestReadProxyInvalidPath15832026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)15842026/10/01 10:22:08 OK 1_commit_pending_closure.sql (3.5ms)15852026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)15862026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.62ms)15872026/10/01 10:22:08 OK 20241026095416_initial_model.sql (12.44ms)15882026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.67ms)15892026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.48ms)15902026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000015912026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.15ms)15922026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.56ms)15932026/10/01 10:22:08 OK 3_commit_push.sql (1.25ms)15942026/10/01 10:22:08 goose: up to current file version: 315952026/10/01 10:22:08 OK 20260905000000_add_claims.sql (4.08ms)15962026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.78ms)15972026/10/01 10:22:08 OK 1_commit_pending_closure.sql (1.91ms)15982026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.57ms)15992026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)16002026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.02ms)16012026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.44ms)16022026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.67ms)16032026/10/01 10:22:08 OK 3_commit_push.sql (1.54ms)16042026/10/01 10:22:08 goose: up to current file version: 316052026/10/01 10:22:08 INFO Aborted multipart uploads count=0 kept=016062026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.11ms)16072026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000016082026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.66ms)16092026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.37ms)16102026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)16112026/10/01 10:22:08 WARN Force mode enabled - objects will be deleted immediately without grace period16122026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.71ms)16132026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.46ms)16142026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.53ms)16152026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)16162026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.25ms)1617--- PASS: TestReadProxyRangeRequest (0.68s)1618=== CONT TestClientFallsBackToClosures16192026/10/01 10:22:08 OK 3_commit_push.sql (2.17ms)16202026/10/01 10:22:08 goose: up to current file version: 316212026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.97ms)16222026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000016232026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.29ms)16242026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.47ms)16252026/10/01 10:22:08 OK 1_commit_pending_closure.sql (8.19ms)16262026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (7.69ms)16272026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000016282026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.75ms)16292026/10/01 10:22:08 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=016302026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (9.46ms)16312026/10/01 10:22:08 OK 3_commit_push.sql (1.23ms)16322026/10/01 10:22:08 goose: up to current file version: 316332026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.46ms)16342026/10/01 10:22:08 INFO Vacuumed table table=pending_closures16352026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.49ms)16362026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.23ms)16372026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000016382026/10/01 10:22:08 OK 3_commit_push.sql (1.86ms)16392026/10/01 10:22:08 goose: up to current file version: 316402026/10/01 10:22:08 INFO Vacuumed table table=pending_objects16412026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.51ms)16422026/10/01 10:22:08 INFO Vacuumed table table=multipart_uploads16432026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.33ms)16442026/10/01 10:22:08 OK 3_commit_push.sql (1.6ms)16452026/10/01 10:22:08 goose: up to current file version: 316462026/10/01 10:22:08 INFO Vacuumed table table=closures16472026/10/01 10:22:08 INFO Vacuumed table table=objects16482026/10/01 10:22:08 INFO Received complete push request method=POST path=/api/pushes/2/complete1649--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.79s)1650=== CONT TestNARDeduplicationMetadataUploadBug16512026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures16522026-10-01 10:22:08.588 UTC [610] ERROR: relation "goose_db_version" does not exist at character 3616532026-10-01 10:22:08.588 UTC [610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16542026-10-01 10:22:08.606 UTC [613] ERROR: relation "goose_db_version" does not exist at character 3616552026-10-01 10:22:08.606 UTC [613] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16562026/10/01 10:22:08 OK 20241026095416_initial_model.sql (16.31ms)1657--- PASS: TestReadRedirectKeepsNarinfoProxied (0.67s)1658=== CONT TestReadProxy40416592026-10-01 10:22:08.624 UTC [615] ERROR: relation "goose_db_version" does not exist at character 3616602026-10-01 10:22:08.624 UTC [615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16612026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (17.36ms)16622026/10/01 10:22:08 OK 20241026095416_initial_model.sql (14.79ms)16632026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.58ms)16642026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2ms)16652026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.36ms)16662026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)16672026-10-01 10:22:08.642 UTC [617] ERROR: relation "goose_db_version" does not exist at character 3616682026-10-01 10:22:08.642 UTC [617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16692026/10/01 10:22:08 INFO Aborted multipart uploads count=0 kept=016702026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (13.22ms)16712026/10/01 10:22:08 OK 20241026095416_initial_model.sql (19.39ms)16722026/10/01 10:22:08 OK 20260905000000_add_claims.sql (12.56ms)16732026/10/01 10:22:08 WARN Force mode enabled - objects will be deleted immediately without grace period16742026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)16752026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.92ms)16762026/10/01 10:22:08 OK 20260905000000_add_claims.sql (4.21ms)16772026/10/01 10:22:08 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016782026/10/01 10:22:08 INFO Vacuumed table table=pending_closures16792026/10/01 10:22:08 INFO Vacuumed table table=pending_objects16802026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.5ms)16812026/10/01 10:22:08 OK 20251218171726_add_pins.sql (4.27ms)16822026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.79ms)16832026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000016842026/10/01 10:22:08 INFO Vacuumed table table=multipart_uploads16852026/10/01 10:22:08 INFO Vacuumed table table=closures16862026/10/01 10:22:08 INFO Vacuumed table table=objects16872026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.17ms)16882026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000016892026/10/01 10:22:08 INFO Aborted multipart uploads count=0 kept=016902026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.79ms)16912026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)16922026/10/01 10:22:08 OK 2_object_stats_trigger.sql (923.53µs)16932026/10/01 10:22:08 OK 1_commit_pending_closure.sql (1.85ms)16942026/10/01 10:22:08 OK 3_commit_push.sql (1.52ms)16952026/10/01 10:22:08 goose: up to current file version: 31696--- PASS: TestGCMetrics (0.71s)1697=== CONT TestClientPushesUseOnePush16982026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.01ms)16992026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.51ms)17002026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.6ms)17012026/10/01 10:22:08 OK 3_commit_push.sql (1.65ms)17022026/10/01 10:22:08 goose: up to current file version: 317032026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)17042026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.65ms)17052026/10/01 10:22:08 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=017062026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.44ms)17072026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.2ms)17082026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000017092026/10/01 10:22:08 INFO Vacuumed table table=pending_closures17102026-10-01 10:22:08.672 UTC [621] ERROR: relation "goose_db_version" does not exist at character 3617112026-10-01 10:22:08.672 UTC [621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17122026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.1ms)17132026/10/01 10:22:08 INFO Vacuumed table table=pending_objects17142026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.27ms)17152026/10/01 10:22:08 INFO Vacuumed table table=multipart_uploads17162026/10/01 10:22:08 OK 2_object_stats_trigger.sql (884.67µs)17172026/10/01 10:22:08 OK 3_commit_push.sql (1.58ms)17182026/10/01 10:22:08 goose: up to current file version: 317192026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.2ms)17202026/10/01 10:22:08 INFO Vacuumed table table=closures17212026/10/01 10:22:08 INFO Vacuumed table table=objects17222026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.99ms)1723--- PASS: TestObjectStatsTrigger (0.70s)1724=== CONT TestCreatePendingClosureRejectsOversizedNAR17252026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures1726--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1727=== CONT TestReadProxyNarStreaming17282026/10/01 10:22:08 INFO Aborted multipart uploads count=0 kept=017292026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (3.2ms)17302026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000017312026/10/01 10:22:08 WARN Force mode enabled - objects will be deleted immediately without grace period17322026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.18ms)17332026/10/01 10:22:08 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017342026/10/01 10:22:08 OK 2_object_stats_trigger.sql (2.02ms)17352026/10/01 10:22:08 INFO Vacuumed table table=pending_closures17362026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.44ms)17372026/10/01 10:22:08 OK 3_commit_push.sql (2.04ms)17382026/10/01 10:22:08 goose: up to current file version: 317392026/10/01 10:22:08 INFO Vacuumed table table=pending_objects17402026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)17412026/10/01 10:22:08 INFO Vacuumed table table=multipart_uploads17422026/10/01 10:22:08 INFO Vacuumed table table=closures17432026/10/01 10:22:08 INFO Vacuumed table table=objects17442026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.79ms)1745--- PASS: TestPushDedupSurvivesConcurrentGC (0.82s)1746=== CONT TestPinProtectsFromGC17472026-10-01 10:22:08.700 UTC [625] ERROR: relation "goose_db_version" does not exist at character 3617482026-10-01 10:22:08.700 UTC [625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17492026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.8ms)17502026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.72ms)17512026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.77ms)17522026/10/01 10:22:08 INFO lead: acquired remote=192.0.2.1:123417532026/10/01 10:22:08 INFO lead: released remote=192.0.2.1:12341754--- PASS: TestLeadEndsOnShutdown (0.69s)1755=== CONT TestCacheConfigHandlerMaxNarSize1756--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1757=== CONT TestReadProxyNarinfoAlreadyDecompressed17582026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.82ms)17592026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000017602026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.46ms)17612026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.49ms)17622026/10/01 10:22:08 OK 3_commit_push.sql (1.35ms)17632026/10/01 10:22:08 goose: up to current file version: 317642026/10/01 10:22:08 OK 20241026095416_initial_model.sql (12.1ms)17652026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)17662026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.86ms)17672026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures17682026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)17692026/10/01 10:22:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17702026/10/01 10:22:08 OK 20260905000000_add_claims.sql (8.9ms)17712026-10-01 10:22:08.741 UTC [630] ERROR: relation "goose_db_version" does not exist at character 3617722026-10-01 10:22:08.741 UTC [630] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17732026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.12ms)17742026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.3ms)17752026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000017762026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures17772026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.26ms)17782026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.8ms)17792026/10/01 10:22:08 OK 3_commit_push.sql (1.44ms)17802026/10/01 10:22:08 goose: up to current file version: 317812026/10/01 10:22:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLjMyYTY1ZDcwLWRiZDgtNDBiZC1hOTQzLWIyN2FmODNlYzRiZXgxNzkwODUwMTI4MDQzMTk2MDQ1 parts=1217822026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures17832026/10/01 10:22:08 INFO Received cleanup request method=DELETE path=/api/pending_closures17842026-10-01 10:22:08.755 UTC [631] ERROR: relation "goose_db_version" does not exist at character 3617852026-10-01 10:22:08.755 UTC [631] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1786--- PASS: TestReadRedirectNar (0.42s)1787=== CONT TestClientSharedPathCommittedMidPush17882026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.02ms)17892026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures17902026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)17912026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.25ms)17922026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)17932026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.02ms)17942026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures17952026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.31ms)17962026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (1.81ms)17972026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)17982026-10-01 10:22:08.775 UTC [634] ERROR: relation "goose_db_version" does not exist at character 3617992026-10-01 10:22:08.775 UTC [634] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18002026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.94ms)18012026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000018022026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.43ms)18032026/10/01 10:22:08 OK 1_commit_pending_closure.sql (1.93ms)18042026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.86ms)18052026/10/01 10:22:08 OK 3_commit_push.sql (1.26ms)18062026/10/01 10:22:08 goose: up to current file version: 318072026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.35ms)18082026-10-01 10:22:08.782 UTC [635] ERROR: relation "goose_db_version" does not exist at character 3618092026-10-01 10:22:08.782 UTC [635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18102026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.91ms)18112026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.94ms)1812--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.43s)1813=== CONT TestReadProxyNarinfo18142026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.31ms)18152026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000018162026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.79ms)18172026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.19ms)18182026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)18192026/10/01 10:22:08 INFO lead: acquired remote=192.0.2.1:123418202026/10/01 10:22:08 OK 2_object_stats_trigger.sql (944.37µs)18212026/10/01 10:22:08 OK 3_commit_push.sql (1.14ms)18222026/10/01 10:22:08 goose: up to current file version: 318232026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.21ms)18242026/10/01 10:22:08 OK 20241026095416_initial_model.sql (9.88ms)18252026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)18262026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)18272026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.34ms)18282026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.49ms)18292026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.99ms)18302026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.1ms)18312026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.03ms)18322026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000018332026/10/01 10:22:08 OK 20260905000000_add_claims.sql (2.99ms)18342026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.86ms)18352026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.95ms)18362026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.5ms)1837--- PASS: TestReadProxyDisabled (0.41s)1838=== CONT TestGenerateLandingPage18392026/10/01 10:22:08 OK 3_commit_push.sql (1.74ms)18402026/10/01 10:22:08 goose: up to current file version: 318412026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.53ms)18422026/10/01 10:22:08 goose: successfully migrated database to version: 202609231200001843--- PASS: TestGenerateLandingPage (0.00s)1844=== CONT TestClientWithDependencies18452026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.25ms)18462026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.23ms)18472026/10/01 10:22:08 OK 3_commit_push.sql (1.29ms)18482026/10/01 10:22:08 goose: up to current file version: 318492026-10-01 10:22:08.832 UTC [641] ERROR: relation "goose_db_version" does not exist at character 3618502026-10-01 10:22:08.832 UTC [641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18512026/10/01 10:22:08 INFO Received uploads request method=POST path=/api/pending_closures18522026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.45ms)1853--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.43s)1854=== CONT TestIsValidCachePath1855=== RUN TestIsValidCachePath/narinfo1856=== PAUSE TestIsValidCachePath/narinfo1857=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1858=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1859=== RUN TestIsValidCachePath/nar_zst1860=== PAUSE TestIsValidCachePath/nar_zst1861=== RUN TestIsValidCachePath/nar_xz1862=== PAUSE TestIsValidCachePath/nar_xz1863=== RUN TestIsValidCachePath/nar_bz21864=== PAUSE TestIsValidCachePath/nar_bz21865=== RUN TestIsValidCachePath/nar_uncompressed1866=== PAUSE TestIsValidCachePath/nar_uncompressed1867=== RUN TestIsValidCachePath/ls1868=== PAUSE TestIsValidCachePath/ls1869=== RUN TestIsValidCachePath/log1870=== PAUSE TestIsValidCachePath/log1871=== RUN TestIsValidCachePath/realisation1872=== PAUSE TestIsValidCachePath/realisation1873=== RUN TestIsValidCachePath/nix-cache-info1874=== PAUSE TestIsValidCachePath/nix-cache-info1875=== RUN TestIsValidCachePath/index.html1876=== PAUSE TestIsValidCachePath/index.html1877=== RUN TestIsValidCachePath/traversal_parent1878=== PAUSE TestIsValidCachePath/traversal_parent1879=== RUN TestIsValidCachePath/traversal_in_middle1880=== PAUSE TestIsValidCachePath/traversal_in_middle1881=== RUN TestIsValidCachePath/invalid_char_e1882=== PAUSE TestIsValidCachePath/invalid_char_e1883=== RUN TestIsValidCachePath/invalid_char_u1884=== PAUSE TestIsValidCachePath/invalid_char_u1885=== RUN TestIsValidCachePath/random_path1886=== PAUSE TestIsValidCachePath/random_path1887=== RUN TestIsValidCachePath/empty1888=== PAUSE TestIsValidCachePath/empty1889=== RUN TestIsValidCachePath/leading_slash1890=== PAUSE TestIsValidCachePath/leading_slash1891=== RUN TestIsValidCachePath/wrong_extension1892=== PAUSE TestIsValidCachePath/wrong_extension1893=== RUN TestIsValidCachePath/short_hash1894=== PAUSE TestIsValidCachePath/short_hash1895=== CONT TestService_readinessHandler18962026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)18972026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.61ms)18982026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.85ms)18992026-10-01 10:22:08.864 UTC [643] ERROR: relation "goose_db_version" does not exist at character 3619002026-10-01 10:22:08.864 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19012026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.26ms)19022026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.75ms)19032026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.25ms)19042026/10/01 10:22:08 goose: successfully migrated database to version: 202609231200001905--- PASS: TestReadProxyHead (0.44s)1906=== CONT TestClientMultipleUploads19072026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.86ms)19082026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.12ms)19092026/10/01 10:22:08 OK 3_commit_push.sql (996.45µs)19102026/10/01 10:22:08 goose: up to current file version: 319112026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.29ms)19122026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)19132026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.3ms)19142026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.57ms)19152026-10-01 10:22:08.890 UTC [647] ERROR: relation "goose_db_version" does not exist at character 3619162026-10-01 10:22:08.890 UTC [647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19172026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.2ms)19182026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (3.75ms)1919--- PASS: TestReadProxyConditionalGet (0.47s)1920=== CONT TestService_cleanupPendingClosuresHandler19212026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.3ms)19222026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000019232026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.35ms)19242026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.67ms)19252026/10/01 10:22:08 OK 3_commit_push.sql (1.24ms)19262026/10/01 10:22:08 goose: up to current file version: 319272026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.03ms)19282026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)19292026/10/01 10:22:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19302026/10/01 10:22:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1931--- PASS: TestService_NativeMTLS (0.47s)1932=== CONT TestClientIntegration1933--- PASS: TestGCBugBareHashReferences (0.92s)1934=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT19352026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.45ms)19362026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)19372026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.43ms)19382026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.47ms)19392026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.27ms)19402026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000019412026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.29ms)19422026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.36ms)19432026/10/01 10:22:08 OK 3_commit_push.sql (1.32ms)19442026/10/01 10:22:08 goose: up to current file version: 319452026-10-01 10:22:08.933 UTC [654] ERROR: relation "goose_db_version" does not exist at character 3619462026-10-01 10:22:08.933 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19472026/10/01 10:22:08 INFO lead: released remote=192.0.2.1:123419482026/10/01 10:22:08 INFO Received cleanup request method=DELETE path=/api/pending_closures19492026/10/01 10:22:08 OK 20241026095416_initial_model.sql (10.85ms)19502026/10/01 10:22:08 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket47/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""19512026/10/01 10:22:08 INFO Aborted multipart uploads count=0 kept=119522026-10-01 10:22:08.955 UTC [655] ERROR: relation "goose_db_version" does not exist at character 3619532026-10-01 10:22:08.955 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19542026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)19552026/10/01 10:22:08 INFO Received cleanup request method=DELETE path=/api/pending_closures19562026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.54ms)19572026/10/01 10:22:08 INFO Aborted multipart uploads count=1 kept=019582026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)1959--- PASS: TestMultipartCleanup (0.55s)1960=== CONT TestIsValidUploadKey1961=== RUN TestIsValidUploadKey/narinfo1962=== PAUSE TestIsValidUploadKey/narinfo1963=== RUN TestIsValidUploadKey/nar_zst1964=== PAUSE TestIsValidUploadKey/nar_zst1965=== RUN TestIsValidUploadKey/nar_xz1966=== PAUSE TestIsValidUploadKey/nar_xz1967=== RUN TestIsValidUploadKey/nar_plain1968=== PAUSE TestIsValidUploadKey/nar_plain1969=== RUN TestIsValidUploadKey/listing1970=== PAUSE TestIsValidUploadKey/listing1971=== RUN TestIsValidUploadKey/build_log1972=== PAUSE TestIsValidUploadKey/build_log1973=== RUN TestIsValidUploadKey/build_log_home-manager_file1974=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1975=== RUN TestIsValidUploadKey/build_log_plus_in_name1976=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1977=== RUN TestIsValidUploadKey/build_log_question_mark1978=== PAUSE TestIsValidUploadKey/build_log_question_mark1979=== RUN TestIsValidUploadKey/build_log_equals1980=== PAUSE TestIsValidUploadKey/build_log_equals1981=== RUN TestIsValidUploadKey/realisation1982=== PAUSE TestIsValidUploadKey/realisation1983=== RUN TestIsValidUploadKey/realisation_plus_in_output1984=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1985=== RUN TestIsValidUploadKey/nix-cache-info1986=== PAUSE TestIsValidUploadKey/nix-cache-info1987=== RUN TestIsValidUploadKey/index.html1988=== PAUSE TestIsValidUploadKey/index.html1989=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1990=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1991=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1992=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1993=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1994=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1995=== RUN TestIsValidUploadKey/traversal1996=== PAUSE TestIsValidUploadKey/traversal1997=== RUN TestIsValidUploadKey/traversal_nar1998=== PAUSE TestIsValidUploadKey/traversal_nar1999=== RUN TestIsValidUploadKey/absolute2000=== PAUSE TestIsValidUploadKey/absolute2001=== RUN TestIsValidUploadKey/empty_key2002=== PAUSE TestIsValidUploadKey/empty_key2003=== RUN TestIsValidUploadKey/unknown_type2004=== PAUSE TestIsValidUploadKey/unknown_type2005=== CONT TestClientErrorHandling2006=== RUN TestClientErrorHandling/InvalidStorePath2007=== PAUSE TestClientErrorHandling/InvalidStorePath2008=== RUN TestClientErrorHandling/InvalidAuthToken2009=== PAUSE TestClientErrorHandling/InvalidAuthToken2010=== RUN TestClientErrorHandling/ServerNotAvailable2011=== PAUSE TestClientErrorHandling/ServerNotAvailable2012=== CONT TestCompleteMultipartUnregistered20132026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.23ms)2014--- PASS: TestMetricsInventory (0.45s)2015=== CONT TestUploadHandlersRejectOversizedBody20162026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.64ms)20172026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.45ms)20182026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000020192026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.13ms)20202026-10-01 10:22:08.974 UTC [657] ERROR: relation "goose_db_version" does not exist at character 3620212026-10-01 10:22:08.974 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20222026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.7ms)20232026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)2024--- PASS: TestReadProxyInvalidPath (0.44s)2025=== CONT TestClientCADerivations20262026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.27ms)20272026/10/01 10:22:08 OK 3_commit_push.sql (1.47ms)20282026/10/01 10:22:08 goose: up to current file version: 320292026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.47ms)20302026/10/01 10:22:08 OK 20260628120000_add_object_size_and_stats.sql (3.18ms)20312026/10/01 10:22:08 OK 20260905000000_add_claims.sql (3.33ms)20322026/10/01 10:22:08 OK 20260920000000_drop_claims.sql (2.79ms)20332026-10-01 10:22:08.990 UTC [661] ERROR: relation "goose_db_version" does not exist at character 3620342026-10-01 10:22:08.990 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20352026-10-01 10:22:08.991 UTC [662] ERROR: relation "goose_db_version" does not exist at character 3620362026-10-01 10:22:08.991 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20372026/10/01 10:22:08 OK 20260923120000_add_pushes.sql (2.59ms)20382026/10/01 10:22:08 goose: successfully migrated database to version: 2026092312000020392026/10/01 10:22:08 OK 20241026095416_initial_model.sql (11.97ms)20402026/10/01 10:22:08 INFO lead: acquired remote=192.0.2.1:123420412026/10/01 10:22:08 OK 1_commit_pending_closure.sql (2.94ms)20422026/10/01 10:22:08 OK 20251210153512_drop_unused_gin_index.sql (2.53ms)20432026/10/01 10:22:08 OK 2_object_stats_trigger.sql (1.63ms)20442026/10/01 10:22:08 OK 3_commit_push.sql (1.13ms)20452026/10/01 10:22:08 goose: up to current file version: 320462026/10/01 10:22:08 INFO lead: released remote=192.0.2.1:12342047--- PASS: TestLeadElectsOneAndHandsOver (0.63s)2048=== CONT TestUploadHandlersRejectInvalidKeys2049=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2050=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2051=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2052=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2053=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2054=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2055=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2056=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2057=== CONT TestService_verifyS3Integrity20582026/10/01 10:22:08 OK 20251218171726_add_pins.sql (3.63ms)20592026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.7ms)20602026/10/01 10:22:09 OK 20260905000000_add_claims.sql (9.07ms)20612026/10/01 10:22:09 OK 20241026095416_initial_model.sql (17.21ms)20622026/10/01 10:22:09 OK 20241026095416_initial_model.sql (17.2ms)20632026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.89ms)20642026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)20652026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)20662026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.74ms)20672026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000020682026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.11ms)20692026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.36ms)20702026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.02ms)20712026/10/01 10:22:09 OK 2_object_stats_trigger.sql (2.6ms)20722026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.71ms)20732026/10/01 10:22:09 OK 3_commit_push.sql (2.1ms)20742026/10/01 10:22:09 goose: up to current file version: 320752026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.79ms)20762026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.64ms)20772026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.56ms)20782026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.86ms)20792026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.82ms)20802026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.63ms)20812026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000020822026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.86ms)20832026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000020842026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.43ms)20852026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.49ms)20862026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.39ms)20872026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.48ms)20882026/10/01 10:22:09 OK 3_commit_push.sql (1.3ms)20892026/10/01 10:22:09 goose: up to current file version: 320902026/10/01 10:22:09 OK 3_commit_push.sql (1.04ms)20912026/10/01 10:22:09 goose: up to current file version: 320922026-10-01 10:22:09.044 UTC [684] ERROR: relation "goose_db_version" does not exist at character 3620932026-10-01 10:22:09.044 UTC [684] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20942026-10-01 10:22:09.053 UTC [686] ERROR: relation "goose_db_version" does not exist at character 3620952026-10-01 10:22:09.053 UTC [686] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20962026/10/01 10:22:09 OK 20241026095416_initial_model.sql (8.88ms)20972026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)2098=== NAME TestNARDeduplicationMetadataUploadBug2099 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3238808964/001/store/v7c5yz2i35mgv8xx61cz2a8bwc9423x5-file1.txt21002026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.58ms)2101--- PASS: TestReadProxy404 (0.45s)2102=== CONT TestCacheStatsHandler21032026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)21042026/10/01 10:22:09 OK 20241026095416_initial_model.sql (11.1ms)21052026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.27ms)21062026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)21072026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.44ms)21082026/10/01 10:22:09 OK 20251218171726_add_pins.sql (2.9ms)21092026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (1.45ms)21102026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000021112026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.37ms)21122026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)21132026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.54ms)21142026/10/01 10:22:09 OK 3_commit_push.sql (1.19ms)21152026/10/01 10:22:09 goose: up to current file version: 321162026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.77ms)21172026-10-01 10:22:09.084 UTC [723] ERROR: relation "goose_db_version" does not exist at character 3621182026-10-01 10:22:09.084 UTC [723] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21192026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.37ms)21202026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.58ms)21212026/10/01 10:22:09 goose: successfully migrated database to version: 202609231200002122--- PASS: TestReadProxyNarStreaming (0.41s)2123=== CONT TestService_createPendingClosureHandler21242026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.69ms)21252026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.42ms)21262026/10/01 10:22:09 OK 3_commit_push.sql (1.94ms)21272026/10/01 10:22:09 goose: up to current file version: 321282026/10/01 10:22:09 OK 20241026095416_initial_model.sql (9.09ms)21292026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)21302026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.55ms)21312026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (10.39ms)2132=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure2133=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure2134=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart2135=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart2136=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts2137=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts2138=== CONT TestCacheConfigHandler2139=== RUN TestCacheConfigHandler/full_config,_no_issuer2140=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2141=== RUN TestCacheConfigHandler/no_cache_url_configured2142=== PAUSE TestCacheConfigHandler/no_cache_url_configured2143=== RUN TestCacheConfigHandler/no_signing_keys2144=== PAUSE TestCacheConfigHandler/no_signing_keys2145=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2146=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2147=== CONT TestGracefulShutdownDrainsInflight21482026/10/01 10:22:09 INFO Starting HTTP server address=127.0.0.1:4670721492026/10/01 10:22:09 INFO Shutdown signal received, draining in-flight requests timeout=10s21502026/10/01 10:22:09 OK 20260905000000_add_claims.sql (4.33ms)21512026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.81ms)21522026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.61ms)21532026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000021542026/10/01 10:22:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21552026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.4ms)21562026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.54ms)21572026/10/01 10:22:09 OK 3_commit_push.sql (1.17ms)21582026/10/01 10:22:09 goose: up to current file version: 32159--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.42s)2160=== CONT TestService_healthCheckHandler21612026/10/01 10:22:09 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLjdmODExMWUyLWJkMTMtNDc0My1hN2FiLWJhNjhhMTgyNWViN3gxNzkwODUwMTI4NzYyMTUxMTc3 error="Get \"http://127.0.0.1:1/bucket25/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"21622026/10/01 10:22:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLjQ0MDYzNmRiLWFiNzktNDIwNi1iNmFiLTdmMGNkYjAwYWYxZngxNzkwODUwMTI4NzU1ODYwOTQw parts=1221632026-10-01 10:22:09.142 UTC [802] ERROR: relation "goose_db_version" does not exist at character 3621642026-10-01 10:22:09.142 UTC [802] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21652026/10/01 10:22:09 INFO Received cleanup request method=DELETE path=/api/pending_closures21662026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes21672026/10/01 10:22:09 INFO Aborted multipart uploads count=1 kept=021682026/10/01 10:22:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21692026/10/01 10:22:09 INFO Uploading v7c5yz2i35mgv8xx61cz2a8bwc9423x5-file1.txt (160B)2170--- PASS: TestRedundantMultipartUpload (1.78s)2171=== CONT TestService_ReadScope_PublicByDefault21722026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"21732026/10/01 10:22:09 WARN Failed to register uploaded object key=v7c5yz2i35mgv8xx61cz2a8bwc9423x5.ls error="server returned 404: 404 page not found\n"21742026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21752026/10/01 10:22:09 INFO Signed narinfos id=1 count=121762026/10/01 10:22:09 INFO Uploading 1 narinfos21772026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete21782026/10/01 10:22:09 WARN Failed to register uploaded object key=v7c5yz2i35mgv8xx61cz2a8bwc9423x5.narinfo error="server returned 404: 404 page not found\n"21792026/10/01 10:22:09 OK 20241026095416_initial_model.sql (10.58ms)21802026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)21812026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.25ms)21822026/10/01 10:22:09 INFO Upload complete. (62ms)2183=== NAME TestNARDeduplicationMetadataUploadBug2184 metadata_upload_test.go:54: Retrieved narinfo from S3:2185 StorePath: /build/TestNARDeduplicationMetadataUploadBug3238808964/001/store/v7c5yz2i35mgv8xx61cz2a8bwc9423x5-file1.txt2186 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2187 Compression: zstd2188 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2189 NarSize: 1602190 References: 2191 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf21922026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (3.74ms)2193 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2194 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2195 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}21962026-10-01 10:22:09.171 UTC [858] ERROR: relation "goose_db_version" does not exist at character 3621972026-10-01 10:22:09.171 UTC [858] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21982026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.55ms)21992026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.77ms)22002026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.35ms)22012026/10/01 10:22:09 goose: successfully migrated database to version: 202609231200002202--- PASS: TestReadProxyNarinfo (0.39s)2203=== CONT TestPendingClosureWriteTimeout2204=== RUN TestPendingClosureWriteTimeout/empty2205=== PAUSE TestPendingClosureWriteTimeout/empty2206=== RUN TestPendingClosureWriteTimeout/400_objects2207=== PAUSE TestPendingClosureWriteTimeout/400_objects2208=== RUN TestPendingClosureWriteTimeout/670k_objects2209=== PAUSE TestPendingClosureWriteTimeout/670k_objects2210=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline2211=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline2212=== CONT TestService_RequireScope_OIDC2213=== NAME TestPinProtectsFromGC2214 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC256780221/001/store/7cb26ivxy2gf7z397wmc1c33kk2njgma-pinned-file.txt2215 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC256780221/001/store/sa0pl5fhn031x6hgwxn1z18kblk7b5nz-unpinned-file.txt22162026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.49ms)22172026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.27ms)22182026/10/01 10:22:09 OK 3_commit_push.sql (1.2ms)22192026/10/01 10:22:09 goose: up to current file version: 322202026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures2221--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2222=== CONT TestProxyWriteTimeout2223=== RUN TestProxyWriteTimeout/narinfo2224=== PAUSE TestProxyWriteTimeout/narinfo2225=== RUN TestProxyWriteTimeout/1_GiB_nar2226=== PAUSE TestProxyWriteTimeout/1_GiB_nar2227=== RUN TestProxyWriteTimeout/10_GiB_nar2228=== PAUSE TestProxyWriteTimeout/10_GiB_nar2229=== RUN TestProxyWriteTimeout/unknown_size2230=== PAUSE TestProxyWriteTimeout/unknown_size2231=== CONT TestService_AuthMiddleware_OIDC22322026/10/01 10:22:09 OK 20241026095416_initial_model.sql (11.48ms)22332026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures22342026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)22352026/10/01 10:22:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22362026/10/01 10:22:09 INFO Uploading qs8nx6cch1x61n5iiwl8pbzx4smcl0z6-shared-dep (136B)22372026/10/01 10:22:09 INFO Uploading kp5kxqwzz5b5hyq1syzq2w9q76lqcxzv-b (216B)22382026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.64ms)22392026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22402026/10/01 10:22:09 WARN Failed to register uploaded object key=fzip13dkrq4m9gnyszyi2dhbsic2idnf.ls error="server returned 404: 404 page not found\n"22412026/10/01 10:22:09 WARN Failed to register uploaded object key=kp5kxqwzz5b5hyq1syzq2w9q76lqcxzv.ls error="server returned 404: 404 page not found\n"22422026/10/01 10:22:09 WARN Failed to register uploaded object key=qs8nx6cch1x61n5iiwl8pbzx4smcl0z6.ls error="server returned 404: 404 page not found\n"22432026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22442026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/14ry5z75jm4n6hjfv2acapq7kfq4yl70ppxx1qnrccha32kdfgw2.nar.zst error="server returned 404: 404 page not found\n"22452026/10/01 10:22:09 INFO Signed narinfos id=1 count=222462026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22472026/10/01 10:22:09 INFO Signed narinfos id=2 count=222482026/10/01 10:22:09 INFO Uploading 4 narinfos22492026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (3.85ms)22502026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.72ms)22512026/10/01 10:22:09 WARN Failed to register uploaded object key=qs8nx6cch1x61n5iiwl8pbzx4smcl0z6.narinfo error="server returned 404: 404 page not found\n"22522026/10/01 10:22:09 WARN Failed to register uploaded object key=kp5kxqwzz5b5hyq1syzq2w9q76lqcxzv.narinfo error="server returned 404: 404 page not found\n"22532026/10/01 10:22:09 WARN Failed to register uploaded object key=fzip13dkrq4m9gnyszyi2dhbsic2idnf.narinfo error="server returned 404: 404 page not found\n"2254=== NAME TestNARDeduplicationMetadataUploadBug2255 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3238808964/001/store/20hbah13fzpzz3j81bvxx7vnxjzwvi20-file2.txt22562026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.62ms)22572026/10/01 10:22:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22582026/10/01 10:22:09 WARN Failed to register uploaded object key=qs8nx6cch1x61n5iiwl8pbzx4smcl0z6.narinfo error="server returned 404: 404 page not found\n"22592026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (1.95ms)22602026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000022612026/10/01 10:22:09 WARN readiness check failed error="closed pool"2262--- PASS: TestService_readinessHandler (0.35s)2263=== CONT TestService_AuthMiddleware_MTLSBoundSubjects22642026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.29ms)22652026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.52ms)22662026/10/01 10:22:09 INFO Completed upload id=222672026/10/01 10:22:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22682026-10-01 10:22:09.216 UTC [965] ERROR: relation "goose_db_version" does not exist at character 3622692026-10-01 10:22:09.216 UTC [965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22702026/10/01 10:22:09 OK 3_commit_push.sql (6.44ms)22712026/10/01 10:22:09 goose: up to current file version: 322722026/10/01 10:22:09 INFO Completed upload id=122732026/10/01 10:22:09 INFO Upload complete. (71ms)2274=== NAME TestClientFallsBackToClosures2275 client_pushes_test.go:112: Retrieved narinfo from S3:2276 StorePath: /build/TestClientFallsBackToClosures1033477365/001/store/qs8nx6cch1x61n5iiwl8pbzx4smcl0z6-shared-dep2277 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2278 Compression: zstd2279 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822280 NarSize: 1362281 References: 2282 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2283 client_pushes_test.go:112: Retrieved narinfo from S3:2284 StorePath: /build/TestClientFallsBackToClosures1033477365/001/store/fzip13dkrq4m9gnyszyi2dhbsic2idnf-a2285 URL: nar/14ry5z75jm4n6hjfv2acapq7kfq4yl70ppxx1qnrccha32kdfgw2.nar.zst2286 Compression: zstd2287 NarHash: sha256:14ry5z75jm4n6hjfv2acapq7kfq4yl70ppxx1qnrccha32kdfgw22288 NarSize: 2162289 References: /build/TestClientFallsBackToClosures1033477365/001/store/qs8nx6cch1x61n5iiwl8pbzx4smcl0z6-shared-dep2290 CA: text:sha256:0zvw8y8vga5zs032c1fwda8bsbn0lq0ckfgrxdz0y3i41q2xjsx12291 client_pushes_test.go:112: Retrieved narinfo from S3:2292 StorePath: /build/TestClientFallsBackToClosures1033477365/001/store/kp5kxqwzz5b5hyq1syzq2w9q76lqcxzv-b2293 URL: nar/14ry5z75jm4n6hjfv2acapq7kfq4yl70ppxx1qnrccha32kdfgw2.nar.zst2294 Compression: zstd2295 NarHash: sha256:14ry5z75jm4n6hjfv2acapq7kfq4yl70ppxx1qnrccha32kdfgw22296 NarSize: 2162297 References: /build/TestClientFallsBackToClosures1033477365/001/store/qs8nx6cch1x61n5iiwl8pbzx4smcl0z6-shared-dep2298 CA: text:sha256:0zvw8y8vga5zs032c1fwda8bsbn0lq0ckfgrxdz0y3i41q2xjsx122992026-10-01 10:22:09.228 UTC [1002] ERROR: relation "goose_db_version" does not exist at character 3623002026-10-01 10:22:09.228 UTC [1002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2301--- PASS: TestClientFallsBackToClosures (0.68s)2302=== CONT TestService_ReadAuthMiddleware23032026/10/01 10:22:09 OK 20241026095416_initial_model.sql (9.98ms)23042026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)23052026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.06ms)23062026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes23072026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.96ms)23082026/10/01 10:22:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23092026/10/01 10:22:09 INFO Uploading 3x2qsbqhj3gqf42wrgfzw96k02s3ly83-shared-dep (136B)23102026/10/01 10:22:09 INFO Uploading wk1hdlvqj838bl6mf9lvaxw7acajf67g-b (216B)23112026/10/01 10:22:09 OK 20241026095416_initial_model.sql (11.75ms)23122026/10/01 10:22:09 OK 20260905000000_add_claims.sql (4.3ms)23132026/10/01 10:22:09 INFO Received cleanup request method=DELETE path=/api/pending_closures23142026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes23152026/10/01 10:22:09 INFO Aborted multipart uploads count=0 kept=023162026/10/01 10:22:09 WARN Failed to register uploaded object key=5fcbj6zjy4ikgb1lsgp3x76rc87cpxlb.ls error="server returned 404: 404 page not found\n"23172026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23182026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/0lvv5qwl4nq4x9z673v83c9b0isr3vlrfd325pi7kjsbmvril1d0.nar.zst error="server returned 404: 404 page not found\n"23192026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)23202026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.75ms)23212026/10/01 10:22:09 WARN Failed to register uploaded object key=3x2qsbqhj3gqf42wrgfzw96k02s3ly83.ls error="server returned 404: 404 page not found\n"23222026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23232026/10/01 10:22:09 WARN Failed to register uploaded object key=wk1hdlvqj838bl6mf9lvaxw7acajf67g.ls error="server returned 404: 404 page not found\n"23242026/10/01 10:22:09 INFO Signed narinfos id=1 count=323252026/10/01 10:22:09 INFO Uploading 3 narinfos23262026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures23272026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.49ms)23282026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000023292026/10/01 10:22:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23302026/10/01 10:22:09 INFO Uploading 7cb26ivxy2gf7z397wmc1c33kk2njgma-pinned-file.txt (128B)23312026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.23ms)23322026/10/01 10:22:09 WARN Failed to register uploaded object key=5fcbj6zjy4ikgb1lsgp3x76rc87cpxlb.narinfo error="server returned 404: 404 page not found\n"23332026/10/01 10:22:09 WARN Failed to register uploaded object key=3x2qsbqhj3gqf42wrgfzw96k02s3ly83.narinfo error="server returned 404: 404 page not found\n"23342026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete23352026/10/01 10:22:09 WARN Failed to register uploaded object key=wk1hdlvqj838bl6mf9lvaxw7acajf67g.narinfo error="server returned 404: 404 page not found\n"23362026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.4ms)23372026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.53ms)23382026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"23392026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23402026/10/01 10:22:09 WARN Failed to register uploaded object key=7cb26ivxy2gf7z397wmc1c33kk2njgma.ls error="server returned 404: 404 page not found\n"23412026/10/01 10:22:09 INFO Signed narinfos id=1 count=123422026/10/01 10:22:09 INFO Uploading 1 narinfos23432026/10/01 10:22:09 OK 3_commit_push.sql (1.34ms)23442026/10/01 10:22:09 goose: up to current file version: 323452026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)23462026/10/01 10:22:09 INFO Received cleanup request method=DELETE path=/api/pending_closures23472026/10/01 10:22:09 INFO Upload complete. (56ms)23482026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes2349=== NAME TestClientPushesUseOnePush2350 client_pushes_test.go:97: Retrieved narinfo from S3:2351 StorePath: /build/TestClientPushesUseOnePush3922722924/001/store/3x2qsbqhj3gqf42wrgfzw96k02s3ly83-shared-dep2352 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2353 Compression: zstd2354 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822355 NarSize: 1362356 References: 2357 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n23582026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.04ms)23592026/10/01 10:22:09 INFO Aborted multipart uploads count=1 kept=023602026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete23612026/10/01 10:22:09 WARN Failed to register uploaded object key=7cb26ivxy2gf7z397wmc1c33kk2njgma.narinfo error="server returned 404: 404 page not found\n"2362 client_pushes_test.go:97: Retrieved narinfo from S3:2363 StorePath: /build/TestClientPushesUseOnePush3922722924/001/store/5fcbj6zjy4ikgb1lsgp3x76rc87cpxlb-a2364 URL: nar/0lvv5qwl4nq4x9z673v83c9b0isr3vlrfd325pi7kjsbmvril1d0.nar.zst2365 Compression: zstd2366 NarHash: sha256:0lvv5qwl4nq4x9z673v83c9b0isr3vlrfd325pi7kjsbmvril1d02367 NarSize: 2162368 References: /build/TestClientPushesUseOnePush3922722924/001/store/3x2qsbqhj3gqf42wrgfzw96k02s3ly83-shared-dep2369 CA: text:sha256:13244sdk8h0wbd02n4b7b957g55wngnl3npkwnc14rfja936jyrl23702026/10/01 10:22:09 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)23712026/10/01 10:22:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23722026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.24ms)23732026-10-01 10:22:09.268 UTC [657] ERROR: Closure does not exist: id=123742026-10-01 10:22:09.268 UTC [657] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE23752026-10-01 10:22:09.268 UTC [657] STATEMENT: -- name: CommitPendingClosure :exec2376 SELECT commit_pending_closure($1::bigint)2377 2378--- PASS: TestService_cleanupPendingClosuresHandler (0.37s)2379=== CONT TestService_AuthMiddleware_MTLSProxyHeader2380=== NAME TestClientPushesUseOnePush2381 client_pushes_test.go:97: Retrieved narinfo from S3:2382 StorePath: /build/TestClientPushesUseOnePush3922722924/001/store/wk1hdlvqj838bl6mf9lvaxw7acajf67g-b2383 URL: nar/0lvv5qwl4nq4x9z673v83c9b0isr3vlrfd325pi7kjsbmvril1d0.nar.zst2384 Compression: zstd2385 NarHash: sha256:0lvv5qwl4nq4x9z673v83c9b0isr3vlrfd325pi7kjsbmvril1d02386 NarSize: 2162387 References: /build/TestClientPushesUseOnePush3922722924/001/store/3x2qsbqhj3gqf42wrgfzw96k02s3ly83-shared-dep2388 CA: text:sha256:13244sdk8h0wbd02n4b7b957g55wngnl3npkwnc14rfja936jyrl23892026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.39ms)23902026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000023912026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign23922026/10/01 10:22:09 INFO Upload complete. (56ms)23932026/10/01 10:22:09 WARN Failed to register uploaded object key=20hbah13fzpzz3j81bvxx7vnxjzwvi20.ls error="server returned 404: 404 page not found\n"23942026/10/01 10:22:09 INFO Signed narinfos id=2 count=123952026/10/01 10:22:09 INFO Uploading 1 narinfos23962026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.47ms)2397=== NAME TestClientMultipleUploads2398 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3732926226/001/store/aq05153ryjar67yg70d9cwwziqn0pjg3-test-file-0.txt2399--- PASS: TestClientPushesUseOnePush (0.61s)2400=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows24012026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.55ms)24022026/10/01 10:22:09 OK 3_commit_push.sql (894.11µs)24032026/10/01 10:22:09 goose: up to current file version: 324042026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/2/complete24052026/10/01 10:22:09 WARN Failed to register uploaded object key=20hbah13fzpzz3j81bvxx7vnxjzwvi20.narinfo error="server returned 404: 404 page not found\n"2406=== NAME TestClientWithDependencies2407 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2945781875/001/store/ll4nfjqdfh6g44qyfkaym4zazrk84ihn-test-script24082026/10/01 10:22:09 INFO Upload complete. (42ms)2409=== NAME TestNARDeduplicationMetadataUploadBug2410 metadata_upload_test.go:76: Retrieved narinfo from S3:2411 StorePath: /build/TestNARDeduplicationMetadataUploadBug3238808964/001/store/20hbah13fzpzz3j81bvxx7vnxjzwvi20-file2.txt2412 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2413 Compression: zstd2414 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2415 NarSize: 1602416 References: 2417 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2418 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2419 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2420 {"version":1,"root":{"type":"regular","size":44}}2421--- PASS: TestNARDeduplicationMetadataUploadBug (0.70s)2422=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check24232026-10-01 10:22:09.286 UTC [1153] ERROR: relation "goose_db_version" does not exist at character 3624242026-10-01 10:22:09.286 UTC [1153] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24252026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes24262026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures24272026/10/01 10:22:09 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)24282026/10/01 10:22:09 INFO Uploading qyfzkni9l4xhqcnql4gj375b6k0dkibx-top (216B)24292026/10/01 10:22:09 INFO Uploading b42h8kg54f3294sx0ams5fbv1yrjiaw3-shared-dep (136B)24302026/10/01 10:22:09 WARN Failed to register uploaded object key=qyfzkni9l4xhqcnql4gj375b6k0dkibx.ls error="server returned 404: 404 page not found\n"24312026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24322026/10/01 10:22:09 WARN Failed to register uploaded object key=b42h8kg54f3294sx0ams5fbv1yrjiaw3.ls error="server returned 404: 404 page not found\n"24332026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24342026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/0a6m9fhs3h8h1rgrywnkjiw45abnfcsb9qaikn1fc4ijl8s4r5wr.nar.zst error="server returned 404: 404 page not found\n"24352026/10/01 10:22:09 INFO Signed narinfos id=1 count=224362026/10/01 10:22:09 INFO Uploading 2 narinfos24372026/10/01 10:22:09 OK 20241026095416_initial_model.sql (10.52ms)24382026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete24392026/10/01 10:22:09 WARN Failed to register uploaded object key=b42h8kg54f3294sx0ams5fbv1yrjiaw3.narinfo error="server returned 404: 404 page not found\n"24402026/10/01 10:22:09 WARN Failed to register uploaded object key=qyfzkni9l4xhqcnql4gj375b6k0dkibx.narinfo error="server returned 404: 404 page not found\n"2441--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.39s)2442=== CONT TestParseSingleRange/none2443=== CONT TestParseSingleRange/single_byte2444=== CONT TestParseSingleRange/suffix_exceeds_size2445=== CONT TestParseSingleRange/suffix2446=== CONT TestParseSingleRange/end_clamped_to_size2447=== CONT TestParseSingleRange/open-ended2448=== CONT TestParseSingleRange/closed2449=== CONT TestParseSingleRange/malformed_end_before_start2450=== CONT TestParseSingleRange/start_past_EOF2451=== CONT TestParseSingleRange/malformed_both_empty2452=== CONT TestParseSingleRange/malformed_no_dash2453=== CONT TestParseSingleRange/unknown_unit2454=== CONT TestParseSingleRange/start_far_past_EOF2455=== CONT TestParseSingleRange/multi-range_ignored2456=== CONT TestPush_RejectsBadRequests/no_objects24572026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes2458--- PASS: TestParseSingleRange (0.00s)2459 --- PASS: TestParseSingleRange/none (0.00s)2460 --- PASS: TestParseSingleRange/single_byte (0.00s)2461 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2462 --- PASS: TestParseSingleRange/suffix (0.00s)2463 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2464 --- PASS: TestParseSingleRange/open-ended (0.00s)2465 --- PASS: TestParseSingleRange/closed (0.00s)2466 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2467 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2468 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2469 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2470 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2471 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2472 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2473=== CONT TestPush_RejectsBadRequests/root_not_in_objects24742026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes2475=== CONT TestPush_RejectsBadRequests/bad_root24762026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes2477=== CONT TestPush_RejectsBadRequests/no_roots24782026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes2479=== CONT TestServerTLSConfig/no_client_CA2480=== CONT TestServerTLSConfig/missing_CA_file2481--- PASS: TestPush_RejectsBadRequests (0.69s)2482 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2483 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2484 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2485 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2486=== CONT TestServerTLSConfig/not_a_PEM_file2487--- PASS: TestServerTLSConfig (0.00s)2488 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2489 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2490 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2491=== CONT TestResolveDBConnectionString/flag_wins2492=== CONT TestResolveDBConnectionString/nothing_configured2493=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2494=== CONT TestResolveDBConnectionString/missing_file_is_an_error2495=== CONT TestResolveDBConnectionString/file_when_flag_empty2496=== NAME TestClientMultipleUploads2497 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3732926226/001/store/vb56p2ynzj7851yy1baxnlhk8swnrc7x-test-file-1.txt2498=== CONT TestIsValidCachePath/narinfo2499=== CONT TestIsValidCachePath/short_hash2500=== CONT TestIsValidCachePath/wrong_extension2501=== CONT TestIsValidCachePath/leading_slash2502=== CONT TestIsValidCachePath/empty2503=== CONT TestIsValidCachePath/random_path2504=== CONT TestIsValidCachePath/invalid_char_u2505=== CONT TestIsValidCachePath/invalid_char_e2506=== CONT TestIsValidCachePath/traversal_in_middle2507=== CONT TestIsValidCachePath/traversal_parent2508=== CONT TestIsValidCachePath/index.html2509=== CONT TestIsValidCachePath/nix-cache-info2510--- PASS: TestResolveDBConnectionString (0.00s)2511 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2512 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2513 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2514 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2515 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2516=== CONT TestIsValidCachePath/realisation2517=== CONT TestIsValidCachePath/log2518=== CONT TestIsValidCachePath/ls2519=== CONT TestIsValidCachePath/nar_uncompressed2520=== CONT TestIsValidCachePath/nar_bz22521=== CONT TestIsValidCachePath/nar_xz2522=== CONT TestIsValidCachePath/nar_zst2523=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2524--- PASS: TestIsValidCachePath (0.00s)2525 --- PASS: TestIsValidCachePath/narinfo (0.00s)2526 --- PASS: TestIsValidCachePath/short_hash (0.00s)2527 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2528 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2529 --- PASS: TestIsValidCachePath/empty (0.00s)2530 --- PASS: TestIsValidCachePath/random_path (0.00s)2531 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2532 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2533 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2534 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2535 --- PASS: TestIsValidCachePath/index.html (0.00s)2536 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2537 --- PASS: TestIsValidCachePath/realisation (0.00s)2538 --- PASS: TestIsValidCachePath/log (0.00s)2539 --- PASS: TestIsValidCachePath/ls (0.00s)2540 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2541 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2542 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2543 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2544 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2545=== CONT TestIsValidUploadKey/narinfo2546=== CONT TestIsValidUploadKey/realisation_plus_in_output2547=== CONT TestIsValidUploadKey/unknown_type2548=== NAME TestClientWithDependencies2549 client_integration_test.go:615: Found 1 dependencies (including self)25502026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (3.09ms)2551=== CONT TestIsValidUploadKey/empty_key2552=== CONT TestIsValidUploadKey/absolute2553=== CONT TestIsValidUploadKey/traversal_nar2554=== CONT TestIsValidUploadKey/traversal2555=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2556=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2557=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2558=== CONT TestIsValidUploadKey/index.html2559=== CONT TestIsValidUploadKey/build_log_home-manager_file2560=== CONT TestIsValidUploadKey/realisation2561=== CONT TestIsValidUploadKey/build_log_equals2562=== CONT TestIsValidUploadKey/nar_plain2563=== CONT TestIsValidUploadKey/build_log_question_mark2564=== CONT TestIsValidUploadKey/build_log2565=== CONT TestIsValidUploadKey/build_log_plus_in_name2566=== CONT TestIsValidUploadKey/listing2567=== CONT TestIsValidUploadKey/nar_xz2568=== CONT TestIsValidUploadKey/nar_zst2569=== CONT TestIsValidUploadKey/nix-cache-info2570--- PASS: TestIsValidUploadKey (0.00s)2571 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2572 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2573 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2574 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2575 --- PASS: TestIsValidUploadKey/absolute (0.00s)2576 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2577 --- PASS: TestIsValidUploadKey/traversal (0.00s)2578 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2579 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2580 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2581 --- PASS: TestIsValidUploadKey/index.html (0.00s)2582 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2583 --- PASS: TestIsValidUploadKey/realisation (0.00s)2584 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2585 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2586 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2587 --- PASS: TestIsValidUploadKey/build_log (0.00s)2588 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2589 --- PASS: TestIsValidUploadKey/listing (0.00s)2590 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2591 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2592 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2593=== CONT TestClientErrorHandling/InvalidStorePath2594=== NAME TestClientIntegration2595 client_integration_test.go:286: Created store path: /build/TestClientIntegration3880270989/002/store/hc7ravl7r54nyczlhlaplfihdaf0kza8-test-file.txt25962026/10/01 10:22:09 INFO Upload complete. (58ms)25972026/10/01 10:22:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete25982026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.44ms)2599=== NAME TestClientSharedPathCommittedMidPush2600 client_integration_test.go:680: Retrieved narinfo from S3:2601 StorePath: /build/TestClientSharedPathCommittedMidPush4995339/001/store/b42h8kg54f3294sx0ams5fbv1yrjiaw3-shared-dep2602 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2603 Compression: zstd2604 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822605 NarSize: 1362606 References: 2607 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n26082026/10/01 10:22:09 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst2609--- PASS: TestCompleteMultipartUnregistered (0.35s)2610=== CONT TestClientErrorHandling/ServerNotAvailable26112026-10-01 10:22:09.316 UTC [1240] ERROR: relation "goose_db_version" does not exist at character 3626122026-10-01 10:22:09.316 UTC [1240] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2613=== NAME TestClientSharedPathCommittedMidPush2614 client_integration_test.go:680: Retrieved narinfo from S3:2615 StorePath: /build/TestClientSharedPathCommittedMidPush4995339/001/store/qyfzkni9l4xhqcnql4gj375b6k0dkibx-top2616 URL: nar/0a6m9fhs3h8h1rgrywnkjiw45abnfcsb9qaikn1fc4ijl8s4r5wr.nar.zst2617 Compression: zstd2618 NarHash: sha256:0a6m9fhs3h8h1rgrywnkjiw45abnfcsb9qaikn1fc4ijl8s4r5wr2619 NarSize: 2162620 References: /build/TestClientSharedPathCommittedMidPush4995339/001/store/b42h8kg54f3294sx0ams5fbv1yrjiaw3-shared-dep2621 CA: text:sha256:0pp4d3mdciqvq9s65dcgjpvcrkib6928z4qys1i31nii893pxbpk2622--- PASS: TestClientSharedPathCommittedMidPush (0.56s)2623=== CONT TestClientErrorHandling/InvalidAuthToken26242026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (10.39ms)26252026/10/01 10:22:09 OK 20260905000000_add_claims.sql (5.21ms)26262026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.68ms)26272026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.82ms)26282026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000026292026/10/01 10:22:09 OK 20241026095416_initial_model.sql (14.36ms)26302026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes26312026-10-01 10:22:09.341 UTC [1266] ERROR: relation "goose_db_version" does not exist at character 3626322026-10-01 10:22:09.341 UTC [1266] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26332026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (2.99ms)26342026/10/01 10:22:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26352026/10/01 10:22:09 INFO Uploading sa0pl5fhn031x6hgwxn1z18kblk7b5nz-unpinned-file.txt (128B)26362026/10/01 10:22:09 OK 1_commit_pending_closure.sql (3.42ms)26372026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.52ms)2638--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.84s)2639=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info26402026/10/01 10:22:09 INFO Received uploads request method=POST path=/2641=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26422026/10/01 10:22:09 INFO Received complete multipart upload request method=POST path=/2643=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2644=== NAME TestClientMultipleUploads26452026/10/01 10:22:09 INFO Received uploads request method=POST path=/2646 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3732926226/001/store/xksamjdlw2l2y6mh8njjrqf1zy0kxx3r-test-file-2.txt2647=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26482026/10/01 10:22:09 INFO Received request for more parts method=POST path=/2649--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2650 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2651 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2652 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2653 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2654=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26552026/10/01 10:22:09 INFO Received uploads request method=POST path=/26562026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.75ms)26572026/10/01 10:22:09 OK 3_commit_push.sql (2.37ms)26582026/10/01 10:22:09 goose: up to current file version: 326592026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"26602026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign26612026/10/01 10:22:09 WARN Failed to register uploaded object key=sa0pl5fhn031x6hgwxn1z18kblk7b5nz.ls error="server returned 404: 404 page not found\n"26622026/10/01 10:22:09 INFO Signed narinfos id=2 count=126632026/10/01 10:22:09 INFO Uploading 1 narinfos26642026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/2/complete26652026/10/01 10:22:09 WARN Failed to register uploaded object key=sa0pl5fhn031x6hgwxn1z18kblk7b5nz.narinfo error="server returned 404: 404 page not found\n"26662026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (6.11ms)26672026/10/01 10:22:09 INFO Upload complete. (47ms)26682026-10-01 10:22:09.354 UTC [1337] ERROR: relation "goose_db_version" does not exist at character 3626692026-10-01 10:22:09.354 UTC [1337] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26702026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures26712026/10/01 10:22:09 OK 20260905000000_add_claims.sql (4.05ms)26722026/10/01 10:22:09 OK 20241026095416_initial_model.sql (11.93ms)26732026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.51ms)26742026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)26752026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (3.38ms)26762026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000026772026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.54ms)26782026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.97ms)26792026/10/01 10:22:09 OK 2_object_stats_trigger.sql (2.08ms)26802026/10/01 10:22:09 OK 3_commit_push.sql (1.56ms)26812026/10/01 10:22:09 goose: up to current file version: 326822026-10-01 10:22:09.372 UTC [1341] ERROR: relation "goose_db_version" does not exist at character 3626832026-10-01 10:22:09.372 UTC [1341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26842026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.58ms)26852026/10/01 10:22:09 OK 20241026095416_initial_model.sql (11.59ms)26862026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)26872026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.25ms)26882026/10/01 10:22:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33405/oidc26892026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.15ms)26902026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.03ms)26912026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes26922026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes26932026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.44ms)26942026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000026952026/10/01 10:22:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures26962026/10/01 10:22:09 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/present26972026-10-01 10:22:09.389 UTC [1440] ERROR: relation "goose_db_version" does not exist at character 3626982026-10-01 10:22:09.389 UTC [1440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26992026/10/01 10:22:09 INFO Garbage collection started27002026/10/01 10:22:09 OK 1_commit_pending_closure.sql (7.96ms)27012026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (10.77ms)27022026/10/01 10:22:09 OK 20241026095416_initial_model.sql (10.76ms)27032026/10/01 10:22:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43839/oidc27042026/10/01 10:22:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27052026/10/01 10:22:09 INFO Uploading ll4nfjqdfh6g44qyfkaym4zazrk84ihn-test-script (136B)27062026/10/01 10:22:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27072026/10/01 10:22:09 INFO Uploading hc7ravl7r54nyczlhlaplfihdaf0kza8-test-file.txt (152B)27082026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.17ms)27092026/10/01 10:22:09 OK 3_commit_push.sql (1.35ms)27102026/10/01 10:22:09 goose: up to current file version: 327112026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.53ms)27122026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)2713--- PASS: TestCacheStatsHandler (0.33s)2714=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts27152026/10/01 10:22:09 INFO Received request for more parts method=POST path=/27162026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"27172026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"27182026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.76ms)27192026/10/01 10:22:09 WARN Failed to register uploaded object key=ll4nfjqdfh6g44qyfkaym4zazrk84ihn.ls error="server returned 404: 404 page not found\n"27202026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27212026/10/01 10:22:09 WARN Failed to register uploaded object key=hc7ravl7r54nyczlhlaplfihdaf0kza8.ls error="server returned 404: 404 page not found\n"27222026/10/01 10:22:09 INFO Signed narinfos id=1 count=127232026/10/01 10:22:09 INFO Uploading 1 narinfos27242026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.29ms)27252026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.3ms)27262026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000027272026/10/01 10:22:09 WARN Failed to register uploaded object key=log/bsfpivrgrsxgwk76ya67z6m0gmp3l1b8-test-script.drv error="server returned 404: 404 page not found\n"27282026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27292026/10/01 10:22:09 INFO Signed narinfos id=1 count=127302026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures27312026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures27322026/10/01 10:22:09 INFO Uploading 1 narinfos27332026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures27342026-10-01 10:22:09.401 UTC [1449] ERROR: relation "goose_db_version" does not exist at character 3627352026-10-01 10:22:09.401 UTC [1449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27362026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.5ms)27372026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete27382026/10/01 10:22:09 WARN Failed to register uploaded object key=hc7ravl7r54nyczlhlaplfihdaf0kza8.narinfo error="server returned 404: 404 page not found\n"27392026/10/01 10:22:09 INFO Aborted multipart uploads count=0 kept=027402026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.54ms)27412026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)27422026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete27432026/10/01 10:22:09 WARN Failed to register uploaded object key=ll4nfjqdfh6g44qyfkaym4zazrk84ihn.narinfo error="server returned 404: 404 page not found\n"27442026/10/01 10:22:09 OK 3_commit_push.sql (2.58ms)27452026/10/01 10:22:09 goose: up to current file version: 327462026/10/01 10:22:09 WARN Force mode enabled - objects will be deleted immediately without grace period27472026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.87ms)27482026/10/01 10:22:09 INFO Upload complete. (66ms)27492026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.64ms)27502026/10/01 10:22:09 OK 20241026095416_initial_model.sql (13.34ms)27512026/10/01 10:22:09 INFO Upload complete. (69ms)27522026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.71ms)27532026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000027542026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (2.92ms)2755=== NAME TestClientWithDependencies2756 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2945781875/001/store) requires matching store prefix27572026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.58ms)2758--- PASS: TestClientWithDependencies (0.60s)2759=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart27602026/10/01 10:22:09 INFO Received complete multipart upload request method=POST path=/27612026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.9ms)27622026/10/01 10:22:09 OK 20251218171726_add_pins.sql (4.99ms)2763=== NAME TestClientCADerivations2764 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1398422569/001/store/jjcfbvikjv45a8ny4niiqhw4pvbkbm20-ca-test27652026/10/01 10:22:09 OK 3_commit_push.sql (1.56ms)27662026/10/01 10:22:09 goose: up to current file version: 327672026/10/01 10:22:09 OK 20241026095416_initial_model.sql (12.17ms)27682026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)27692026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (4.28ms)27702026/10/01 10:22:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=027712026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes2772--- PASS: TestService_healthCheckHandler (0.29s)2773=== CONT TestCacheConfigHandler/full_config,_no_issuer2774=== CONT TestCacheConfigHandler/no_signing_keys2775=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2776=== CONT TestCacheConfigHandler/no_cache_url_configured2777--- PASS: TestCacheConfigHandler (0.00s)2778 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2779 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2780 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2781 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2782=== CONT TestPendingClosureWriteTimeout/empty2783=== CONT TestPendingClosureWriteTimeout/670k_objects2784=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline27852026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.97ms)27862026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.66ms)27872026/10/01 10:22:09 INFO Vacuumed table table=pending_closures27882026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (3.82ms)27892026/10/01 10:22:09 INFO Vacuumed table table=pending_objects27902026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (5.21ms)27912026/10/01 10:22:09 INFO Vacuumed table table=multipart_uploads27922026/10/01 10:22:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)27932026/10/01 10:22:09 INFO Uploading vb56p2ynzj7851yy1baxnlhk8swnrc7x-test-file-1.txt (160B)27942026/10/01 10:22:09 INFO Uploading aq05153ryjar67yg70d9cwwziqn0pjg3-test-file-0.txt (160B)27952026/10/01 10:22:09 INFO Uploading xksamjdlw2l2y6mh8njjrqf1zy0kxx3r-test-file-2.txt (160B)27962026/10/01 10:22:09 INFO Vacuumed table table=closures27972026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (6ms)27982026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000027992026/10/01 10:22:09 OK 20260905000000_add_claims.sql (4.69ms)28002026/10/01 10:22:09 INFO Vacuumed table table=objects28012026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"28022026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"28032026/10/01 10:22:09 WARN Failed to register uploaded object key=xksamjdlw2l2y6mh8njjrqf1zy0kxx3r.ls error="server returned 404: 404 page not found\n"28042026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.65ms)28052026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.76ms)28062026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"28072026/10/01 10:22:09 WARN Failed to register uploaded object key=aq05153ryjar67yg70d9cwwziqn0pjg3.ls error="server returned 404: 404 page not found\n"28082026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28092026/10/01 10:22:09 WARN Failed to register uploaded object key=vb56p2ynzj7851yy1baxnlhk8swnrc7x.ls error="server returned 404: 404 page not found\n"28102026/10/01 10:22:09 INFO Signed narinfos id=1 count=328112026/10/01 10:22:09 INFO Uploading 3 narinfos28122026/10/01 10:22:09 OK 2_object_stats_trigger.sql (2.02ms)28132026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (2.88ms)28142026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000028152026/10/01 10:22:09 OK 3_commit_push.sql (1.69ms)28162026/10/01 10:22:09 goose: up to current file version: 328172026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete28182026/10/01 10:22:09 WARN Failed to register uploaded object key=vb56p2ynzj7851yy1baxnlhk8swnrc7x.narinfo error="server returned 404: 404 page not found\n"28192026/10/01 10:22:09 WARN Failed to register uploaded object key=xksamjdlw2l2y6mh8njjrqf1zy0kxx3r.narinfo error="server returned 404: 404 page not found\n"28202026/10/01 10:22:09 WARN Failed to register uploaded object key=aq05153ryjar67yg70d9cwwziqn0pjg3.narinfo error="server returned 404: 404 page not found\n"28212026/10/01 10:22:09 OK 1_commit_pending_closure.sql (2.64ms)28222026/10/01 10:22:09 INFO All 1 paths already cached28232026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.8ms)2824--- PASS: TestService_ReadScope_PublicByDefault (0.30s)2825=== CONT TestPendingClosureWriteTimeout/400_objects2826=== CONT TestProxyWriteTimeout/narinfo2827=== CONT TestProxyWriteTimeout/10_GiB_nar2828=== CONT TestProxyWriteTimeout/unknown_size2829=== CONT TestProxyWriteTimeout/1_GiB_nar2830--- PASS: TestProxyWriteTimeout (0.00s)2831 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2832 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2833 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2834 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)28352026/10/01 10:22:09 OK 3_commit_push.sql (1.08ms)2836=== NAME TestClientIntegration28372026/10/01 10:22:09 goose: up to current file version: 32838 client_integration_test.go:312: Retrieved narinfo from S3:2839 StorePath: /build/TestClientIntegration3880270989/002/store/hc7ravl7r54nyczlhlaplfihdaf0kza8-test-file.txt2840 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2841 Compression: zstd2842 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12843 NarSize: 1522844 References: 2845 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk128462026/10/01 10:22:09 INFO Upload complete. (70ms)2847=== NAME TestClientMultipleUploads2848 client_integration_test.go:369: Uploaded 3 paths in 105.21053ms2849=== NAME TestClientIntegration2850 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2851 client_integration_test.go:313: Decompressed .ls content (64 bytes):2852 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2853 client_integration_test.go:316: Testing garbage collection...2854=== NAME TestClientCADerivations2855 client_ca_test.go:139: Found 1 dependencies (including self)28562026-10-01 10:22:09.456 UTC [1510] ERROR: relation "goose_db_version" does not exist at character 3628572026-10-01 10:22:09.456 UTC [1510] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2858--- PASS: TestClientMultipleUploads (0.58s)28592026/10/01 10:22:09 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"28602026/10/01 10:22:09 WARN mTLS auth: bound subjects configured but subject DN unavailable28612026/10/01 10:22:09 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2862--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.26s)28632026-10-01 10:22:09.469 UTC [1528] ERROR: relation "goose_db_version" does not exist at character 3628642026-10-01 10:22:09.469 UTC [1528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28652026/10/01 10:22:09 OK 20241026095416_initial_model.sql (11.73ms)28662026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)28672026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.57ms)28682026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)28692026/10/01 10:22:09 OK 20241026095416_initial_model.sql (10.05ms)28702026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)28712026/10/01 10:22:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures2872--- PASS: TestService_ReadAuthMiddleware (0.26s)28732026/10/01 10:22:09 INFO Garbage collection started28742026/10/01 10:22:09 OK 20260905000000_add_claims.sql (2.88ms)28752026/10/01 10:22:09 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=203.981015ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28762026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (1.88ms)28772026/10/01 10:22:09 OK 20251218171726_add_pins.sql (2.94ms)28782026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (1.63ms)28792026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000028802026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)28812026/10/01 10:22:09 OK 1_commit_pending_closure.sql (1.71ms)28822026-10-01 10:22:09.496 UTC [1564] ERROR: relation "goose_db_version" does not exist at character 3628832026-10-01 10:22:09.496 UTC [1564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28842026/10/01 10:22:09 INFO Aborted multipart uploads count=0 kept=028852026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.22ms)28862026/10/01 10:22:09 OK 20260905000000_add_claims.sql (2.44ms)28872026/10/01 10:22:09 OK 3_commit_push.sql (831.61µs)28882026/10/01 10:22:09 goose: up to current file version: 328892026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (1.67ms)28902026/10/01 10:22:09 WARN Force mode enabled - objects will be deleted immediately without grace period28912026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (1.62ms)28922026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000028932026/10/01 10:22:09 OK 1_commit_pending_closure.sql (1.61ms)28942026/10/01 10:22:09 OK 2_object_stats_trigger.sql (1.34ms)2895--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.24s)28962026/10/01 10:22:09 OK 3_commit_push.sql (706.59µs)28972026/10/01 10:22:09 goose: up to current file version: 328982026/10/01 10:22:09 OK 20241026095416_initial_model.sql (8.67ms)28992026/10/01 10:22:09 OK 20251210153512_drop_unused_gin_index.sql (1.58ms)29002026/10/01 10:22:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=029012026/10/01 10:22:09 OK 20251218171726_add_pins.sql (3.06ms)29022026/10/01 10:22:09 INFO Vacuumed table table=pending_closures29032026/10/01 10:22:09 INFO Vacuumed table table=pending_objects29042026/10/01 10:22:09 INFO Vacuumed table table=multipart_uploads29052026/10/01 10:22:09 OK 20260628120000_add_object_size_and_stats.sql (3.03ms)29062026/10/01 10:22:09 INFO Vacuumed table table=closures29072026/10/01 10:22:09 INFO Vacuumed table table=objects29082026/10/01 10:22:09 OK 20260905000000_add_claims.sql (3.04ms)29092026/10/01 10:22:09 OK 20260920000000_drop_claims.sql (2.01ms)29102026/10/01 10:22:09 OK 20260923120000_add_pushes.sql (1.63ms)29112026/10/01 10:22:09 goose: successfully migrated database to version: 2026092312000029122026/10/01 10:22:09 OK 1_commit_pending_closure.sql (1.76ms)29132026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures29142026/10/01 10:22:09 OK 2_object_stats_trigger.sql (740.07µs)29152026/10/01 10:22:09 OK 3_commit_push.sql (872.85µs)29162026/10/01 10:22:09 goose: up to current file version: 329172026/10/01 10:22:09 INFO Aborted multipart uploads count=0 kept=029182026/10/01 10:22:09 WARN Force mode enabled - objects will be deleted immediately without grace period29192026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures29202026/10/01 10:22:09 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=029212026/10/01 10:22:09 INFO Vacuumed table table=pending_closures29222026/10/01 10:22:09 INFO Vacuumed table table=pending_objects29232026/10/01 10:22:09 INFO Vacuumed table table=multipart_uploads29242026/10/01 10:22:09 INFO Vacuumed table table=closures29252026/10/01 10:22:09 INFO Vacuumed table table=objects29262026/10/01 10:22:09 INFO Aborted multipart uploads count=0 kept=029272026/10/01 10:22:09 WARN Force mode enabled - objects will be deleted immediately without grace period29282026/10/01 10:22:09 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=029292026/10/01 10:22:09 INFO Vacuumed table table=pending_closures29302026/10/01 10:22:09 INFO Received push request method=POST path=/api/pushes29312026/10/01 10:22:09 INFO Vacuumed table table=pending_objects29322026/10/01 10:22:09 INFO Vacuumed table table=multipart_uploads29332026/10/01 10:22:09 INFO Vacuumed table table=closures29342026/10/01 10:22:09 INFO Vacuumed table table=objects29352026/10/01 10:22:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)29362026/10/01 10:22:09 INFO Uploading jjcfbvikjv45a8ny4niiqhw4pvbkbm20-ca-test (144B)2937=== NAME TestOrphanedObjectsGCStressTest2938 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains29392026/10/01 10:22:09 WARN Failed to register uploaded object key=jjcfbvikjv45a8ny4niiqhw4pvbkbm20.ls error="server returned 404: 404 page not found\n"29402026/10/01 10:22:09 WARN Failed to register uploaded object key=log/hkpwvwarphq3pydl6vcqjp8d0yw2b2yw-ca-test.drv error="server returned 404: 404 page not found\n"29412026/10/01 10:22:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29422026/10/01 10:22:09 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"29432026/10/01 10:22:09 INFO Signed narinfos id=1 count=129442026/10/01 10:22:09 INFO Uploading 1 narinfos2945--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2946 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.30s)2947 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.30s)29482026/10/01 10:22:09 INFO Received complete push request method=POST path=/api/pushes/1/complete29492026/10/01 10:22:09 WARN Failed to register uploaded object key=jjcfbvikjv45a8ny4niiqhw4pvbkbm20.narinfo error="server returned 404: 404 page not found\n"29502026/10/01 10:22:09 INFO Upload complete. (96ms)2951=== NAME TestClientCADerivations2952 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1398422569/001/store/jjcfbvikjv45a8ny4niiqhw4pvbkbm20-ca-test2953 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2954 Compression: zstd2955 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2956 NarSize: 1442957 References: 2958 Deriver: /build/TestClientCADerivations1398422569/001/store/hkpwvwarphq3pydl6vcqjp8d0yw2b2yw-ca-test.drv2959 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2960 client_ca_test.go:185: Checking for realisation files in S3...2961 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2962 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2963=== NAME TestOrphanedObjectsGCStressTest2964 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2965=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2966=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2967=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2968=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2969=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2970=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2971=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2972=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2973=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2974=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected2975=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2976=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured29772026/10/01 10:22:09 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]29782026/10/01 10:22:09 WARN Authentication failed token_preview=eyJhbGciOi...pVIWbBVvqg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2979--- PASS: TestService_AuthMiddleware_OIDC (0.42s)2980 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2981 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2982 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2983 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2984=== RUN TestService_RequireScope_OIDC/builder_may_write2985=== PAUSE TestService_RequireScope_OIDC/builder_may_write2986=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2987=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2988=== RUN TestService_RequireScope_OIDC/ops_may_admin29892026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures2990=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2991=== RUN TestService_RequireScope_OIDC/ops_may_not_write2992=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2993=== RUN TestService_RequireScope_OIDC/reader_may_not_write2994=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2995=== RUN TestService_RequireScope_OIDC/static_token_may_admin2996=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2997=== RUN TestService_RequireScope_OIDC/static_token_may_write2998=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2999=== RUN TestService_RequireScope_OIDC/reader_may_read3000=== PAUSE TestService_RequireScope_OIDC/reader_may_read3001=== RUN TestService_RequireScope_OIDC/writer_implies_read3002=== PAUSE TestService_RequireScope_OIDC/writer_implies_read3003=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read3004=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read3005=== CONT TestService_RequireScope_OIDC/builder_may_write3006=== CONT TestService_RequireScope_OIDC/reader_may_read3007=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read3008=== CONT TestService_RequireScope_OIDC/static_token_may_admin3009=== CONT TestService_RequireScope_OIDC/writer_implies_read3010=== CONT TestService_RequireScope_OIDC/ops_may_not_write3011=== CONT TestService_RequireScope_OIDC/reader_may_not_write3012=== CONT TestService_RequireScope_OIDC/ops_may_admin3013=== CONT TestService_RequireScope_OIDC/builder_may_not_admin3014=== CONT TestService_RequireScope_OIDC/static_token_may_write3015--- PASS: TestService_RequireScope_OIDC (0.47s)3016 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)3017 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)3018 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)3019 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)3020 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)3021 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)3022 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)3023 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)3024 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)3025 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)30262026/10/01 10:22:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30272026/10/01 10:22:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete30282026/10/01 10:22:09 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLmU4NDg3MGVjLTY2MWMtNDE3Mi1hNTkxLTFjYmQyZjdkZTdhNHgxNzkwODUwMTI5MzY0MjkxNDMz parts=1030292026/10/01 10:22:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete3030=== NAME TestClientCADerivations3031 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features3032 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable3033 error: binary cache 's3://bucket71?endpoint=http://localhost:44885®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1398422569/001/store'3034 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 130352026/10/01 10:22:09 INFO Completed upload id=130362026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures30372026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures3038--- PASS: TestClientCADerivations (0.71s)30392026/10/01 10:22:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30402026/10/01 10:22:09 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo30412026/10/01 10:22:09 WARN Found objects in DB but missing from S3, will re-upload count=13042--- PASS: TestService_verifyS3Integrity (0.69s)30432026/10/01 10:22:09 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=410.371906ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30442026/10/01 10:22:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete30452026/10/01 10:22:09 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=Yjk2Mjg4MDQtNTJkNi00ZWExLTg0ZDUtNTkxMTU3NjU0MTEzLmM4MjBlOGM1LTY3ZmYtNDRhYi1iMDU4LThmNWJjNzg2MTRmZHgxNzkwODUwMTI5NDA3OTYxMDI3 parts=1030462026/10/01 10:22:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete30472026/10/01 10:22:09 INFO Completed upload id=130482026/10/01 10:22:09 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000030492026/10/01 10:22:09 INFO Received uploads request method=POST path=/api/pending_closures30502026/10/01 10:22:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures30512026/10/01 10:22:09 INFO Aborted multipart uploads count=0 kept=030522026/10/01 10:22:09 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=030532026/10/01 10:22:09 INFO Vacuumed table table=pending_closures30542026/10/01 10:22:09 INFO Vacuumed table table=pending_objects30552026/10/01 10:22:09 INFO Vacuumed table table=multipart_uploads30562026/10/01 10:22:09 INFO Vacuumed table table=closures30572026/10/01 10:22:09 INFO Vacuumed table table=objects30582026/10/01 10:22:09 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000003059--- PASS: TestService_createPendingClosureHandler (0.69s)3060=== NAME TestOrphanedObjectsGCStressTest3061 orphaned_objects_gc_test.go:509: Stress test completed successfully:3062 orphaned_objects_gc_test.go:510: - Active objects preserved: 203063 orphaned_objects_gc_test.go:511: - Objects deleted: 2103064 orphaned_objects_gc_test.go:512: - Total GC'd: 2103065--- PASS: TestOrphanedObjectsGCStressTest (2.50s)30662026/10/01 10:22:10 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=859.825402ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3067--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)3068 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)3069 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)3070 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.84s)3071--- PASS: TestPendingClosureWriteTimeout (0.00s)3072 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)3073 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)3074 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)3075 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.03s)30762026/10/01 10:22:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.563565632s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30772026/10/01 10:22:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=030782026/10/01 10:22:11 INFO Received create pin request method=POST path=/api/pins/myapp30792026/10/01 10:22:11 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC256780221/001/store/7cb26ivxy2gf7z397wmc1c33kk2njgma-pinned-file.txt narinfo_key=7cb26ivxy2gf7z397wmc1c33kk2njgma.narinfo30802026/10/01 10:22:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures30812026/10/01 10:22:11 INFO Garbage collection started30822026/10/01 10:22:11 INFO Aborted multipart uploads count=0 kept=030832026/10/01 10:22:11 WARN Force mode enabled - objects will be deleted immediately without grace period30842026/10/01 10:22: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=030852026/10/01 10:22:11 INFO Vacuumed table table=pending_closures30862026/10/01 10:22:11 INFO Vacuumed table table=pending_objects30872026/10/01 10:22:11 INFO Vacuumed table table=multipart_uploads30882026/10/01 10:22:11 INFO Vacuumed table table=closures30892026/10/01 10:22:11 INFO Vacuumed table table=objects30902026/10/01 10:22:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03091=== NAME TestClientIntegration3092 client_integration_test.go:323: Objects in database after GC:3093 client_integration_test.go:323: Successfully deleted all objects with GC --force3094--- PASS: TestClientIntegration (2.58s)30952026/10/01 10:22:12 WARN Rate limiter enabled after throttle name=s3-test rate=530962026/10/01 10:22:12 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3097=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3098 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103099 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003100--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.83s)31012026/10/01 10:22:12 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-config31022026/10/01 10:22:12 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=218.223236ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31032026/10/01 10:22:12 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=389.553837ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31042026/10/01 10:22:13 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=852.20817ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config3105=== NAME TestPinProtectsFromGC3106 client_integration_test.go:840: Pin successfully protected closure from garbage collection3107--- PASS: TestPinProtectsFromGC (4.71s)31082026/10/01 10:22:14 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.449398378s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31092026/10/01 10:22:14 INFO Aborted multipart uploads count=1 kept=031102026/10/01 10:22:14 INFO Received cleanup request method=DELETE path=/api/pending_closures31112026/10/01 10:22:14 INFO Aborted multipart uploads count=1 kept=03112--- PASS: TestPendingCleanupUsesOneCutoff (6.75s)31132026/10/01 10:22:15 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"31142026/10/01 10:22: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-config31152026/10/01 10:22:15 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=182.868928ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31162026/10/01 10:22:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=402.945232ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31172026/10/01 10:22:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=868.869103ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31182026/10/01 10:22:17 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.534544175s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config31192026/10/01 10:22:18 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_closures31202026/10/01 10:22:18 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.436575ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures31212026/10/01 10:22:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=390.372006ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures31222026/10/01 10:22:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=815.979852ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures31232026/10/01 10:22:20 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.545125798s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3124--- PASS: TestClientErrorHandling (0.00s)3125 --- PASS: TestClientErrorHandling/InvalidStorePath (0.29s)3126 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.37s)3127 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.42s)3128PASS31292026-10-01 10:22:21.964 UTC [128] LOG: received smart shutdown request31302026-10-01 10:22:21.968 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 131312026-10-01 10:22:21.978 UTC [133] LOG: shutting down31322026-10-01 10:22:21.978 UTC [133] LOG: checkpoint starting: shutdown immediate31332026-10-01 10:22:22.799 UTC [133] LOG: checkpoint complete: wrote 10375 buffers (63.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.171 s, sync=0.622 s, total=0.821 s; sync files=28984, longest=0.002 s, average=0.001 s; distance=401168 kB, estimate=401168 kB; lsn=0/19F29F88, redo lsn=0/19F29F8831342026-10-01 10:22:22.872 UTC [128] LOG: database system is shut down3135Running OIDC tests...3136=== RUN TestAudienceForIssuer3137=== PAUSE TestAudienceForIssuer3138=== RUN TestGlobMatch3139=== PAUSE TestGlobMatch3140=== RUN TestValidateToken_ValidToken3141=== PAUSE TestValidateToken_ValidToken3142=== RUN TestValidateToken_WrongAudience3143=== PAUSE TestValidateToken_WrongAudience3144=== RUN TestValidateToken_Expired3145=== PAUSE TestValidateToken_Expired3146=== RUN TestValidateToken_BoundClaimsMismatch3147=== PAUSE TestValidateToken_BoundClaimsMismatch3148=== RUN TestValidateToken_BoundSubjectMismatch3149=== PAUSE TestValidateToken_BoundSubjectMismatch3150=== RUN TestValidateToken_MultipleProviders3151=== PAUSE TestValidateToken_MultipleProviders3152=== RUN TestValidateToken_NoMatchingProvider3153=== PAUSE TestValidateToken_NoMatchingProvider3154=== RUN TestValidateToken_KubernetesServiceAccount3155=== PAUSE TestValidateToken_KubernetesServiceAccount3156=== RUN TestNewValidator_KubernetesRequiresCA3157=== PAUSE TestNewValidator_KubernetesRequiresCA3158=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3159=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3160=== RUN TestPins_ReservedForMatchingRule3161=== PAUSE TestPins_ReservedForMatchingRule3162=== RUN TestPins_TopLevelShorthand3163=== PAUSE TestPins_TopLevelShorthand3164=== RUN TestPins_ConfigValidation3165=== PAUSE TestPins_ConfigValidation3166=== RUN TestScopes_LegacyProviderDefaultsToWrite3167=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3168=== RUN TestScopes_Rules3169=== PAUSE TestScopes_Rules3170=== RUN TestScopes_ConfigValidation3171=== PAUSE TestScopes_ConfigValidation3172=== CONT TestAudienceForIssuer3173=== CONT TestPins_ConfigValidation3174--- PASS: TestAudienceForIssuer (0.00s)3175=== CONT TestValidateToken_KubernetesServiceAccount3176=== CONT TestPins_ReservedForMatchingRule3177=== CONT TestValidateToken_NoMatchingProvider3178=== CONT TestValidateToken_MultipleProviders3179=== CONT TestValidateToken_BoundSubjectMismatch3180=== CONT TestValidateToken_BoundClaimsMismatch3181=== CONT TestValidateToken_Expired3182=== CONT TestValidateToken_WrongAudience3183=== CONT TestValidateToken_ValidToken3184--- PASS: TestPins_ConfigValidation (0.00s)3185=== CONT TestGlobMatch3186=== CONT TestPins_TopLevelShorthand3187=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3188=== CONT TestScopes_Rules3189=== CONT TestScopes_ConfigValidation3190=== CONT TestNewValidator_KubernetesRequiresCA3191=== CONT TestScopes_LegacyProviderDefaultsToWrite3192=== RUN TestGlobMatch/foo_foo3193=== PAUSE TestGlobMatch/foo_foo3194=== RUN TestGlobMatch/foo_bar3195=== PAUSE TestGlobMatch/foo_bar3196=== RUN TestGlobMatch/*_3197=== PAUSE TestGlobMatch/*_3198=== RUN TestGlobMatch/*_anything3199=== PAUSE TestGlobMatch/*_anything3200=== RUN TestGlobMatch/foo*_foo3201=== PAUSE TestGlobMatch/foo*_foo3202=== RUN TestGlobMatch/foo*_foobar3203=== PAUSE TestGlobMatch/foo*_foobar3204=== RUN TestGlobMatch/foo*_bar3205=== PAUSE TestGlobMatch/foo*_bar3206=== RUN TestGlobMatch/*bar_bar3207=== PAUSE TestGlobMatch/*bar_bar3208=== RUN TestGlobMatch/*bar_foobar3209=== PAUSE TestGlobMatch/*bar_foobar3210=== RUN TestGlobMatch/*bar_foo3211--- PASS: TestScopes_ConfigValidation (0.00s)3212=== PAUSE TestGlobMatch/*bar_foo3213=== RUN TestGlobMatch/foo*bar_foobar3214=== PAUSE TestGlobMatch/foo*bar_foobar3215=== RUN TestGlobMatch/foo*bar_foo123bar3216=== PAUSE TestGlobMatch/foo*bar_foo123bar3217=== RUN TestGlobMatch/foo*bar_foobarbaz3218=== PAUSE TestGlobMatch/foo*bar_foobarbaz3219=== RUN TestGlobMatch/*/*_foo/bar3220=== PAUSE TestGlobMatch/*/*_foo/bar3221=== RUN TestGlobMatch/*/*_foo3222=== PAUSE TestGlobMatch/*/*_foo3223=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3224=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3225=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03226=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03227=== RUN TestGlobMatch/refs/*/main_refs/heads/main3228=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3229=== RUN TestGlobMatch/fo?_foo3230=== PAUSE TestGlobMatch/fo?_foo3231=== RUN TestGlobMatch/fo?_fo3232=== PAUSE TestGlobMatch/fo?_fo3233=== RUN TestGlobMatch/fo?_fooo3234=== PAUSE TestGlobMatch/fo?_fooo3235=== RUN TestGlobMatch/?oo_foo3236=== PAUSE TestGlobMatch/?oo_foo3237=== RUN TestGlobMatch/?oo_boo3238=== PAUSE TestGlobMatch/?oo_boo3239=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3240=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3241=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3242=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3243=== CONT TestGlobMatch/foo_foo3244=== CONT TestGlobMatch/fo?_foo3245=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3246=== CONT TestGlobMatch/*_anything3247=== CONT TestGlobMatch/foo_bar3248=== CONT TestGlobMatch/foo*_foobar3249=== CONT TestGlobMatch/foo*bar_foo123bar3250=== CONT TestGlobMatch/foo*bar_foobar3251=== CONT TestGlobMatch/*bar_foo3252=== CONT TestGlobMatch/*_3253=== CONT TestGlobMatch/?oo_boo3254=== CONT TestGlobMatch/*/*_foo/bar3255=== CONT TestGlobMatch/*/*_foo3256=== CONT TestGlobMatch/*bar_foobar3257=== CONT TestGlobMatch/?oo_foo3258=== CONT TestGlobMatch/fo?_fooo3259=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03260=== CONT TestGlobMatch/fo?_fo3261=== CONT TestGlobMatch/foo*_foo3262=== CONT TestGlobMatch/foo*bar_foobarbaz3263=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3264=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3265=== CONT TestGlobMatch/refs/*/main_refs/heads/main3266=== CONT TestGlobMatch/*bar_bar3267=== CONT TestGlobMatch/foo*_bar3268--- PASS: TestGlobMatch (0.00s)3269 --- PASS: TestGlobMatch/foo_foo (0.00s)3270 --- PASS: TestGlobMatch/fo?_foo (0.00s)3271 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3272 --- PASS: TestGlobMatch/*_anything (0.00s)3273 --- PASS: TestGlobMatch/foo_bar (0.00s)3274 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3275 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3276 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3277 --- PASS: TestGlobMatch/*bar_foo (0.00s)3278 --- PASS: TestGlobMatch/*_ (0.00s)3279 --- PASS: TestGlobMatch/?oo_boo (0.00s)3280 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3281 --- PASS: TestGlobMatch/*/*_foo (0.00s)3282 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3283 --- PASS: TestGlobMatch/?oo_foo (0.00s)3284 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3285 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3286 --- PASS: TestGlobMatch/fo?_fo (0.00s)3287 --- PASS: TestGlobMatch/foo*_foo (0.00s)3288 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3289 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3290 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3291 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3292 --- PASS: TestGlobMatch/*bar_bar (0.00s)3293 --- PASS: TestGlobMatch/foo*_bar (0.00s)32942026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35007/oidc3295--- PASS: TestValidateToken_BoundClaimsMismatch (0.03s)32962026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37363/oidc3297--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)32982026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38493/oidc3299--- PASS: TestValidateToken_Expired (0.07s)33002026/10/01 10:22:24 http: TLS handshake error from 127.0.0.1:33332: remote error: tls: bad certificate3301--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)33022026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41867/oidc3303--- PASS: TestValidateToken_WrongAudience (0.10s)33042026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39619/oidc3305--- PASS: TestPins_TopLevelShorthand (0.11s)33062026/10/01 10:22:24 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12333072026/10/01 10:22:24 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39099/oidc33082026/10/01 10:22:24 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:44355/oidc3309--- PASS: TestValidateToken_MultipleProviders (0.14s)3310--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.14s)33112026/10/01 10:22:24 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:334773312--- PASS: TestValidateToken_KubernetesServiceAccount (0.17s)33132026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37017/oidc33142026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43323/oidc3315--- PASS: TestScopes_Rules (0.18s)33162026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46581/oidc3317--- PASS: TestPins_ReservedForMatchingRule (0.19s)3318--- PASS: TestValidateToken_ValidToken (0.19s)33192026/10/01 10:22:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46117/oidc3320--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.22s)33212026/10/01 10:22:24 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46695/oidc3322--- PASS: TestValidateToken_NoMatchingProvider (0.24s)3323PASS3324Running hook tests...3325=== RUN TestSendPathsEmpty3326=== PAUSE TestSendPathsEmpty3327=== RUN TestQueueEnqueueAndFetch3328=== PAUSE TestQueueEnqueueAndFetch3329=== RUN TestQueueDeduplication3330=== PAUSE TestQueueDeduplication3331=== RUN TestQueueRemove3332=== PAUSE TestQueueRemove3333=== RUN TestQueueFetchBatchLimit3334=== PAUSE TestQueueFetchBatchLimit3335=== RUN TestQueueRetryMovesToBack3336=== PAUSE TestQueueRetryMovesToBack3337=== RUN TestQueueFetchRemoveLifecycle3338=== PAUSE TestQueueFetchRemoveLifecycle3339=== RUN TestQueueConcurrentWriters3340=== PAUSE TestQueueConcurrentWriters3341=== RUN TestQueueRemoveLargeClosure3342=== PAUSE TestQueueRemoveLargeClosure3343=== RUN TestServerClientIntegration3344=== PAUSE TestServerClientIntegration3345=== RUN TestServerQueueError3346=== PAUSE TestServerQueueError3347=== RUN TestGetListenerSocketActivation3348 server_test.go:210: === RUN TestGetListenerSocketActivation3349 --- PASS: TestGetListenerSocketActivation (0.00s)3350 PASS3351 3352--- PASS: TestGetListenerSocketActivation (0.01s)3353=== RUN TestDrainIsolatesPoisonPath3354=== PAUSE TestDrainIsolatesPoisonPath3355=== RUN TestRunNotBlockedByPoisonHead3356=== PAUSE TestRunNotBlockedByPoisonHead3357=== RUN TestDrainGivesUpWhenServerDown3358=== PAUSE TestDrainGivesUpWhenServerDown3359=== RUN TestFailedPathPrunedByLaterClosure3360=== PAUSE TestFailedPathPrunedByLaterClosure3361=== RUN TestWorkerUploadsAndRemoves3362=== PAUSE TestWorkerUploadsAndRemoves3363=== RUN TestWorkerSkipsGCdPaths3364=== PAUSE TestWorkerSkipsGCdPaths3365=== RUN TestWorkerPrunesClosureDeps3366=== PAUSE TestWorkerPrunesClosureDeps3367=== RUN TestDrainTimeout3368=== PAUSE TestDrainTimeout3369=== CONT TestSendPathsEmpty3370=== CONT TestDrainGivesUpWhenServerDown3371=== CONT TestDrainTimeout3372--- PASS: TestSendPathsEmpty (0.00s)3373=== CONT TestRunNotBlockedByPoisonHead3374=== CONT TestDrainIsolatesPoisonPath3375=== CONT TestServerQueueError3376=== CONT TestServerClientIntegration3377=== CONT TestQueueRemoveLargeClosure3378=== CONT TestQueueConcurrentWriters3379=== CONT TestQueueFetchRemoveLifecycle3380=== CONT TestQueueRetryMovesToBack3381=== CONT TestQueueFetchBatchLimit3382=== CONT TestQueueRemove33832026/10/01 10:22:24 ERROR Failed to queue paths error="permission denied" count=13384=== CONT TestQueueDeduplication3385=== CONT TestQueueEnqueueAndFetch3386=== CONT TestWorkerUploadsAndRemoves3387=== CONT TestWorkerPrunesClosureDeps3388=== CONT TestFailedPathPrunedByLaterClosure3389=== CONT TestWorkerSkipsGCdPaths3390--- PASS: TestServerClientIntegration (0.00s)3391--- PASS: TestServerQueueError (0.00s)33922026/10/01 10:22:24 INFO Uploading batch count=433932026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=433942026/10/01 10:22:24 INFO Uploading batch count=233952026/10/01 10:22:24 INFO Upload queue status pending=233962026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1541216549/002/bbb3397--- PASS: TestQueueRemove (0.01s)33982026/10/01 10:22:24 INFO Uploading batch count=133992026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=134002026/10/01 10:22:24 INFO Upload queue status pending=234012026/10/01 10:22:24 INFO Uploading batch count=134022026/10/01 10:22:24 INFO Uploading batch count=234032026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=234042026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown272260977/002/a34052026/10/01 10:22:24 INFO Upload queue status pending=23406--- PASS: TestQueueFetchRemoveLifecycle (0.01s)34072026/10/01 10:22:24 INFO Uploading batch count=23408--- PASS: TestQueueEnqueueAndFetch (0.01s)34092026/10/01 10:22:24 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2029498695/002/nonexistent34102026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown272260977/002/b34112026/10/01 10:22:24 INFO Upload queue status pending=334122026/10/01 10:22:24 INFO Uploading batch count=134132026/10/01 10:22:24 INFO Uploading batch count=134142026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=13415--- PASS: TestQueueRetryMovesToBack (0.01s)34162026/10/01 10:22:24 INFO Uploading batch count=13417--- PASS: TestQueueDeduplication (0.01s)34182026/10/01 10:22:24 INFO Uploading batch count=134192026/10/01 10:22:24 INFO Uploading batch count=234202026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=234212026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown272260977/002/c34222026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown272260977/002/d34232026/10/01 10:22:24 INFO Uploading batch count=13424--- PASS: TestQueueFetchBatchLimit (0.01s)34252026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=134262026/10/01 10:22:24 INFO Uploading batch count=234272026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=234282026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown272260977/002/e34292026/10/01 10:22:24 INFO Uploading batch count=134302026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=134312026/10/01 10:22:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown272260977/002/f34322026/10/01 10:22:24 INFO Uploading batch count=134332026/10/01 10:22:24 ERROR Upload failed error="upload failed" count=13434--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)34352026/10/01 10:22:24 ERROR Drain finished with paths left in queue remaining=1034362026/10/01 10:22:24 ERROR Drain finished with paths left in queue remaining=13437--- PASS: TestDrainIsolatesPoisonPath (0.02s)3438--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3439--- PASS: TestWorkerSkipsGCdPaths (0.03s)3440--- PASS: TestWorkerPrunesClosureDeps (0.03s)3441--- PASS: TestWorkerUploadsAndRemoves (0.03s)3442--- PASS: TestQueueRemoveLargeClosure (0.15s)3443--- PASS: TestQueueConcurrentWriters (0.21s)34442026/10/01 10:22:24 ERROR Upload failed error="context deadline exceeded" count=234452026/10/01 10:22:24 ERROR Drain finished with paths left in queue remaining=43446--- PASS: TestDrainTimeout (0.22s)34472026/10/01 10:22:25 INFO Uploading batch count=134482026/10/01 10:22:25 INFO Uploading batch count=134492026/10/01 10:22:25 INFO Uploading batch count=134502026/10/01 10:22:25 ERROR Upload failed error="upload failed" count=134512026/10/01 10:22:25 INFO Uploading batch count=134522026/10/01 10:22:25 ERROR Upload failed error="upload failed" count=134532026/10/01 10:22:25 INFO Uploading batch count=134542026/10/01 10:22:25 ERROR Upload failed error="upload failed" count=134552026/10/01 10:22:25 INFO Uploading batch count=134562026/10/01 10:22:25 ERROR Upload failed error="upload failed" count=134572026/10/01 10:22:25 ERROR Drain finished with paths left in queue remaining=13458--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3459PASS