niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #305
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.07s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96=== CONT TestSetClientTLSErrors97=== CONT TestEncodeNixBase32WithRealHash98=== CONT TestPathInfoCACompatibility99=== RUN TestPathInfoCACompatibility/null_ca_field100--- PASS: TestShellSplit (0.00s)101--- PASS: TestEncodeNixBase32WithRealHash (0.00s)102=== PAUSE TestPathInfoCACompatibility/null_ca_field103=== CONT TestSetClientTLSDoesNotMutateDefaultTransport104=== RUN TestPathInfoCACompatibility/old_string_format_-_text105=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text106=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive107=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive108=== RUN TestPathInfoCACompatibility/new_structured_format_-_text109=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text110=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method111=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method112=== CONT TestStreamPushBatchesUnderLoad113=== CONT TestSetClientTLS114=== CONT TestClientSignaturesByStorePath115--- PASS: TestClientSignaturesByStorePath (0.00s)116=== CONT TestStreamPushReportsEveryPath117=== CONT TestStreamPushReportsSignatures118=== CONT TestStreamPushRequestLine119=== CONT TestStreamPushGivesUpOnDeadServer120=== CONT TestStreamPushIsolatesFailures1212026/10/01 09:15:11 ERROR Upload failed error="connection refused" count=201222026/10/01 09:15:11 ERROR Server seems unavailable, giving up on batch untried=171232026/10/01 09:15:11 ERROR Upload failed error="bad path" count=3124--- PASS: TestStreamPushReportsEveryPath (0.00s)125=== CONT TestShellSplitErrors126--- PASS: TestShellSplitErrors (0.00s)127=== CONT TestPathInfoHashCompatibility128=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)129=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)130=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon131=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon132=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI133=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI134=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha5121352026/10/01 09:15:11 ERROR Upload failed error=boom count=1136=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512137=== CONT TestParsePathInfoJSONMultiplePaths138=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths139=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1402026/10/01 09:15:11 ERROR Upload failed error=boom count=1141--- PASS: TestStreamPushIsolatesFailures (0.00s)142=== CONT TestParsePathInfoJSON143--- PASS: TestStreamPushReportsSignatures (0.00s)144=== CONT TestGetStorePathHash145=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths146=== RUN TestGetStorePathHash/valid_store_path147=== RUN TestParsePathInfoJSON/Nix_format148--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)149=== CONT TestUploadMultipart_SupersededByPeer150=== RUN TestUploadMultipart_SupersededByPeer/exists151=== PAUSE TestUploadMultipart_SupersededByPeer/exists152=== RUN TestUploadMultipart_SupersededByPeer/missing153=== PAUSE TestUploadMultipart_SupersededByPeer/missing154=== CONT TestEncodeNixBase32155=== RUN TestEncodeNixBase32/test_string_hash156=== PAUSE TestEncodeNixBase32/test_string_hash157=== PAUSE TestGetStorePathHash/valid_store_path158=== RUN TestEncodeNixBase32/empty_input159=== PAUSE TestEncodeNixBase32/empty_input160=== PAUSE TestParsePathInfoJSON/Nix_format161=== RUN TestParsePathInfoJSON/Lix_format162=== PAUSE TestParsePathInfoJSON/Lix_format163=== CONT TestDumpPathWriterError164=== RUN TestParsePathInfoJSON/empty_input165=== RUN TestGetStorePathHash/basename_without_hyphen_should_error166=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error167=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error168=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error169=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error170=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error171=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths172=== CONT TestDumpPathSingleFile173=== PAUSE TestParsePathInfoJSON/empty_input174=== RUN TestParsePathInfoJSON/whitespace_only175=== PAUSE TestParsePathInfoJSON/whitespace_only176=== RUN TestParsePathInfoJSON/invalid_JSON177=== PAUSE TestParsePathInfoJSON/invalid_JSON178=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess179=== CONT TestDumpPathMatchesNix1802026/10/01 09:15:11 WARN Rate limiter enabled after throttle name=server-test rate=5181=== RUN TestSetClientTLSErrors/missing_cert_file182=== PAUSE TestSetClientTLSErrors/missing_cert_file183=== RUN TestSetClientTLSErrors/missing_key_file184=== PAUSE TestSetClientTLSErrors/missing_key_file185=== RUN TestSetClientTLSErrors/missing_ca_file186=== PAUSE TestSetClientTLSErrors/missing_ca_file187=== RUN TestSetClientTLSErrors/invalid_ca_file188=== PAUSE TestSetClientTLSErrors/invalid_ca_file189=== CONT TestRateLimiterFeedback190=== RUN TestRateLimiterFeedback/429_enables_limiter191=== PAUSE TestRateLimiterFeedback/429_enables_limiter192=== RUN TestRateLimiterFeedback/503_enables_limiter193=== PAUSE TestRateLimiterFeedback/503_enables_limiter194=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter195=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter196=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter197=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter198=== CONT TestScriptTokenCachesUntilRefresh199=== RUN TestSetClientTLS/rejects_connection_without_client_cert200=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert201=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA202--- PASS: TestDoServerRequestAttachesToken (0.00s)203=== CONT TestScriptTokenEmptyCommand204--- PASS: TestScriptTokenEmptyCommand (0.00s)205=== CONT TestScriptTokenScriptFails206--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)207=== CONT TestScriptTokenBadJSON208=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA209=== RUN TestSetClientTLS/preserves_debug_logging_transport210=== PAUSE TestSetClientTLS/preserves_debug_logging_transport211=== CONT TestScriptTokenEmptyToken212--- PASS: TestScriptTokenScriptFails (0.00s)213=== CONT TestFileTokenMissing214--- PASS: TestFileTokenMissing (0.00s)215=== CONT TestScriptTokenNoExpiryRerunsEveryCall216--- PASS: TestScriptTokenBadJSON (0.01s)217=== CONT TestFileTokenEmpty218--- PASS: TestStreamPushRequestLine (0.01s)219=== CONT TestConvertHashToNix32220=== RUN TestConvertHashToNix32/SRI_format_to_Nix32221=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32222=== RUN TestConvertHashToNix32/already_Nix32_format223=== PAUSE TestConvertHashToNix32/already_Nix32_format224=== RUN TestConvertHashToNix32/invalid_format225=== PAUSE TestConvertHashToNix32/invalid_format226=== CONT TestFileTokenReadsAndCaches227--- PASS: TestFileTokenEmpty (0.00s)228=== CONT TestStaticToken229--- PASS: TestStaticToken (0.00s)230=== CONT TestDoWithRetry_BodyReplayedViaGetBody231--- PASS: TestFileTokenReadsAndCaches (0.00s)2322026/10/01 09:15:11 WARN Rate limiter enabled after throttle name=server-test rate=5233=== CONT TestCaseHackSuffix2342026/10/01 09:15:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:62051235--- PASS: TestScriptTokenEmptyToken (0.01s)236=== CONT TestRegisterUploadedObjectReusesConnections2372026/10/01 09:15:11 WARN Rate limiter backed off name=server-test rate=52382026/10/01 09:15:11 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:62051239--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)240=== CONT TestPartSizeForNAR241=== RUN TestPartSizeForNAR/zero_stays_at_minimum242=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum243=== RUN TestPartSizeForNAR/small_stays_at_minimum244=== PAUSE TestPartSizeForNAR/small_stays_at_minimum245=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum246=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum247=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts248=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts249=== RUN TestPartSizeForNAR/1_TiB250=== PAUSE TestPartSizeForNAR/1_TiB251=== RUN TestPartSizeForNAR/5_TiB_S3_max_object252=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object253=== RUN TestPartSizeForNAR/capped_at_5_GiB254=== PAUSE TestPartSizeForNAR/capped_at_5_GiB255=== CONT TestFilterOversizedClosures256=== RUN TestFilterOversizedClosures/no_limit_keeps_everything257=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything258=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped259=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== RUN TestFilterOversizedClosures/all_closures_skipped261=== PAUSE TestFilterOversizedClosures/all_closures_skipped262=== CONT TestUploadMultipart_PartsInParallel263--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)264=== CONT TestResolveStorePath265--- PASS: TestResolveStorePath (0.00s)266=== CONT TestPathInfoCACompatibility/null_ca_field267=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive268=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method269=== CONT TestPathInfoCACompatibility/new_structured_format_-_text270=== CONT TestPathInfoCACompatibility/old_string_format_-_text271--- PASS: TestPathInfoCACompatibility (0.00s)272 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)273 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)274 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)275 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)276 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)277=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)278=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI280=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon281--- PASS: TestPathInfoHashCompatibility (0.00s)282 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)283 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)284 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)285 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)286=== CONT TestUploadMultipart_SupersededByPeer/exists287=== CONT TestUploadMultipart_SupersededByPeer/missing288--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)289 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)290 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)291=== CONT TestEncodeNixBase32/test_string_hash292=== CONT TestEncodeNixBase32/empty_input293--- PASS: TestEncodeNixBase32 (0.00s)294 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)295 --- PASS: TestEncodeNixBase32/empty_input (0.00s)296=== CONT TestGetStorePathHash/valid_store_path297=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths298=== CONT TestParsePathInfoJSON/Nix_format299=== CONT TestGetStorePathHash/basename_without_hyphen_should_error300=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error301=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error302--- PASS: TestGetStorePathHash (0.00s)303 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)304 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)305 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)306 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)307=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths308--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)309 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)310 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)311=== CONT TestParsePathInfoJSON/Lix_format312=== CONT TestParsePathInfoJSON/invalid_JSON313=== CONT TestParsePathInfoJSON/whitespace_only314=== CONT TestParsePathInfoJSON/empty_input315--- PASS: TestParsePathInfoJSON (0.00s)316 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)317 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)318 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)319 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)320 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)321=== CONT TestSetClientTLSErrors/missing_cert_file322=== CONT TestSetClientTLSErrors/missing_ca_file323=== CONT TestSetClientTLSErrors/invalid_ca_file324=== CONT TestSetClientTLSErrors/missing_key_file325--- PASS: TestSetClientTLSErrors (0.00s)326 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)327 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)328 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)329 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)330=== CONT TestRateLimiterFeedback/429_enables_limiter3312026/10/01 09:15:11 WARN Rate limiter enabled after throttle name=server-test rate=53322026/10/01 09:15:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:621273332026/10/01 09:15:11 WARN Rate limiter backed off name=server-test rate=5334=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter335=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter336=== CONT TestRateLimiterFeedback/503_enables_limiter337--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)338=== CONT TestSetClientTLS/rejects_connection_without_client_cert3392026/10/01 09:15:11 WARN Rate limiter enabled after throttle name=server-test rate=53402026/10/01 09:15:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:621333412026/10/01 09:15:11 WARN Rate limiter backed off name=server-test rate=5342--- PASS: TestRateLimiterFeedback (0.00s)343 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)344 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)345 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)346 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)347=== CONT TestSetClientTLS/preserves_debug_logging_transport348=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA349--- PASS: TestDumpPathWriterError (0.05s)350=== CONT TestConvertHashToNix32/SRI_format_to_Nix32351=== CONT TestConvertHashToNix32/invalid_format352=== CONT TestConvertHashToNix32/already_Nix32_format353--- PASS: TestConvertHashToNix32 (0.00s)354 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)355 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)356 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)357=== CONT TestPartSizeForNAR/zero_stays_at_minimum358=== CONT TestPartSizeForNAR/1_TiB359=== CONT TestPartSizeForNAR/capped_at_5_GiB360=== CONT TestPartSizeForNAR/5_TiB_S3_max_object361=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts362=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum363=== CONT TestPartSizeForNAR/small_stays_at_minimum364--- PASS: TestPartSizeForNAR (0.00s)365 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)366 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)367 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)368 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)369 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)370 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)372=== CONT TestFilterOversizedClosures/no_limit_keeps_everything373=== CONT TestFilterOversizedClosures/all_closures_skipped3742026/10/01 09:15:11 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50375=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3762026/10/01 09:15:11 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=2000377--- PASS: TestFilterOversizedClosures (0.00s)378 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)379 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)380 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)381--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)3822026/10/01 09:15:12 http: TLS handshake error from 127.0.0.1:62135: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.01s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestDumpPathSingleFile (0.06s)388--- PASS: TestCaseHackSuffix (0.05s)389--- PASS: TestDumpPathMatchesNix (0.09s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestUploadMultipart_PartsInParallel (0.62s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld1".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-13789-2688134661/postgres1767795411/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-13789-2688134661/postgres1767795411/data -l logfile start4214222026-10-01 09:15:13.662 UTC [13860] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4232026-10-01 09:15:13.662 UTC [13860] LOG: listening on Unix socket "/nix/var/nix/builds/nix-13789-2688134661/postgres1767795411/.s.PGSQL.5432"4242026-10-01 09:15:13.664 UTC [13868] LOG: database system was shut down at 2026-10-01 09:15:13 UTC4252026-10-01 09:15:13.664 UTC [13869] FATAL: the database system is starting up426/nix/var/nix/builds/nix-13789-2688134661/postgres1767795411:5432 - rejecting connections4272026-10-01 09:15:13.665 UTC [13860] LOG: database system is ready to accept connections428/nix/var/nix/builds/nix-13789-2688134661/postgres1767795411:5432 - accepting connections429{"timestamp":"2026-10-01T09:15:13.887408Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c9f86511-b1eb-4860-8418-9e1fd3179bce","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:15:14.078 UTC [13903] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:15:14.078 UTC [13903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:15:14 OK 20241026095416_initial_model.sql (3.43ms)4762026/10/01 09:15:14 OK 20251210153512_drop_unused_gin_index.sql (385.38µs)4772026/10/01 09:15:14 OK 20251218171726_add_pins.sql (823.42µs)4782026/10/01 09:15:14 OK 20260628120000_add_object_size_and_stats.sql (835µs)4792026/10/01 09:15:14 OK 20260905000000_add_claims.sql (910.75µs)4802026/10/01 09:15:14 OK 20260920000000_drop_claims.sql (571.96µs)4812026/10/01 09:15:14 OK 20260923120000_add_pushes.sql (389.25µs)4822026/10/01 09:15:14 goose: successfully migrated database to version: 202609231200004832026/10/01 09:15:14 OK 1_commit_pending_closure.sql (856.33µs)4842026/10/01 09:15:14 OK 2_object_stats_trigger.sql (249.75µs)4852026/10/01 09:15:14 OK 3_commit_push.sql (179.38µs)4862026/10/01 09:15:14 goose: up to current file version: 34872026/10/01 09:15:14 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:15:14 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:15:14 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:15:14 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.81s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:15:14.841 UTC [13916] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:15:14.841 UTC [13916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:15:14 OK 20241026095416_initial_model.sql (3.05ms)4982026/10/01 09:15:14 OK 20251210153512_drop_unused_gin_index.sql (366.88µs)4992026/10/01 09:15:14 OK 20251218171726_add_pins.sql (729.63µs)5002026/10/01 09:15:14 OK 20260628120000_add_object_size_and_stats.sql (764.58µs)5012026/10/01 09:15:14 OK 20260905000000_add_claims.sql (881.29µs)5022026/10/01 09:15:14 OK 20260920000000_drop_claims.sql (581.08µs)5032026/10/01 09:15:14 OK 20260923120000_add_pushes.sql (389.75µs)5042026/10/01 09:15:14 goose: successfully migrated database to version: 202609231200005052026/10/01 09:15:14 OK 1_commit_pending_closure.sql (872.17µs)5062026/10/01 09:15:14 OK 2_object_stats_trigger.sql (222.79µs)5072026/10/01 09:15:14 OK 3_commit_push.sql (153.13µs)5082026/10/01 09:15:14 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.14s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCTaskStore_StartNew543=== PAUSE TestGCTaskStore_StartNew544=== RUN TestGCTaskStore_DeduplicateSameParams545=== PAUSE TestGCTaskStore_DeduplicateSameParams546=== RUN TestGCTaskStore_ConflictDifferentParams547=== PAUSE TestGCTaskStore_ConflictDifferentParams548=== RUN TestGCTaskStore_GetEmpty549=== PAUSE TestGCTaskStore_GetEmpty550=== RUN TestGCTaskStore_GetReturnsLatest551=== PAUSE TestGCTaskStore_GetReturnsLatest552=== RUN TestGCTaskStore_CompletedAllowsNewTask553=== PAUSE TestGCTaskStore_CompletedAllowsNewTask554=== RUN TestGCTaskStore_PhaseUpdates555=== PAUSE TestGCTaskStore_PhaseUpdates556=== RUN TestGCTaskStore_Fail557=== PAUSE TestGCTaskStore_Fail558=== RUN TestGracefulShutdownDrainsInflight559=== PAUSE TestGracefulShutdownDrainsInflight560=== RUN TestService_healthCheckHandler561=== PAUSE TestService_healthCheckHandler562=== RUN TestService_readinessHandler563=== PAUSE TestService_readinessHandler564=== RUN TestGenerateLandingPage565=== PAUSE TestGenerateLandingPage566=== RUN TestCacheConfigHandlerMaxNarSize567=== PAUSE TestCacheConfigHandlerMaxNarSize568=== RUN TestCreatePendingClosureRejectsOversizedNAR569=== PAUSE TestCreatePendingClosureRejectsOversizedNAR570=== RUN TestNARDeduplicationMetadataUploadBug571=== PAUSE TestNARDeduplicationMetadataUploadBug572=== RUN TestMetricsInventory573=== PAUSE TestMetricsInventory574=== RUN TestService_NativeMTLS575=== PAUSE TestService_NativeMTLS576=== RUN TestServerTLSConfig577=== PAUSE TestServerTLSConfig578=== RUN TestMultipartCleanup579=== PAUSE TestMultipartCleanup580=== RUN TestObjectStatsTrigger581=== PAUSE TestObjectStatsTrigger582=== RUN TestOrphanedObjectsGC583=== PAUSE TestOrphanedObjectsGC584=== RUN TestOrphanedObjectsGCStressTest585=== PAUSE TestOrphanedObjectsGCStressTest586=== RUN TestCreatePin_ReservedPins587=== PAUSE TestCreatePin_ReservedPins588=== RUN TestParseSingleRange589=== PAUSE TestParseSingleRange590=== RUN TestProxyHeadersOnlyTrustedOnSocket591=== PAUSE TestProxyHeadersOnlyTrustedOnSocket592=== RUN TestIsValidCachePath593=== PAUSE TestIsValidCachePath594=== RUN TestReadProxyNarinfo595=== PAUSE TestReadProxyNarinfo596=== RUN TestReadProxyNarinfoAlreadyDecompressed597=== PAUSE TestReadProxyNarinfoAlreadyDecompressed598=== RUN TestReadProxyNarStreaming599=== PAUSE TestReadProxyNarStreaming600=== RUN TestReadProxy404601=== PAUSE TestReadProxy404602=== RUN TestReadProxyInvalidPath603=== PAUSE TestReadProxyInvalidPath604=== RUN TestReadProxyHead605=== PAUSE TestReadProxyHead606=== RUN TestReadProxyConditionalGet607=== PAUSE TestReadProxyConditionalGet608=== RUN TestReadProxyRootRedirectsToIndexHTML609=== PAUSE TestReadProxyRootRedirectsToIndexHTML610=== RUN TestReadProxyDisabled611=== PAUSE TestReadProxyDisabled612=== RUN TestReadRedirectNar613=== PAUSE TestReadRedirectNar614=== RUN TestReadRedirectKeepsNarinfoProxied615=== PAUSE TestReadRedirectKeepsNarinfoProxied616=== RUN TestReadProxyRangeRequest617=== PAUSE TestReadProxyRangeRequest618=== RUN TestReadRedirectUsesPublicS3URL619=== PAUSE TestReadRedirectUsesPublicS3URL620=== RUN TestPush_OverlappingRootsStoreOneRowPerKey621=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey622=== RUN TestPush_CompleteCommitsEveryRoot623=== PAUSE TestPush_CompleteCommitsEveryRoot624=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit625=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit626=== RUN TestPush_RejectsBadRequests627=== PAUSE TestPush_RejectsBadRequests628=== RUN TestPush_SignsNarinfosOfItsPendingObjects629=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects630=== RUN TestRedundantMultipartUpload631=== PAUSE TestRedundantMultipartUpload632=== RUN TestCompleteMultipartUpload_ErrorButObjectExists633=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists634=== RUN TestCompletedNarNotReofferedAcrossClosures635=== PAUSE TestCompletedNarNotReofferedAcrossClosures636=== RUN TestPresignedUploadRegisteredBeforeCommit637=== PAUSE TestPresignedUploadRegisteredBeforeCommit638=== RUN TestService_Rustfstest639=== PAUSE TestService_Rustfstest640=== RUN TestParseSize641=== PAUSE TestParseSize642=== RUN TestSkippedUploadsHandler643=== PAUSE TestSkippedUploadsHandler644=== RUN TestSystemdListenerNotActivated645--- PASS: TestSystemdListenerNotActivated (0.00s)646=== RUN TestWatchdogBeatsWhenHealthy647--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)648=== RUN TestWatchdogSkipsWhenUnhealthy6492026/10/01 09:15:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6502026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6512026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6522026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6532026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6542026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:15:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"658--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)659=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle660=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle661=== RUN TestProxyWriteTimeout662=== PAUSE TestProxyWriteTimeout663=== RUN TestIsValidUploadKey664=== PAUSE TestIsValidUploadKey665=== RUN TestUploadHandlersRejectInvalidKeys666=== PAUSE TestUploadHandlersRejectInvalidKeys667=== RUN TestUploadHandlersRejectOversizedBody668=== PAUSE TestUploadHandlersRejectOversizedBody669=== RUN TestService_cleanupPendingClosuresHandler670=== PAUSE TestService_cleanupPendingClosuresHandler671=== RUN TestService_createPendingClosureHandler672=== PAUSE TestService_createPendingClosureHandler673=== RUN TestService_verifyS3Integrity674=== PAUSE TestService_verifyS3Integrity675=== RUN TestCompleteMultipartUnregistered676=== PAUSE TestCompleteMultipartUnregistered677=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT678=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT679=== CONT TestService_AuthMiddleware680=== CONT TestUploadHandlersRejectInvalidKeys681=== CONT TestReadProxyRootRedirectsToIndexHTML682=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info683=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info684=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal685=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal686=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key687=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key688=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key689=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key690=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT691=== CONT TestCompleteMultipartUnregistered692=== CONT TestService_verifyS3Integrity693=== CONT TestService_createPendingClosureHandler694=== CONT TestService_cleanupPendingClosuresHandler695=== CONT TestUploadHandlersRejectOversizedBody696=== CONT TestCacheConfigHandlerMaxNarSize697=== CONT TestCreatePin_ReservedPins698--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)699=== CONT TestReadProxyConditionalGet700=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure701=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure702=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart703=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart704=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts705=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts706=== CONT TestReadProxyHead7072026/10/01 09:15:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62157/oidc7082026-10-01 09:15:15.383 UTC [13940] ERROR: relation "goose_db_version" does not exist at character 367092026-10-01 09:15:15.383 UTC [13940] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7102026-10-01 09:15:15.396 UTC [13941] ERROR: relation "goose_db_version" does not exist at character 367112026-10-01 09:15:15.396 UTC [13941] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7122026-10-01 09:15:15.398 UTC [13944] ERROR: relation "goose_db_version" does not exist at character 367132026-10-01 09:15:15.398 UTC [13944] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7142026-10-01 09:15:15.399 UTC [13942] ERROR: relation "goose_db_version" does not exist at character 367152026-10-01 09:15:15.399 UTC [13942] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7162026-10-01 09:15:15.399 UTC [13945] ERROR: relation "goose_db_version" does not exist at character 367172026-10-01 09:15:15.399 UTC [13945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7182026-10-01 09:15:15.401 UTC [13943] ERROR: relation "goose_db_version" does not exist at character 367192026-10-01 09:15:15.401 UTC [13943] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7202026-10-01 09:15:15.401 UTC [13946] ERROR: relation "goose_db_version" does not exist at character 367212026-10-01 09:15:15.401 UTC [13946] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7222026/10/01 09:15:15 OK 20241026095416_initial_model.sql (9.72ms)7232026-10-01 09:15:15.402 UTC [13947] ERROR: relation "goose_db_version" does not exist at character 367242026-10-01 09:15:15.402 UTC [13947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (1.42ms)7262026-10-01 09:15:15.406 UTC [13948] ERROR: relation "goose_db_version" does not exist at character 367272026-10-01 09:15:15.406 UTC [13948] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7282026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.48ms)7292026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (2.32ms)7302026-10-01 09:15:15.412 UTC [13949] ERROR: relation "goose_db_version" does not exist at character 367312026-10-01 09:15:15.412 UTC [13949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7322026/10/01 09:15:15 OK 20241026095416_initial_model.sql (9.35ms)7332026/10/01 09:15:15 OK 20260905000000_add_claims.sql (3.47ms)7342026/10/01 09:15:15 OK 20241026095416_initial_model.sql (7.66ms)7352026/10/01 09:15:15 OK 20241026095416_initial_model.sql (9.27ms)7362026/10/01 09:15:15 OK 20241026095416_initial_model.sql (6.52ms)7372026/10/01 09:15:15 OK 20241026095416_initial_model.sql (8.92ms)7382026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (663.92µs)7392026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (1.43ms)7402026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)7412026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)7422026/10/01 09:15:15 OK 20241026095416_initial_model.sql (8.72ms)7432026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (1.08ms)7442026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (788.17µs)7452026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (706.13µs)7462026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (1.24ms)7472026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200007482026/10/01 09:15:15 OK 20241026095416_initial_model.sql (9.32ms)7492026/10/01 09:15:15 OK 20251218171726_add_pins.sql (1.63ms)7502026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (687.79µs)7512026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.35ms)7522026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.06ms)7532026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.01ms)7542026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.01ms)7552026/10/01 09:15:15 OK 20251218171726_add_pins.sql (1.54ms)7562026/10/01 09:15:15 OK 1_commit_pending_closure.sql (1.55ms)7572026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (1.98ms)7582026/10/01 09:15:15 OK 2_object_stats_trigger.sql (704.92µs)7592026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (1.4ms)7602026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (1.73ms)7612026/10/01 09:15:15 OK 3_commit_push.sql (711.29µs)7622026/10/01 09:15:15 goose: up to current file version: 37632026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (1.84ms)7642026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.3ms)7652026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (2.1ms)7662026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (1.99ms)7672026/10/01 09:15:15 OK 20241026095416_initial_model.sql (7.06ms)7682026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (1.57ms)7692026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (999.54µs)7702026/10/01 09:15:15 OK 20260905000000_add_claims.sql (2.77ms)7712026/10/01 09:15:15 OK 20260905000000_add_claims.sql (2.29ms)7722026/10/01 09:15:15 OK 20260905000000_add_claims.sql (2.16ms)7732026/10/01 09:15:15 OK 20260905000000_add_claims.sql (2.09ms)7742026/10/01 09:15:15 OK 20260905000000_add_claims.sql (2.28ms)7752026/10/01 09:15:15 OK 20260905000000_add_claims.sql (3.48ms)7762026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (1.37ms)7772026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (1.5ms)7782026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (1.83ms)7792026/10/01 09:15:15 OK 20251218171726_add_pins.sql (2.1ms)7802026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (3.4ms)7812026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (3.91ms)7822026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (3.75ms)7832026/10/01 09:15:15 OK 20260905000000_add_claims.sql (5.89ms)7842026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (3.8ms)7852026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200007862026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (1.56ms)7872026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200007882026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (1.7ms)7892026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200007902026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (4.18ms)7912026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200007922026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (3.9ms)7932026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200007942026/10/01 09:15:15 OK 20241026095416_initial_model.sql (9.83ms)7952026/10/01 09:15:15 OK 1_commit_pending_closure.sql (985.38µs)7962026/10/01 09:15:15 OK 1_commit_pending_closure.sql (934µs)7972026/10/01 09:15:15 OK 1_commit_pending_closure.sql (907.08µs)7982026/10/01 09:15:15 OK 1_commit_pending_closure.sql (1.17ms)7992026/10/01 09:15:15 OK 2_object_stats_trigger.sql (384.08µs)8002026/10/01 09:15:15 OK 1_commit_pending_closure.sql (1.34ms)8012026/10/01 09:15:15 OK 2_object_stats_trigger.sql (279.54µs)8022026/10/01 09:15:15 OK 2_object_stats_trigger.sql (402.92µs)8032026/10/01 09:15:15 OK 3_commit_push.sql (196.92µs)8042026/10/01 09:15:15 goose: up to current file version: 38052026/10/01 09:15:15 OK 3_commit_push.sql (216.96µs)8062026/10/01 09:15:15 goose: up to current file version: 38072026/10/01 09:15:15 OK 2_object_stats_trigger.sql (258.92µs)8082026/10/01 09:15:15 OK 2_object_stats_trigger.sql (251.38µs)8092026/10/01 09:15:15 OK 3_commit_push.sql (254.58µs)8102026/10/01 09:15:15 goose: up to current file version: 38112026/10/01 09:15:15 OK 3_commit_push.sql (147.25µs)8122026/10/01 09:15:15 goose: up to current file version: 38132026/10/01 09:15:15 OK 3_commit_push.sql (163.79µs)8142026/10/01 09:15:15 goose: up to current file version: 38152026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (45.01ms)8162026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (42.24ms)8172026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200008182026/10/01 09:15:15 OK 20251210153512_drop_unused_gin_index.sql (41.88ms)8192026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (42.41ms)8202026/10/01 09:15:15 OK 1_commit_pending_closure.sql (880.04µs)8212026/10/01 09:15:15 OK 2_object_stats_trigger.sql (191.75µs)8222026/10/01 09:15:15 OK 3_commit_push.sql (151.04µs)8232026/10/01 09:15:15 goose: up to current file version: 38242026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (6.49ms)8252026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200008262026/10/01 09:15:15 OK 20251218171726_add_pins.sql (7ms)8272026/10/01 09:15:15 OK 1_commit_pending_closure.sql (831.75µs)8282026/10/01 09:15:15 OK 2_object_stats_trigger.sql (159.92µs)8292026/10/01 09:15:15 OK 3_commit_push.sql (135.54µs)8302026/10/01 09:15:15 goose: up to current file version: 38312026/10/01 09:15:15 OK 20260905000000_add_claims.sql (13.54ms)8322026/10/01 09:15:15 OK 20260628120000_add_object_size_and_stats.sql (7.15ms)8332026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (1.46ms)8342026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (3.67ms)8352026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200008362026/10/01 09:15:15 OK 20260905000000_add_claims.sql (4.17ms)8372026/10/01 09:15:15 OK 1_commit_pending_closure.sql (813.04µs)8382026/10/01 09:15:15 OK 2_object_stats_trigger.sql (175.79µs)8392026/10/01 09:15:15 OK 3_commit_push.sql (161.38µs)8402026/10/01 09:15:15 goose: up to current file version: 38412026/10/01 09:15:15 OK 20260920000000_drop_claims.sql (4.19ms)8422026/10/01 09:15:15 OK 20260923120000_add_pushes.sql (675.79µs)8432026/10/01 09:15:15 goose: successfully migrated database to version: 202609231200008442026/10/01 09:15:15 OK 1_commit_pending_closure.sql (699.29µs)8452026/10/01 09:15:15 OK 2_object_stats_trigger.sql (163.25µs)8462026/10/01 09:15:15 OK 3_commit_push.sql (154.29µs)8472026/10/01 09:15:15 goose: up to current file version: 38482026/10/01 09:15:15 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"849--- PASS: TestService_AuthMiddleware (0.35s)850=== CONT TestReadProxyInvalidPath851--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.49s)852=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info8532026/10/01 09:15:15 INFO Received uploads request method=POST path=/854=== CONT TestOrphanedObjectsGC8552026/10/01 09:15:15 INFO Received cleanup request method=DELETE path=/api/pending_closures8562026/10/01 09:15:15 INFO Aborted multipart uploads count=08572026/10/01 09:15:15 INFO Received uploads request method=POST path=/api/pending_closures8582026/10/01 09:15:15 INFO Received cleanup request method=DELETE path=/api/pending_closures8592026/10/01 09:15:15 INFO Aborted multipart uploads count=18602026/10/01 09:15:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8612026-10-01 09:15:15.890 UTC [13942] ERROR: Closure does not exist: id=18622026-10-01 09:15:15.890 UTC [13942] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE8632026-10-01 09:15:15.890 UTC [13942] STATEMENT: -- name: CommitPendingClosure :exec864 SELECT commit_pending_closure($1::bigint)865 866--- PASS: TestService_cleanupPendingClosuresHandler (0.72s)867=== CONT TestReadProxy4048682026/10/01 09:15:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8692026/10/01 09:15:15 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst870--- PASS: TestCompleteMultipartUnregistered (0.82s)871=== CONT TestOrphanedObjectsGCStressTest8722026/10/01 09:15:16 INFO Received uploads request method=POST path=/api/pending_closures8732026-10-01 09:15:16.176 UTC [13960] ERROR: relation "goose_db_version" does not exist at character 368742026-10-01 09:15:16.176 UTC [13960] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8752026/10/01 09:15:16 OK 20241026095416_initial_model.sql (95.37ms)8762026/10/01 09:15:16 OK 20251210153512_drop_unused_gin_index.sql (13.27ms)8772026/10/01 09:15:16 INFO Received uploads request method=POST path=/api/pending_closures8782026/10/01 09:15:16 OK 20251218171726_add_pins.sql (24.37ms)8792026-10-01 09:15:16.351 UTC [13963] ERROR: relation "goose_db_version" does not exist at character 368802026-10-01 09:15:16.351 UTC [13963] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8812026/10/01 09:15:16 OK 20260628120000_add_object_size_and_stats.sql (29.04ms)882--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.22s)883=== CONT TestReadProxyNarStreaming8842026/10/01 09:15:16 OK 20260905000000_add_claims.sql (33.87ms)8852026/10/01 09:15:16 OK 20260920000000_drop_claims.sql (17.56ms)8862026/10/01 09:15:16 OK 20260923120000_add_pushes.sql (7.47ms)8872026/10/01 09:15:16 goose: successfully migrated database to version: 202609231200008882026/10/01 09:15:16 OK 1_commit_pending_closure.sql (1.95ms)8892026/10/01 09:15:16 OK 2_object_stats_trigger.sql (397.75µs)8902026/10/01 09:15:16 OK 3_commit_push.sql (377.42µs)8912026/10/01 09:15:16 goose: up to current file version: 38922026/10/01 09:15:16 INFO Received uploads request method=POST path=/api/pending_closures8932026/10/01 09:15:16 INFO Received uploads request method=POST path=/api/pending_closures8942026/10/01 09:15:16 INFO Received uploads request method=POST path=/api/pending_closures8952026-10-01 09:15:16.544 UTC [13966] ERROR: relation "goose_db_version" does not exist at character 368962026-10-01 09:15:16.544 UTC [13966] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8972026/10/01 09:15:16 OK 20241026095416_initial_model.sql (176.13ms)8982026/10/01 09:15:16 OK 20251210153512_drop_unused_gin_index.sql (21.39ms)8992026/10/01 09:15:16 OK 20251218171726_add_pins.sql (26.59ms)9002026/10/01 09:15:16 OK 20260628120000_add_object_size_and_stats.sql (8.41ms)9012026/10/01 09:15:16 OK 20260905000000_add_claims.sql (24.5ms)9022026/10/01 09:15:16 OK 20260920000000_drop_claims.sql (51.04ms)9032026/10/01 09:15:16 OK 20260923120000_add_pushes.sql (17.06ms)9042026/10/01 09:15:16 goose: successfully migrated database to version: 202609231200009052026/10/01 09:15:16 OK 1_commit_pending_closure.sql (4.11ms)9062026/10/01 09:15:16 OK 2_object_stats_trigger.sql (906.21µs)9072026/10/01 09:15:16 OK 3_commit_push.sql (681µs)9082026/10/01 09:15:16 goose: up to current file version: 39092026/10/01 09:15:16 OK 20241026095416_initial_model.sql (112.67ms)9102026-10-01 09:15:16.734 UTC [13967] ERROR: relation "goose_db_version" does not exist at character 369112026-10-01 09:15:16.734 UTC [13967] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9122026/10/01 09:15:16 OK 20251210153512_drop_unused_gin_index.sql (11.73ms)9132026/10/01 09:15:16 OK 20251218171726_add_pins.sql (12.72ms)9142026/10/01 09:15:16 OK 20260628120000_add_object_size_and_stats.sql (11.1ms)9152026/10/01 09:15:16 OK 20260905000000_add_claims.sql (58.73ms)916--- PASS: TestReadProxyConditionalGet (1.67s)917=== CONT TestCreatePendingClosureRejectsOversizedNAR9182026/10/01 09:15:16 INFO Received uploads request method=POST path=/api/pending_closures919--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)920=== CONT TestMultipartCleanup9212026/10/01 09:15:16 OK 20260920000000_drop_claims.sql (27.09ms)9222026/10/01 09:15:16 OK 20260923120000_add_pushes.sql (10.57ms)9232026/10/01 09:15:16 goose: successfully migrated database to version: 202609231200009242026/10/01 09:15:16 OK 1_commit_pending_closure.sql (2.58ms)9252026/10/01 09:15:16 OK 2_object_stats_trigger.sql (411.38µs)9262026/10/01 09:15:16 OK 3_commit_push.sql (330.75µs)9272026/10/01 09:15:16 goose: up to current file version: 39282026/10/01 09:15:16 OK 20241026095416_initial_model.sql (154.68ms)9292026/10/01 09:15:16 OK 20251210153512_drop_unused_gin_index.sql (11.12ms)9302026/10/01 09:15:16 OK 20251218171726_add_pins.sql (29.51ms)9312026/10/01 09:15:16 OK 20260628120000_add_object_size_and_stats.sql (17.42ms)9322026/10/01 09:15:17 OK 20260905000000_add_claims.sql (41.47ms)9332026/10/01 09:15:17 OK 20260920000000_drop_claims.sql (31.42ms)9342026/10/01 09:15:17 OK 20260923120000_add_pushes.sql (8.11ms)9352026/10/01 09:15:17 goose: successfully migrated database to version: 202609231200009362026/10/01 09:15:17 OK 1_commit_pending_closure.sql (2.82ms)9372026/10/01 09:15:17 OK 2_object_stats_trigger.sql (915.79µs)9382026/10/01 09:15:17 OK 3_commit_push.sql (487µs)9392026/10/01 09:15:17 goose: up to current file version: 3940--- PASS: TestReadProxyHead (1.90s)941=== CONT TestServerTLSConfig942=== RUN TestServerTLSConfig/no_client_CA943=== PAUSE TestServerTLSConfig/no_client_CA944=== RUN TestServerTLSConfig/missing_CA_file945=== PAUSE TestServerTLSConfig/missing_CA_file946=== RUN TestServerTLSConfig/not_a_PEM_file947=== PAUSE TestServerTLSConfig/not_a_PEM_file948=== CONT TestService_NativeMTLS9492026/10/01 09:15:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9502026/10/01 09:15:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9512026/10/01 09:15:17 WARN Refused reserved pin name=worker-x86_64-linux9522026/10/01 09:15:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9532026/10/01 09:15:17 INFO Received create pin request method=POST path=/api/pins/my-app9542026/10/01 09:15:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux955--- PASS: TestCreatePin_ReservedPins (2.14s)956=== CONT TestMetricsInventory9572026/10/01 09:15:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZjdhYWUyZDItNWQ0Yi00NWJkLThjZDQtNDNlYWJmNmM2OGI2LmYzMDU1NjIwLWVhNDMtNDVhYi1hYTgwLTJiY2NkMWJjMmNlZXgxNzkwODQ2MTE2MTQ3MTQ4MDAw parts=109582026/10/01 09:15:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9592026/10/01 09:15:17 INFO Completed upload id=19602026/10/01 09:15:17 INFO Received uploads request method=POST path=/api/pending_closures9612026/10/01 09:15:17 INFO Received uploads request method=POST path=/api/pending_closures9622026/10/01 09:15:17 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9632026/10/01 09:15:17 WARN Found objects in DB but missing from S3, will re-upload count=1964--- PASS: TestService_verifyS3Integrity (2.19s)965=== CONT TestNARDeduplicationMetadataUploadBug966--- PASS: TestReadProxyInvalidPath (1.97s)967=== CONT TestReadProxyNarinfoAlreadyDecompressed9682026/10/01 09:15:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9692026/10/01 09:15:17 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZjdhYWUyZDItNWQ0Yi00NWJkLThjZDQtNDNlYWJmNmM2OGI2LjliMjBhZWNlLWIxMmYtNGQxMC1hMzc2LTk3ODJmMDk3ODJiNngxNzkwODQ2MTE2NTc4MDA5MDAw parts=109702026/10/01 09:15:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9712026/10/01 09:15:17 INFO Completed upload id=19722026/10/01 09:15:17 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009732026/10/01 09:15:17 INFO Received uploads request method=POST path=/api/pending_closures9742026/10/01 09:15:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures9752026/10/01 09:15:17 INFO Aborted multipart uploads count=09762026/10/01 09:15:17 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=09772026/10/01 09:15:17 INFO Vacuumed table table=pending_closures9782026/10/01 09:15:17 INFO Vacuumed table table=pending_objects9792026-10-01 09:15:17.926 UTC [13979] ERROR: relation "goose_db_version" does not exist at character 369802026-10-01 09:15:17.926 UTC [13979] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9812026/10/01 09:15:17 INFO Vacuumed table table=multipart_uploads9822026/10/01 09:15:17 INFO Vacuumed table table=closures9832026/10/01 09:15:17 INFO Vacuumed table table=objects984--- PASS: TestReadProxy404 (2.08s)985=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key9862026/10/01 09:15:17 INFO Received request for more parts method=POST path=/987=== CONT TestReadProxyNarinfo9882026/10/01 09:15:17 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000989--- PASS: TestService_createPendingClosureHandler (2.82s)990=== CONT TestIsValidCachePath991=== RUN TestIsValidCachePath/narinfo992=== PAUSE TestIsValidCachePath/narinfo993=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars994=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars995=== RUN TestIsValidCachePath/nar_zst996=== PAUSE TestIsValidCachePath/nar_zst997=== RUN TestIsValidCachePath/nar_xz998=== PAUSE TestIsValidCachePath/nar_xz999=== RUN TestIsValidCachePath/nar_bz21000=== PAUSE TestIsValidCachePath/nar_bz21001=== RUN TestIsValidCachePath/nar_uncompressed1002=== PAUSE TestIsValidCachePath/nar_uncompressed1003=== RUN TestIsValidCachePath/ls1004=== PAUSE TestIsValidCachePath/ls1005=== RUN TestIsValidCachePath/log1006=== PAUSE TestIsValidCachePath/log1007=== RUN TestIsValidCachePath/realisation1008=== PAUSE TestIsValidCachePath/realisation1009=== RUN TestIsValidCachePath/nix-cache-info1010=== PAUSE TestIsValidCachePath/nix-cache-info1011=== RUN TestIsValidCachePath/index.html1012=== PAUSE TestIsValidCachePath/index.html1013=== RUN TestIsValidCachePath/traversal_parent1014=== PAUSE TestIsValidCachePath/traversal_parent1015=== RUN TestIsValidCachePath/traversal_in_middle1016=== PAUSE TestIsValidCachePath/traversal_in_middle1017=== RUN TestIsValidCachePath/invalid_char_e1018=== PAUSE TestIsValidCachePath/invalid_char_e1019=== RUN TestIsValidCachePath/invalid_char_u1020=== PAUSE TestIsValidCachePath/invalid_char_u1021=== RUN TestIsValidCachePath/random_path1022=== PAUSE TestIsValidCachePath/random_path1023=== RUN TestIsValidCachePath/empty1024=== PAUSE TestIsValidCachePath/empty1025=== RUN TestIsValidCachePath/leading_slash1026=== PAUSE TestIsValidCachePath/leading_slash1027=== RUN TestIsValidCachePath/wrong_extension1028=== PAUSE TestIsValidCachePath/wrong_extension1029=== RUN TestIsValidCachePath/short_hash1030=== PAUSE TestIsValidCachePath/short_hash1031=== CONT TestProxyHeadersOnlyTrustedOnSocket10322026/10/01 09:15:18 OK 20241026095416_initial_model.sql (144.48ms)10332026/10/01 09:15:18 OK 20251210153512_drop_unused_gin_index.sql (12.97ms)10342026/10/01 09:15:18 OK 20251218171726_add_pins.sql (39.37ms)10352026/10/01 09:15:18 OK 20260628120000_add_object_size_and_stats.sql (40.72ms)10362026/10/01 09:15:18 OK 20260905000000_add_claims.sql (19.97ms)10372026/10/01 09:15:18 OK 20260920000000_drop_claims.sql (13.21ms)10382026/10/01 09:15:18 OK 20260923120000_add_pushes.sql (7.27ms)10392026/10/01 09:15:18 goose: successfully migrated database to version: 2026092312000010402026/10/01 09:15:18 OK 1_commit_pending_closure.sql (3.24ms)10412026/10/01 09:15:18 OK 2_object_stats_trigger.sql (585.29µs)10422026/10/01 09:15:18 OK 3_commit_push.sql (331.88µs)10432026/10/01 09:15:18 goose: up to current file version: 31044=== NAME TestOrphanedObjectsGC1045 orphaned_objects_gc_test.go:290: GC Test Summary:1046 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1047 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1048 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1049 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1050 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1051--- PASS: TestOrphanedObjectsGC (2.68s)1052=== CONT TestObjectStatsTrigger10532026-10-01 09:15:18.390 UTC [13984] ERROR: relation "goose_db_version" does not exist at character 3610542026-10-01 09:15:18.390 UTC [13984] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1055--- PASS: TestReadProxyNarStreaming (2.15s)1056=== CONT TestParseSingleRange1057=== RUN TestParseSingleRange/none1058=== PAUSE TestParseSingleRange/none1059=== RUN TestParseSingleRange/unknown_unit1060=== PAUSE TestParseSingleRange/unknown_unit1061=== RUN TestParseSingleRange/multi-range_ignored1062=== PAUSE TestParseSingleRange/multi-range_ignored1063=== RUN TestParseSingleRange/malformed_no_dash1064=== PAUSE TestParseSingleRange/malformed_no_dash1065=== RUN TestParseSingleRange/malformed_both_empty1066=== PAUSE TestParseSingleRange/malformed_both_empty1067=== RUN TestParseSingleRange/malformed_end_before_start1068=== PAUSE TestParseSingleRange/malformed_end_before_start1069=== RUN TestParseSingleRange/closed1070=== PAUSE TestParseSingleRange/closed1071=== RUN TestParseSingleRange/open-ended1072=== PAUSE TestParseSingleRange/open-ended1073=== RUN TestParseSingleRange/end_clamped_to_size1074=== PAUSE TestParseSingleRange/end_clamped_to_size1075=== RUN TestParseSingleRange/suffix1076=== PAUSE TestParseSingleRange/suffix1077=== RUN TestParseSingleRange/suffix_exceeds_size1078=== PAUSE TestParseSingleRange/suffix_exceeds_size1079=== RUN TestParseSingleRange/single_byte1080=== PAUSE TestParseSingleRange/single_byte1081=== RUN TestParseSingleRange/start_past_EOF1082=== PAUSE TestParseSingleRange/start_past_EOF1083=== RUN TestParseSingleRange/start_far_past_EOF1084=== PAUSE TestParseSingleRange/start_far_past_EOF1085=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key10862026/10/01 09:15:18 INFO Received complete multipart upload request method=POST path=/1087=== CONT TestDeduplicatedObjectsRecordedAsPending10882026/10/01 09:15:18 OK 20241026095416_initial_model.sql (108.3ms)10892026/10/01 09:15:18 OK 20251210153512_drop_unused_gin_index.sql (7.27ms)10902026/10/01 09:15:18 OK 20251218171726_add_pins.sql (13.81ms)10912026-10-01 09:15:18.593 UTC [13990] ERROR: relation "goose_db_version" does not exist at character 3610922026-10-01 09:15:18.593 UTC [13990] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10932026-10-01 09:15:18.602 UTC [13991] ERROR: relation "goose_db_version" does not exist at character 3610942026-10-01 09:15:18.602 UTC [13991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10952026-10-01 09:15:18.605 UTC [13992] ERROR: relation "goose_db_version" does not exist at character 3610962026-10-01 09:15:18.605 UTC [13992] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10972026/10/01 09:15:18 OK 20260628120000_add_object_size_and_stats.sql (22.24ms)10982026/10/01 09:15:18 OK 20260905000000_add_claims.sql (11.97ms)10992026/10/01 09:15:18 OK 20260920000000_drop_claims.sql (1.98ms)11002026/10/01 09:15:18 OK 20260923120000_add_pushes.sql (6.15ms)11012026/10/01 09:15:18 goose: successfully migrated database to version: 2026092312000011022026/10/01 09:15:18 OK 20241026095416_initial_model.sql (11.56ms)11032026/10/01 09:15:18 OK 20251210153512_drop_unused_gin_index.sql (467.88µs)11042026/10/01 09:15:18 OK 1_commit_pending_closure.sql (1.3ms)11052026/10/01 09:15:18 OK 2_object_stats_trigger.sql (323.33µs)11062026/10/01 09:15:18 OK 20251218171726_add_pins.sql (1.08ms)11072026/10/01 09:15:18 OK 3_commit_push.sql (227.83µs)11082026/10/01 09:15:18 goose: up to current file version: 311092026/10/01 09:15:18 OK 20260628120000_add_object_size_and_stats.sql (21.51ms)11102026/10/01 09:15:18 OK 20241026095416_initial_model.sql (45.69ms)11112026/10/01 09:15:18 OK 20251210153512_drop_unused_gin_index.sql (10.23ms)11122026/10/01 09:15:18 OK 20260905000000_add_claims.sql (25.04ms)11132026/10/01 09:15:18 OK 20241026095416_initial_model.sql (57.05ms)11142026/10/01 09:15:18 OK 20260920000000_drop_claims.sql (1.69ms)11152026/10/01 09:15:18 OK 20251210153512_drop_unused_gin_index.sql (648.63µs)11162026/10/01 09:15:18 OK 20251218171726_add_pins.sql (2.57ms)11172026/10/01 09:15:18 OK 20260923120000_add_pushes.sql (16.75ms)11182026/10/01 09:15:18 goose: successfully migrated database to version: 2026092312000011192026/10/01 09:15:18 OK 20251218171726_add_pins.sql (16.75ms)11202026/10/01 09:15:18 OK 1_commit_pending_closure.sql (1.91ms)11212026/10/01 09:15:18 OK 2_object_stats_trigger.sql (371.08µs)11222026/10/01 09:15:18 OK 3_commit_push.sql (243.5µs)11232026/10/01 09:15:18 goose: up to current file version: 311242026/10/01 09:15:18 OK 20260628120000_add_object_size_and_stats.sql (24.89ms)11252026/10/01 09:15:18 OK 20260628120000_add_object_size_and_stats.sql (27.48ms)11262026/10/01 09:15:18 OK 20260905000000_add_claims.sql (49.66ms)11272026/10/01 09:15:18 OK 20260905000000_add_claims.sql (45.54ms)11282026/10/01 09:15:18 OK 20260920000000_drop_claims.sql (27.51ms)11292026/10/01 09:15:18 OK 20260920000000_drop_claims.sql (26.31ms)11302026/10/01 09:15:18 OK 20260923120000_add_pushes.sql (20.79ms)11312026/10/01 09:15:18 goose: successfully migrated database to version: 2026092312000011322026/10/01 09:15:18 OK 1_commit_pending_closure.sql (3.16ms)11332026/10/01 09:15:18 OK 2_object_stats_trigger.sql (1.05ms)11342026/10/01 09:15:18 OK 3_commit_push.sql (1.34ms)11352026/10/01 09:15:18 goose: up to current file version: 311362026/10/01 09:15:18 OK 20260923120000_add_pushes.sql (13ms)11372026/10/01 09:15:18 goose: successfully migrated database to version: 2026092312000011382026/10/01 09:15:18 OK 1_commit_pending_closure.sql (2.93ms)11392026/10/01 09:15:18 OK 2_object_stats_trigger.sql (379.88µs)11402026/10/01 09:15:18 OK 3_commit_push.sql (316.21µs)11412026/10/01 09:15:18 goose: up to current file version: 311422026/10/01 09:15:18 INFO Received uploads request method=POST path=/api/pending_closures11432026-10-01 09:15:18.909 UTC [13996] ERROR: relation "goose_db_version" does not exist at character 3611442026-10-01 09:15:18.909 UTC [13996] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11452026/10/01 09:15:19 INFO Received cleanup request method=DELETE path=/api/pending_closures11462026/10/01 09:15:19 INFO Aborted multipart uploads count=11147--- PASS: TestMultipartCleanup (2.19s)1148=== CONT TestGCTaskStore_StartNew1149--- PASS: TestGCTaskStore_StartNew (0.00s)1150=== CONT TestGenerateLandingPage1151--- PASS: TestGenerateLandingPage (0.01s)1152=== CONT TestCommitRacingPendingCleanupKeepsObjects11532026/10/01 09:15:19 OK 20241026095416_initial_model.sql (138.94ms)11542026/10/01 09:15:19 OK 20251210153512_drop_unused_gin_index.sql (11.49ms)11552026/10/01 09:15:19 OK 20251218171726_add_pins.sql (34.84ms)11562026/10/01 09:15:19 OK 20260628120000_add_object_size_and_stats.sql (43.88ms)11572026/10/01 09:15:19 OK 20260905000000_add_claims.sql (74.11ms)11582026/10/01 09:15:19 OK 20260920000000_drop_claims.sql (53.94ms)11592026/10/01 09:15:19 OK 20260923120000_add_pushes.sql (16.26ms)11602026/10/01 09:15:19 goose: successfully migrated database to version: 2026092312000011612026/10/01 09:15:19 OK 1_commit_pending_closure.sql (2.17ms)11622026/10/01 09:15:19 OK 2_object_stats_trigger.sql (496.88µs)11632026/10/01 09:15:19 OK 3_commit_push.sql (393.17µs)11642026/10/01 09:15:19 goose: up to current file version: 311652026/10/01 09:15:19 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11662026/10/01 09:15:19 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1167--- PASS: TestService_NativeMTLS (2.28s)1168=== CONT TestService_readinessHandler1169=== NAME TestNARDeduplicationMetadataUploadBug1170 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-13789-2688134661/TestNARDeduplicationMetadataUploadBug1412388327/001/store/c3j212ipfv36zmi9np1brk7plpfh14yv-file1.txt11712026/10/01 09:15:19 INFO Received push request method=POST path=/api/pushes11722026/10/01 09:15:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11732026/10/01 09:15:19 INFO Uploading c3j212ipfv36zmi9np1brk7plpfh14yv-file1.txt (160B)11742026/10/01 09:15:19 WARN Failed to register uploaded object key=c3j212ipfv36zmi9np1brk7plpfh14yv.ls error="server returned 404: 404 page not found\n"11752026/10/01 09:15:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11762026/10/01 09:15:19 INFO Signed narinfos id=1 count=111772026/10/01 09:15:19 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11782026/10/01 09:15:19 INFO Uploading 1 narinfos11792026/10/01 09:15:19 INFO Received complete push request method=POST path=/api/pushes/1/complete11802026/10/01 09:15:19 WARN Failed to register uploaded object key=c3j212ipfv36zmi9np1brk7plpfh14yv.narinfo error="server returned 404: 404 page not found\n"11812026-10-01 09:15:19.563 UTC [14007] ERROR: relation "goose_db_version" does not exist at character 3611822026-10-01 09:15:19.563 UTC [14007] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11832026/10/01 09:15:19 INFO Upload complete. (126ms)1184 metadata_upload_test.go:54: Retrieved narinfo from S3:1185 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestNARDeduplicationMetadataUploadBug1412388327/001/store/c3j212ipfv36zmi9np1brk7plpfh14yv-file1.txt1186 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1187 Compression: zstd1188 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1189 NarSize: 1601190 References: 1191 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1192 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1193 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1194 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11952026-10-01 09:15:19.612 UTC [14008] ERROR: relation "goose_db_version" does not exist at character 3611962026-10-01 09:15:19.612 UTC [14008] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1197--- PASS: TestMetricsInventory (2.34s)1198=== CONT TestPushWaitsForSweepHoldingRow1199=== NAME TestNARDeduplicationMetadataUploadBug1200 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-13789-2688134661/TestNARDeduplicationMetadataUploadBug1412388327/001/store/y3vvzd09xkcm6i8kyqpbbvs7d79v4pwh-file2.txt12012026/10/01 09:15:19 OK 20241026095416_initial_model.sql (133.3ms)12022026/10/01 09:15:19 INFO Received push request method=POST path=/api/pushes12032026/10/01 09:15:19 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12042026/10/01 09:15:19 OK 20251210153512_drop_unused_gin_index.sql (8.05ms)12052026/10/01 09:15:19 OK 20241026095416_initial_model.sql (111.86ms)12062026/10/01 09:15:19 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12072026/10/01 09:15:19 INFO Signed narinfos id=2 count=112082026/10/01 09:15:19 INFO Uploading 1 narinfos12092026/10/01 09:15:19 WARN Failed to register uploaded object key=y3vvzd09xkcm6i8kyqpbbvs7d79v4pwh.ls error="server returned 404: 404 page not found\n"12102026/10/01 09:15:19 OK 20251210153512_drop_unused_gin_index.sql (8.29ms)12112026/10/01 09:15:19 INFO Received complete push request method=POST path=/api/pushes/2/complete12122026/10/01 09:15:19 WARN Failed to register uploaded object key=y3vvzd09xkcm6i8kyqpbbvs7d79v4pwh.narinfo error="server returned 404: 404 page not found\n"12132026/10/01 09:15:19 INFO Upload complete. (92ms)1214 metadata_upload_test.go:76: Retrieved narinfo from S3:1215 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestNARDeduplicationMetadataUploadBug1412388327/001/store/y3vvzd09xkcm6i8kyqpbbvs7d79v4pwh-file2.txt1216 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1217 Compression: zstd1218 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1219 NarSize: 1601220 References: 1221 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1222 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1223 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1224 {"version":1,"root":{"type":"regular","size":44}}12252026/10/01 09:15:19 OK 20251218171726_add_pins.sql (42.63ms)12262026/10/01 09:15:19 OK 20251218171726_add_pins.sql (25.27ms)12272026/10/01 09:15:19 OK 20260628120000_add_object_size_and_stats.sql (33.34ms)12282026/10/01 09:15:19 OK 20260628120000_add_object_size_and_stats.sql (26.93ms)1229--- PASS: TestNARDeduplicationMetadataUploadBug (2.49s)1230=== CONT TestService_healthCheckHandler1231--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.36s)1232=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal12332026/10/01 09:15:19 INFO Received uploads request method=POST path=/1234--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1235 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1236 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1237 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1238 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1239=== CONT TestSweepRechecksPendingAfterLocking12402026/10/01 09:15:19 OK 20260905000000_add_claims.sql (29.21ms)12412026/10/01 09:15:19 OK 20260905000000_add_claims.sql (29.4ms)12422026-10-01 09:15:19.860 UTC [14018] ERROR: relation "goose_db_version" does not exist at character 3612432026-10-01 09:15:19.860 UTC [14018] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12442026/10/01 09:15:19 OK 20260920000000_drop_claims.sql (10.91ms)12452026/10/01 09:15:19 OK 20260920000000_drop_claims.sql (17.55ms)12462026/10/01 09:15:19 OK 20260923120000_add_pushes.sql (7.95ms)12472026/10/01 09:15:19 goose: successfully migrated database to version: 2026092312000012482026/10/01 09:15:19 OK 1_commit_pending_closure.sql (1.27ms)12492026/10/01 09:15:19 OK 2_object_stats_trigger.sql (236.83µs)12502026/10/01 09:15:19 OK 3_commit_push.sql (178.75µs)12512026/10/01 09:15:19 goose: up to current file version: 312522026/10/01 09:15:19 OK 20260923120000_add_pushes.sql (9.08ms)12532026/10/01 09:15:19 goose: successfully migrated database to version: 2026092312000012542026/10/01 09:15:19 OK 1_commit_pending_closure.sql (935.83µs)12552026/10/01 09:15:19 OK 2_object_stats_trigger.sql (216.54µs)12562026/10/01 09:15:19 OK 3_commit_push.sql (166.88µs)12572026/10/01 09:15:19 goose: up to current file version: 312582026-10-01 09:15:19.954 UTC [14022] ERROR: relation "goose_db_version" does not exist at character 3612592026-10-01 09:15:19.954 UTC [14022] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12602026/10/01 09:15:20 OK 20241026095416_initial_model.sql (122.54ms)12612026/10/01 09:15:20 OK 20251210153512_drop_unused_gin_index.sql (5.16ms)12622026/10/01 09:15:20 OK 20251218171726_add_pins.sql (18.16ms)12632026/10/01 09:15:20 OK 20260628120000_add_object_size_and_stats.sql (32.23ms)1264--- PASS: TestReadProxyNarinfo (2.15s)1265=== CONT TestPushDedupSurvivesConcurrentGC12662026/10/01 09:15:20 OK 20241026095416_initial_model.sql (126.23ms)12672026/10/01 09:15:20 OK 20260905000000_add_claims.sql (51.76ms)12682026/10/01 09:15:20 OK 20251210153512_drop_unused_gin_index.sql (12.15ms)12692026/10/01 09:15:20 OK 20260920000000_drop_claims.sql (14.97ms)12702026/10/01 09:15:20 OK 20260923120000_add_pushes.sql (11.45ms)12712026/10/01 09:15:20 goose: successfully migrated database to version: 2026092312000012722026/10/01 09:15:20 OK 1_commit_pending_closure.sql (1.81ms)12732026/10/01 09:15:20 OK 2_object_stats_trigger.sql (406.21µs)12742026/10/01 09:15:20 OK 3_commit_push.sql (364.25µs)12752026/10/01 09:15:20 goose: up to current file version: 312762026/10/01 09:15:20 OK 20251218171726_add_pins.sql (26.6ms)12772026/10/01 09:15:20 OK 20260628120000_add_object_size_and_stats.sql (31.67ms)12782026/10/01 09:15:20 OK 20260905000000_add_claims.sql (34.02ms)12792026/10/01 09:15:20 OK 20260920000000_drop_claims.sql (17.37ms)12802026/10/01 09:15:20 OK 20260923120000_add_pushes.sql (21.18ms)12812026/10/01 09:15:20 goose: successfully migrated database to version: 2026092312000012822026/10/01 09:15:20 OK 1_commit_pending_closure.sql (3.06ms)12832026/10/01 09:15:20 OK 2_object_stats_trigger.sql (676.58µs)12842026/10/01 09:15:20 OK 3_commit_push.sql (475.75µs)12852026/10/01 09:15:20 goose: up to current file version: 312862026/10/01 09:15:20 INFO Starting HTTP server address=/nix/var/nix/builds/nix-13789-2688134661/TestProxyHeadersOnlyTrustedOnSocket2658494445/001/proxy.sock12872026/10/01 09:15:20 INFO Starting HTTP server address=127.0.0.1:6224312882026/10/01 09:15:20 WARN mTLS auth: subject not in bound subjects subject="CN=someone"12892026/10/01 09:15:20 INFO Shutdown signal received, draining in-flight requests timeout=10s1290--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.36s)1291=== CONT TestGracefulShutdownDrainsInflight12922026/10/01 09:15:20 INFO Starting HTTP server address=127.0.0.1:6224712932026/10/01 09:15:20 INFO Shutdown signal received, draining in-flight requests timeout=10s1294--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1295=== CONT TestForceGCDuringPushOffersSweptObject1296=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1297=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1298=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1299=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1300=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13012026-10-01 09:15:20.608 UTC [14028] ERROR: relation "goose_db_version" does not exist at character 3613022026-10-01 09:15:20.608 UTC [14028] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1303--- PASS: TestObjectStatsTrigger (2.32s)1304=== CONT TestGCTaskStore_Fail1305--- PASS: TestGCTaskStore_Fail (0.00s)1306=== CONT TestGetExistingObjectsLocksRows13072026/10/01 09:15:20 OK 20241026095416_initial_model.sql (169.42ms)13082026/10/01 09:15:20 OK 20251210153512_drop_unused_gin_index.sql (12.32ms)13092026/10/01 09:15:20 OK 20251218171726_add_pins.sql (29.75ms)13102026/10/01 09:15:20 INFO Received uploads request method=POST path=/api/pending_closures13112026/10/01 09:15:20 OK 20260628120000_add_object_size_and_stats.sql (27.16ms)1312--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.37s)1313=== CONT TestGCSweepDeliversEachKeyOnce13142026/10/01 09:15:20 OK 20260905000000_add_claims.sql (19.31ms)13152026/10/01 09:15:20 OK 20260920000000_drop_claims.sql (27.7ms)13162026-10-01 09:15:20.973 UTC [14031] ERROR: relation "goose_db_version" does not exist at character 3613172026-10-01 09:15:20.973 UTC [14031] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13182026/10/01 09:15:20 OK 20260923120000_add_pushes.sql (21.6ms)13192026/10/01 09:15:20 goose: successfully migrated database to version: 2026092312000013202026/10/01 09:15:20 OK 1_commit_pending_closure.sql (3.63ms)13212026/10/01 09:15:20 OK 2_object_stats_trigger.sql (588.88µs)13222026/10/01 09:15:20 OK 3_commit_push.sql (425.54µs)13232026/10/01 09:15:20 goose: up to current file version: 313242026/10/01 09:15:21 OK 20241026095416_initial_model.sql (232.88ms)13252026/10/01 09:15:21 OK 20251210153512_drop_unused_gin_index.sql (9.73ms)13262026/10/01 09:15:21 OK 20251218171726_add_pins.sql (26.63ms)13272026/10/01 09:15:21 OK 20260628120000_add_object_size_and_stats.sql (28.65ms)13282026-10-01 09:15:21.410 UTC [14034] ERROR: relation "goose_db_version" does not exist at character 3613292026-10-01 09:15:21.410 UTC [14034] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13302026/10/01 09:15:21 OK 20260905000000_add_claims.sql (59.7ms)13312026/10/01 09:15:21 OK 20260920000000_drop_claims.sql (57.53ms)13322026/10/01 09:15:21 OK 20260923120000_add_pushes.sql (9.91ms)13332026/10/01 09:15:21 goose: successfully migrated database to version: 2026092312000013342026/10/01 09:15:21 OK 1_commit_pending_closure.sql (5.96ms)13352026/10/01 09:15:21 OK 2_object_stats_trigger.sql (697.96µs)13362026/10/01 09:15:21 OK 3_commit_push.sql (412.46µs)13372026/10/01 09:15:21 goose: up to current file version: 313382026/10/01 09:15:21 INFO Aborted multipart uploads count=013392026/10/01 09:15:21 WARN Force mode enabled - objects will be deleted immediately without grace period13402026/10/01 09:15:21 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=013412026/10/01 09:15:21 INFO Vacuumed table table=pending_closures13422026/10/01 09:15:21 INFO Vacuumed table table=pending_objects13432026/10/01 09:15:21 INFO Vacuumed table table=multipart_uploads13442026/10/01 09:15:21 INFO Vacuumed table table=closures13452026/10/01 09:15:21 INFO Vacuumed table table=objects1346--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.62s)1347=== CONT TestGCTaskStore_PhaseUpdates1348--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1349=== CONT TestRegisterCompletedObjectNeedsPendingRow13502026/10/01 09:15:21 OK 20241026095416_initial_model.sql (251.97ms)13512026/10/01 09:15:21 OK 20251210153512_drop_unused_gin_index.sql (19.22ms)13522026/10/01 09:15:21 OK 20251218171726_add_pins.sql (50.19ms)13532026/10/01 09:15:21 OK 20260628120000_add_object_size_and_stats.sql (44.52ms)13542026/10/01 09:15:21 WARN readiness check failed error="closed pool"1355--- PASS: TestService_readinessHandler (2.49s)1356=== CONT TestTombstonedObjectOfferedWithoutWaiting13572026-10-01 09:15:21.893 UTC [14040] ERROR: relation "goose_db_version" does not exist at character 3613582026-10-01 09:15:21.893 UTC [14040] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13592026/10/01 09:15:21 OK 20260905000000_add_claims.sql (80.15ms)13602026/10/01 09:15:21 OK 20260920000000_drop_claims.sql (15.61ms)13612026-10-01 09:15:21.944 UTC [14041] ERROR: relation "goose_db_version" does not exist at character 3613622026-10-01 09:15:21.944 UTC [14041] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13632026/10/01 09:15:21 OK 20260923120000_add_pushes.sql (4.38ms)13642026/10/01 09:15:21 goose: successfully migrated database to version: 2026092312000013652026/10/01 09:15:21 OK 1_commit_pending_closure.sql (3.22ms)13662026/10/01 09:15:21 OK 2_object_stats_trigger.sql (554.83µs)13672026/10/01 09:15:21 OK 3_commit_push.sql (431.92µs)13682026/10/01 09:15:21 goose: up to current file version: 313692026-10-01 09:15:22.167 UTC [14044] ERROR: relation "goose_db_version" does not exist at character 3613702026-10-01 09:15:22.167 UTC [14044] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13712026/10/01 09:15:22 OK 20241026095416_initial_model.sql (224.54ms)13722026/10/01 09:15:22 OK 20251210153512_drop_unused_gin_index.sql (19.43ms)13732026/10/01 09:15:22 OK 20251218171726_add_pins.sql (47.08ms)13742026/10/01 09:15:22 OK 20241026095416_initial_model.sql (253.63ms)13752026/10/01 09:15:22 OK 20251210153512_drop_unused_gin_index.sql (17.02ms)13762026/10/01 09:15:22 OK 20260628120000_add_object_size_and_stats.sql (60.28ms)13772026/10/01 09:15:22 OK 20251218171726_add_pins.sql (45.54ms)13782026/10/01 09:15:22 INFO Received uploads request method=POST path=/api/pending_closures13792026/10/01 09:15:22 OK 20260905000000_add_claims.sql (47.08ms)13802026/10/01 09:15:22 OK 20260628120000_add_object_size_and_stats.sql (33.38ms)13812026/10/01 09:15:22 OK 20260920000000_drop_claims.sql (48.95ms)13822026/10/01 09:15:22 OK 20260923120000_add_pushes.sql (17.78ms)13832026/10/01 09:15:22 goose: successfully migrated database to version: 2026092312000013842026/10/01 09:15:22 OK 1_commit_pending_closure.sql (4.99ms)13852026/10/01 09:15:22 OK 2_object_stats_trigger.sql (860.67µs)13862026/10/01 09:15:22 OK 3_commit_push.sql (600.21µs)13872026/10/01 09:15:22 goose: up to current file version: 313882026/10/01 09:15:22 OK 20260905000000_add_claims.sql (75.68ms)13892026/10/01 09:15:22 OK 20260920000000_drop_claims.sql (40.82ms)13902026/10/01 09:15:22 OK 20241026095416_initial_model.sql (220.73ms)13912026/10/01 09:15:22 OK 20251210153512_drop_unused_gin_index.sql (16.56ms)13922026/10/01 09:15:22 OK 20260923120000_add_pushes.sql (19.08ms)13932026/10/01 09:15:22 goose: successfully migrated database to version: 2026092312000013942026/10/01 09:15:22 OK 1_commit_pending_closure.sql (4.25ms)13952026/10/01 09:15:22 OK 2_object_stats_trigger.sql (800.17µs)13962026/10/01 09:15:22 OK 3_commit_push.sql (538.54µs)13972026/10/01 09:15:22 goose: up to current file version: 313982026/10/01 09:15:22 OK 20251218171726_add_pins.sql (48.63ms)13992026/10/01 09:15:22 OK 20260628120000_add_object_size_and_stats.sql (57.79ms)14002026/10/01 09:15:22 OK 20260905000000_add_claims.sql (95.1ms)14012026/10/01 09:15:22 OK 20260920000000_drop_claims.sql (54.06ms)14022026/10/01 09:15:22 OK 20260923120000_add_pushes.sql (27.97ms)14032026/10/01 09:15:22 goose: successfully migrated database to version: 2026092312000014042026/10/01 09:15:22 OK 1_commit_pending_closure.sql (5.23ms)14052026/10/01 09:15:22 OK 2_object_stats_trigger.sql (999.46µs)14062026/10/01 09:15:22 OK 3_commit_push.sql (826.79µs)14072026/10/01 09:15:22 goose: up to current file version: 31408--- PASS: TestService_healthCheckHandler (2.96s)1409=== CONT TestGCTaskStore_CompletedAllowsNewTask1410--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1411=== CONT TestSweepSkipsRowsLockedByPush1412--- PASS: TestPushWaitsForSweepHoldingRow (3.18s)1413=== CONT TestGCSweepSkipsPendingObjects14142026-10-01 09:15:22.933 UTC [14050] ERROR: relation "goose_db_version" does not exist at character 3614152026-10-01 09:15:22.933 UTC [14050] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14162026-10-01 09:15:23.130 UTC [14051] ERROR: relation "goose_db_version" does not exist at character 3614172026-10-01 09:15:23.130 UTC [14051] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14182026/10/01 09:15:23 INFO Aborted multipart uploads count=014192026/10/01 09:15:23 WARN Force mode enabled - objects will be deleted immediately without grace period14202026/10/01 09:15:23 OK 20241026095416_initial_model.sql (193.13ms)14212026/10/01 09:15:23 OK 20251210153512_drop_unused_gin_index.sql (19.54ms)14222026/10/01 09:15:23 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014232026/10/01 09:15:23 OK 20251218171726_add_pins.sql (71.07ms)14242026/10/01 09:15:23 INFO Vacuumed table table=pending_closures14252026/10/01 09:15:23 INFO Vacuumed table table=pending_objects14262026/10/01 09:15:23 INFO Vacuumed table table=multipart_uploads14272026/10/01 09:15:23 INFO Vacuumed table table=closures14282026/10/01 09:15:23 OK 20260628120000_add_object_size_and_stats.sql (36.59ms)14292026/10/01 09:15:23 OK 20241026095416_initial_model.sql (152.92ms)14302026/10/01 09:15:23 OK 20251210153512_drop_unused_gin_index.sql (12.67ms)14312026/10/01 09:15:23 INFO Vacuumed table table=objects1432--- PASS: TestSweepRechecksPendingAfterLocking (3.52s)1433=== CONT TestGCTaskStore_GetReturnsLatest1434--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1435=== CONT TestGCTaskStore_DeduplicateSameParams1436--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1437=== CONT TestGCMetrics14382026-10-01 09:15:23.374 UTC [14054] ERROR: relation "goose_db_version" does not exist at character 3614392026-10-01 09:15:23.374 UTC [14054] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14402026/10/01 09:15:23 OK 20251218171726_add_pins.sql (17.64ms)14412026/10/01 09:15:23 OK 20260905000000_add_claims.sql (37.2ms)14422026/10/01 09:15:23 OK 20260628120000_add_object_size_and_stats.sql (34.98ms)14432026/10/01 09:15:23 OK 20260920000000_drop_claims.sql (36.92ms)14442026/10/01 09:15:23 OK 20260923120000_add_pushes.sql (13.31ms)14452026/10/01 09:15:23 goose: successfully migrated database to version: 2026092312000014462026/10/01 09:15:23 OK 1_commit_pending_closure.sql (3.17ms)14472026/10/01 09:15:23 OK 2_object_stats_trigger.sql (529.33µs)14482026/10/01 09:15:23 OK 3_commit_push.sql (429.79µs)14492026/10/01 09:15:23 goose: up to current file version: 314502026/10/01 09:15:23 OK 20260905000000_add_claims.sql (61.03ms)14512026/10/01 09:15:23 OK 20260920000000_drop_claims.sql (35.73ms)14522026/10/01 09:15:23 OK 20260923120000_add_pushes.sql (18.05ms)14532026/10/01 09:15:23 goose: successfully migrated database to version: 2026092312000014542026/10/01 09:15:23 OK 1_commit_pending_closure.sql (3.74ms)14552026/10/01 09:15:23 OK 2_object_stats_trigger.sql (726.79µs)14562026/10/01 09:15:23 OK 3_commit_push.sql (478.71µs)14572026/10/01 09:15:23 goose: up to current file version: 314582026/10/01 09:15:23 INFO Received uploads request method=POST path=/api/pending_closures14592026/10/01 09:15:23 OK 20241026095416_initial_model.sql (183.69ms)14602026/10/01 09:15:23 OK 20251210153512_drop_unused_gin_index.sql (17.79ms)14612026/10/01 09:15:23 INFO Aborted multipart uploads count=014622026/10/01 09:15:23 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=014632026/10/01 09:15:23 INFO Vacuumed table table=pending_closures14642026/10/01 09:15:23 OK 20251218171726_add_pins.sql (34.55ms)14652026/10/01 09:15:23 INFO Vacuumed table table=pending_objects14662026/10/01 09:15:23 INFO Vacuumed table table=multipart_uploads14672026/10/01 09:15:23 OK 20260628120000_add_object_size_and_stats.sql (46.79ms)14682026/10/01 09:15:23 INFO Vacuumed table table=closures14692026/10/01 09:15:23 INFO Vacuumed table table=objects14702026/10/01 09:15:23 INFO Received uploads request method=POST path=/api/pending_closures14712026/10/01 09:15:23 INFO Aborted multipart uploads count=014722026/10/01 09:15:23 WARN Force mode enabled - objects will be deleted immediately without grace period14732026/10/01 09:15:23 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014742026/10/01 09:15:23 INFO Vacuumed table table=pending_closures14752026/10/01 09:15:23 OK 20260905000000_add_claims.sql (80.52ms)14762026/10/01 09:15:23 INFO Vacuumed table table=pending_objects14772026/10/01 09:15:23 INFO Vacuumed table table=multipart_uploads14782026/10/01 09:15:23 INFO Vacuumed table table=closures14792026/10/01 09:15:23 INFO Vacuumed table table=objects14802026/10/01 09:15:23 OK 20260920000000_drop_claims.sql (27.63ms)1481--- PASS: TestPushDedupSurvivesConcurrentGC (3.73s)1482=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock14832026/10/01 09:15:23 OK 20260923120000_add_pushes.sql (20.64ms)14842026/10/01 09:15:23 goose: successfully migrated database to version: 2026092312000014852026/10/01 09:15:23 OK 1_commit_pending_closure.sql (3.68ms)14862026/10/01 09:15:23 OK 2_object_stats_trigger.sql (532.21µs)14872026/10/01 09:15:23 OK 3_commit_push.sql (340.58µs)14882026/10/01 09:15:23 goose: up to current file version: 314892026-10-01 09:15:23.967 UTC [14060] ERROR: relation "goose_db_version" does not exist at character 3614902026-10-01 09:15:23.967 UTC [14060] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1491--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.62s)1492=== CONT TestClientIntegration1493--- PASS: TestGetExistingObjectsLocksRows (3.42s)1494=== CONT TestGCBugBareHashReferences1495=== NAME TestOrphanedObjectsGCStressTest1496 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1497 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion14982026/10/01 09:15:24 OK 20241026095416_initial_model.sql (171.12ms)14992026/10/01 09:15:24 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)15002026-10-01 09:15:24.204 UTC [14066] ERROR: relation "goose_db_version" does not exist at character 3615012026-10-01 09:15:24.204 UTC [14066] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15022026/10/01 09:15:24 OK 20251218171726_add_pins.sql (13.63ms)15032026/10/01 09:15:24 OK 20260628120000_add_object_size_and_stats.sql (14.63ms)15042026/10/01 09:15:24 OK 20260905000000_add_claims.sql (48.17ms)15052026/10/01 09:15:24 OK 20260920000000_drop_claims.sql (14.79ms)15062026/10/01 09:15:24 OK 20260923120000_add_pushes.sql (9.47ms)15072026/10/01 09:15:24 goose: successfully migrated database to version: 2026092312000015082026/10/01 09:15:24 OK 1_commit_pending_closure.sql (2.3ms)15092026/10/01 09:15:24 OK 2_object_stats_trigger.sql (402.71µs)15102026/10/01 09:15:24 OK 3_commit_push.sql (326.5µs)15112026/10/01 09:15:24 goose: up to current file version: 315122026/10/01 09:15:24 INFO Aborted multipart uploads count=015132026/10/01 09:15:24 WARN Force mode enabled - objects will be deleted immediately without grace period15142026/10/01 09:15:24 OK 20241026095416_initial_model.sql (168.3ms)15152026/10/01 09:15:24 OK 20251210153512_drop_unused_gin_index.sql (12.09ms)15162026/10/01 09:15:24 OK 20251218171726_add_pins.sql (128.35ms)15172026/10/01 09:15:24 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=015182026/10/01 09:15:24 INFO Vacuumed table table=pending_closures15192026/10/01 09:15:24 INFO Vacuumed table table=pending_objects15202026/10/01 09:15:24 INFO Vacuumed table table=multipart_uploads15212026/10/01 09:15:24 INFO Vacuumed table table=closures15222026/10/01 09:15:24 OK 20260628120000_add_object_size_and_stats.sql (54.13ms)15232026/10/01 09:15:24 INFO Vacuumed table table=objects1524--- PASS: TestGCSweepDeliversEachKeyOnce (3.71s)1525=== CONT TestLeadEndsOnShutdown1526--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.01s)1527=== CONT TestLeadElectsOneAndHandsOver15282026/10/01 09:15:24 OK 20260905000000_add_claims.sql (75.9ms)15292026/10/01 09:15:24 OK 20260920000000_drop_claims.sql (51.15ms)15302026/10/01 09:15:24 OK 20260923120000_add_pushes.sql (4.46ms)15312026/10/01 09:15:24 goose: successfully migrated database to version: 2026092312000015322026/10/01 09:15:24 OK 1_commit_pending_closure.sql (3.11ms)15332026/10/01 09:15:24 OK 2_object_stats_trigger.sql (539.63µs)15342026/10/01 09:15:24 OK 3_commit_push.sql (413.5µs)15352026/10/01 09:15:24 goose: up to current file version: 315362026/10/01 09:15:25 INFO Received uploads request method=POST path=/api/pending_closures1537--- PASS: TestTombstonedObjectOfferedWithoutWaiting (3.29s)1538=== CONT TestResolveDBConnectionString1539=== RUN TestResolveDBConnectionString/flag_wins1540=== PAUSE TestResolveDBConnectionString/flag_wins1541=== RUN TestResolveDBConnectionString/file_when_flag_empty1542=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1543=== RUN TestResolveDBConnectionString/missing_file_is_an_error1544=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1545=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1546=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1547=== RUN TestResolveDBConnectionString/nothing_configured1548=== PAUSE TestResolveDBConnectionString/nothing_configured1549=== CONT TestGCTaskStore_ConflictDifferentParams1550--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1551=== CONT TestClientErrorHandling1552=== RUN TestClientErrorHandling/InvalidStorePath1553=== PAUSE TestClientErrorHandling/InvalidStorePath1554=== RUN TestClientErrorHandling/InvalidAuthToken1555=== PAUSE TestClientErrorHandling/InvalidAuthToken1556=== RUN TestClientErrorHandling/ServerNotAvailable1557=== PAUSE TestClientErrorHandling/ServerNotAvailable1558=== CONT TestGCTaskStore_GetEmpty1559--- PASS: TestGCTaskStore_GetEmpty (0.00s)1560=== CONT TestClientCADerivations15612026-10-01 09:15:25.200 UTC [14072] ERROR: relation "goose_db_version" does not exist at character 3615622026-10-01 09:15:25.200 UTC [14072] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15632026-10-01 09:15:25.241 UTC [14075] ERROR: relation "goose_db_version" does not exist at character 3615642026-10-01 09:15:25.241 UTC [14075] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15652026/10/01 09:15:25 OK 20241026095416_initial_model.sql (81ms)15662026/10/01 09:15:25 OK 20251210153512_drop_unused_gin_index.sql (15.96ms)15672026-10-01 09:15:25.363 UTC [14076] ERROR: relation "goose_db_version" does not exist at character 3615682026-10-01 09:15:25.363 UTC [14076] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026/10/01 09:15:25 OK 20251218171726_add_pins.sql (27.33ms)15702026/10/01 09:15:25 OK 20241026095416_initial_model.sql (92.32ms)15712026/10/01 09:15:25 OK 20251210153512_drop_unused_gin_index.sql (3.72ms)15722026/10/01 09:15:25 OK 20260628120000_add_object_size_and_stats.sql (16.71ms)15732026/10/01 09:15:25 OK 20251218171726_add_pins.sql (26.27ms)15742026/10/01 09:15:25 OK 20260905000000_add_claims.sql (31.87ms)15752026/10/01 09:15:25 OK 20260628120000_add_object_size_and_stats.sql (25.93ms)15762026/10/01 09:15:25 OK 20260920000000_drop_claims.sql (23.32ms)15772026/10/01 09:15:25 OK 20260923120000_add_pushes.sql (29.03ms)15782026/10/01 09:15:25 goose: successfully migrated database to version: 2026092312000015792026/10/01 09:15:25 OK 20260905000000_add_claims.sql (40.74ms)15802026/10/01 09:15:25 OK 1_commit_pending_closure.sql (3.65ms)15812026/10/01 09:15:25 OK 2_object_stats_trigger.sql (859.63µs)15822026/10/01 09:15:25 OK 3_commit_push.sql (515.63µs)15832026/10/01 09:15:25 goose: up to current file version: 315842026/10/01 09:15:25 OK 20260920000000_drop_claims.sql (43.23ms)15852026/10/01 09:15:25 OK 20241026095416_initial_model.sql (128.43ms)15862026/10/01 09:15:25 OK 20260923120000_add_pushes.sql (10.8ms)15872026/10/01 09:15:25 goose: successfully migrated database to version: 2026092312000015882026/10/01 09:15:25 OK 20251210153512_drop_unused_gin_index.sql (10.58ms)15892026/10/01 09:15:25 OK 1_commit_pending_closure.sql (4.27ms)15902026/10/01 09:15:25 OK 2_object_stats_trigger.sql (867.83µs)15912026/10/01 09:15:25 OK 3_commit_push.sql (598.25µs)15922026/10/01 09:15:25 goose: up to current file version: 315932026/10/01 09:15:25 OK 20251218171726_add_pins.sql (23.58ms)15942026/10/01 09:15:25 OK 20260628120000_add_object_size_and_stats.sql (49.29ms)15952026/10/01 09:15:25 OK 20260905000000_add_claims.sql (70.19ms)15962026/10/01 09:15:25 OK 20260920000000_drop_claims.sql (50.72ms)15972026/10/01 09:15:25 OK 20260923120000_add_pushes.sql (36.85ms)15982026/10/01 09:15:25 goose: successfully migrated database to version: 2026092312000015992026/10/01 09:15:25 OK 1_commit_pending_closure.sql (4.4ms)16002026/10/01 09:15:25 OK 2_object_stats_trigger.sql (983.54µs)16012026/10/01 09:15:25 OK 3_commit_push.sql (744.33µs)16022026/10/01 09:15:25 goose: up to current file version: 316032026/10/01 09:15:25 INFO Aborted multipart uploads count=016042026/10/01 09:15:25 WARN Force mode enabled - objects will be deleted immediately without grace period16052026/10/01 09:15:25 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016062026/10/01 09:15:25 INFO Vacuumed table table=pending_closures16072026/10/01 09:15:25 INFO Vacuumed table table=pending_objects16082026/10/01 09:15:25 INFO Vacuumed table table=multipart_uploads16092026/10/01 09:15:25 INFO Vacuumed table table=closures16102026/10/01 09:15:25 INFO Vacuumed table table=objects16112026/10/01 09:15:25 INFO Aborted multipart uploads count=016122026/10/01 09:15:25 WARN Force mode enabled - objects will be deleted immediately without grace period16132026-10-01 09:15:25.965 UTC [14079] ERROR: relation "goose_db_version" does not exist at character 3616142026-10-01 09:15:25.965 UTC [14079] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16152026/10/01 09:15:25 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=016162026/10/01 09:15:25 INFO Vacuumed table table=pending_closures16172026/10/01 09:15:25 INFO Vacuumed table table=pending_objects16182026/10/01 09:15:25 INFO Vacuumed table table=multipart_uploads16192026/10/01 09:15:25 INFO Vacuumed table table=closures16202026/10/01 09:15:26 INFO Vacuumed table table=objects1621--- PASS: TestSweepSkipsRowsLockedByPush (3.20s)1622=== CONT TestPinProtectsFromGC16232026-10-01 09:15:26.105 UTC [14082] ERROR: relation "goose_db_version" does not exist at character 3616242026-10-01 09:15:26.105 UTC [14082] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16252026/10/01 09:15:26 INFO Received uploads request method=POST path=/api/pending_closures16262026/10/01 09:15:26 OK 20241026095416_initial_model.sql (138.74ms)16272026-10-01 09:15:26.167 UTC [14083] ERROR: relation "goose_db_version" does not exist at character 3616282026-10-01 09:15:26.167 UTC [14083] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16292026/10/01 09:15:26 OK 20251210153512_drop_unused_gin_index.sql (4.23ms)16302026/10/01 09:15:26 INFO Aborted multipart uploads count=016312026/10/01 09:15:26 WARN Force mode enabled - objects will be deleted immediately without grace period16322026/10/01 09:15:26 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016332026/10/01 09:15:26 OK 20251218171726_add_pins.sql (32.91ms)16342026/10/01 09:15:26 INFO Vacuumed table table=pending_closures16352026/10/01 09:15:26 INFO Vacuumed table table=pending_objects16362026/10/01 09:15:26 INFO Vacuumed table table=multipart_uploads16372026/10/01 09:15:26 OK 20260628120000_add_object_size_and_stats.sql (37.22ms)16382026/10/01 09:15:26 INFO Vacuumed table table=closures16392026/10/01 09:15:26 INFO Vacuumed table table=objects16402026/10/01 09:15:26 OK 20241026095416_initial_model.sql (128.07ms)1641--- PASS: TestGCSweepSkipsPendingObjects (3.43s)1642=== CONT TestClientFallsBackToClosures16432026/10/01 09:15:26 OK 20260905000000_add_claims.sql (39.69ms)16442026/10/01 09:15:26 OK 20251210153512_drop_unused_gin_index.sql (10.26ms)16452026/10/01 09:15:26 OK 20251218171726_add_pins.sql (10.07ms)16462026/10/01 09:15:26 OK 20260920000000_drop_claims.sql (12.74ms)16472026/10/01 09:15:26 OK 20260923120000_add_pushes.sql (7.82ms)16482026/10/01 09:15:26 goose: successfully migrated database to version: 2026092312000016492026/10/01 09:15:26 OK 1_commit_pending_closure.sql (1.73ms)16502026/10/01 09:15:26 OK 2_object_stats_trigger.sql (356.75µs)16512026/10/01 09:15:26 OK 3_commit_push.sql (334.04µs)16522026/10/01 09:15:26 goose: up to current file version: 316532026/10/01 09:15:26 OK 20260628120000_add_object_size_and_stats.sql (24.91ms)16542026/10/01 09:15:26 OK 20241026095416_initial_model.sql (108.23ms)16552026/10/01 09:15:26 OK 20251210153512_drop_unused_gin_index.sql (8.48ms)16562026/10/01 09:15:26 OK 20260905000000_add_claims.sql (46.06ms)16572026/10/01 09:15:26 OK 20251218171726_add_pins.sql (18.25ms)16582026/10/01 09:15:26 INFO Aborted multipart uploads count=016592026/10/01 09:15:26 OK 20260920000000_drop_claims.sql (19.03ms)16602026/10/01 09:15:26 WARN Force mode enabled - objects will be deleted immediately without grace period16612026/10/01 09:15:26 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016622026/10/01 09:15:26 INFO Vacuumed table table=pending_closures16632026/10/01 09:15:26 INFO Vacuumed table table=pending_objects16642026/10/01 09:15:26 INFO Vacuumed table table=multipart_uploads16652026/10/01 09:15:26 INFO Vacuumed table table=closures16662026/10/01 09:15:26 INFO Vacuumed table table=objects1667--- PASS: TestGCMetrics (3.01s)1668=== CONT TestClientPushesUseOnePush16692026/10/01 09:15:26 OK 20260923120000_add_pushes.sql (20.21ms)16702026/10/01 09:15:26 goose: successfully migrated database to version: 2026092312000016712026/10/01 09:15:26 OK 1_commit_pending_closure.sql (1.6ms)16722026/10/01 09:15:26 OK 2_object_stats_trigger.sql (410.25µs)16732026/10/01 09:15:26 OK 3_commit_push.sql (292.67µs)16742026/10/01 09:15:26 goose: up to current file version: 316752026/10/01 09:15:26 OK 20260628120000_add_object_size_and_stats.sql (42.53ms)16762026-10-01 09:15:26.426 UTC [14088] ERROR: relation "goose_db_version" does not exist at character 3616772026-10-01 09:15:26.426 UTC [14088] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16782026/10/01 09:15:26 OK 20260905000000_add_claims.sql (14.26ms)16792026/10/01 09:15:26 OK 20260920000000_drop_claims.sql (8.93ms)16802026/10/01 09:15:26 OK 20260923120000_add_pushes.sql (8.06ms)16812026/10/01 09:15:26 goose: successfully migrated database to version: 2026092312000016822026/10/01 09:15:26 OK 1_commit_pending_closure.sql (2.02ms)16832026/10/01 09:15:26 OK 2_object_stats_trigger.sql (349.58µs)16842026/10/01 09:15:26 OK 3_commit_push.sql (271.75µs)16852026/10/01 09:15:26 goose: up to current file version: 316862026-10-01 09:15:26.452 UTC [14091] ERROR: relation "goose_db_version" does not exist at character 3616872026-10-01 09:15:26.452 UTC [14091] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16882026/10/01 09:15:26 OK 20241026095416_initial_model.sql (73.26ms)16892026/10/01 09:15:26 OK 20251210153512_drop_unused_gin_index.sql (8.34ms)16902026/10/01 09:15:26 OK 20251218171726_add_pins.sql (18.46ms)16912026/10/01 09:15:26 OK 20241026095416_initial_model.sql (91.68ms)16922026/10/01 09:15:26 OK 20260628120000_add_object_size_and_stats.sql (10.87ms)16932026/10/01 09:15:26 OK 20251210153512_drop_unused_gin_index.sql (7.14ms)16942026/10/01 09:15:26 OK 20260905000000_add_claims.sql (42.9ms)16952026/10/01 09:15:26 OK 20251218171726_add_pins.sql (35.82ms)16962026/10/01 09:15:26 OK 20260920000000_drop_claims.sql (15.69ms)16972026/10/01 09:15:26 OK 20260628120000_add_object_size_and_stats.sql (20.29ms)16982026/10/01 09:15:26 OK 20260923120000_add_pushes.sql (4.96ms)16992026/10/01 09:15:26 goose: successfully migrated database to version: 2026092312000017002026/10/01 09:15:26 OK 1_commit_pending_closure.sql (4.14ms)17012026/10/01 09:15:26 OK 2_object_stats_trigger.sql (1.36ms)17022026/10/01 09:15:26 OK 3_commit_push.sql (611.71µs)17032026/10/01 09:15:26 goose: up to current file version: 317042026/10/01 09:15:26 OK 20260905000000_add_claims.sql (16.47ms)17052026-10-01 09:15:26.650 UTC [14092] ERROR: relation "goose_db_version" does not exist at character 3617062026-10-01 09:15:26.650 UTC [14092] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17072026/10/01 09:15:26 OK 20260920000000_drop_claims.sql (9.91ms)17082026/10/01 09:15:26 OK 20260923120000_add_pushes.sql (25.84ms)17092026/10/01 09:15:26 goose: successfully migrated database to version: 2026092312000017102026/10/01 09:15:26 OK 1_commit_pending_closure.sql (3.28ms)17112026/10/01 09:15:26 OK 2_object_stats_trigger.sql (733.17µs)17122026/10/01 09:15:26 OK 3_commit_push.sql (497.04µs)17132026/10/01 09:15:26 goose: up to current file version: 317142026/10/01 09:15:26 OK 20241026095416_initial_model.sql (94.15ms)17152026/10/01 09:15:26 OK 20251210153512_drop_unused_gin_index.sql (11.35ms)17162026/10/01 09:15:26 OK 20251218171726_add_pins.sql (33.03ms)17172026/10/01 09:15:26 OK 20260628120000_add_object_size_and_stats.sql (20.43ms)17182026/10/01 09:15:26 OK 20260905000000_add_claims.sql (24.76ms)17192026/10/01 09:15:26 OK 20260920000000_drop_claims.sql (16.69ms)17202026/10/01 09:15:26 OK 20260923120000_add_pushes.sql (6.84ms)17212026/10/01 09:15:26 goose: successfully migrated database to version: 2026092312000017222026/10/01 09:15:26 OK 1_commit_pending_closure.sql (4.98ms)17232026/10/01 09:15:26 OK 2_object_stats_trigger.sql (616.83µs)17242026/10/01 09:15:26 OK 3_commit_push.sql (352.96µs)17252026/10/01 09:15:26 goose: up to current file version: 31726=== NAME TestOrphanedObjectsGCStressTest1727 orphaned_objects_gc_test.go:509: Stress test completed successfully:1728 orphaned_objects_gc_test.go:510: - Active objects preserved: 201729 orphaned_objects_gc_test.go:511: - Objects deleted: 2101730 orphaned_objects_gc_test.go:512: - Total GC'd: 2101731--- PASS: TestOrphanedObjectsGCStressTest (10.98s)1732=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1733--- PASS: TestGCBugBareHashReferences (2.99s)1734=== CONT TestService_ReadAuthMiddleware17352026-10-01 09:15:27.096 UTC [14095] ERROR: relation "goose_db_version" does not exist at character 3617362026-10-01 09:15:27.096 UTC [14095] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1737=== NAME TestClientIntegration1738 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-13789-2688134661/TestClientIntegration3966945784/002/store/7fv914rrl6vqjzkhjrf73jkmwna9aycm-test-file.txt17392026/10/01 09:15:27 OK 20241026095416_initial_model.sql (61.16ms)17402026/10/01 09:15:27 OK 20251210153512_drop_unused_gin_index.sql (5.9ms)17412026-10-01 09:15:27.211 UTC [14101] ERROR: relation "goose_db_version" does not exist at character 3617422026-10-01 09:15:27.211 UTC [14101] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17432026/10/01 09:15:27 OK 20251218171726_add_pins.sql (13.41ms)17442026/10/01 09:15:27 OK 20260628120000_add_object_size_and_stats.sql (14.27ms)17452026/10/01 09:15:27 INFO lead: acquired remote=192.0.2.1:123417462026/10/01 09:15:27 OK 20260905000000_add_claims.sql (18.35ms)17472026/10/01 09:15:27 INFO Received push request method=POST path=/api/pushes17482026/10/01 09:15:27 OK 20260920000000_drop_claims.sql (26.66ms)17492026/10/01 09:15:27 OK 20260923120000_add_pushes.sql (12.59ms)17502026/10/01 09:15:27 goose: successfully migrated database to version: 2026092312000017512026/10/01 09:15:27 OK 1_commit_pending_closure.sql (919.5µs)17522026/10/01 09:15:27 OK 2_object_stats_trigger.sql (233.67µs)17532026/10/01 09:15:27 OK 3_commit_push.sql (178.58µs)17542026/10/01 09:15:27 goose: up to current file version: 317552026/10/01 09:15:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17562026/10/01 09:15:27 INFO Uploading 7fv914rrl6vqjzkhjrf73jkmwna9aycm-test-file.txt (152B)17572026/10/01 09:15:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17582026/10/01 09:15:27 INFO Signed narinfos id=1 count=117592026/10/01 09:15:27 WARN Failed to register uploaded object key=7fv914rrl6vqjzkhjrf73jkmwna9aycm.ls error="server returned 404: 404 page not found\n"17602026/10/01 09:15:27 INFO Uploading 1 narinfos17612026/10/01 09:15:27 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17622026/10/01 09:15:27 INFO Received complete push request method=POST path=/api/pushes/1/complete17632026/10/01 09:15:27 WARN Failed to register uploaded object key=7fv914rrl6vqjzkhjrf73jkmwna9aycm.narinfo error="server returned 404: 404 page not found\n"17642026/10/01 09:15:27 INFO Upload complete. (120ms)17652026/10/01 09:15:27 OK 20241026095416_initial_model.sql (112.03ms)17662026/10/01 09:15:27 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)17672026/10/01 09:15:27 INFO All 1 paths already cached1768 client_integration_test.go:312: Retrieved narinfo from S3:1769 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientIntegration3966945784/002/store/7fv914rrl6vqjzkhjrf73jkmwna9aycm-test-file.txt1770 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1771 Compression: zstd1772 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11773 NarSize: 1521774 References: 1775 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11776 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1777 client_integration_test.go:313: Decompressed .ls content (64 bytes):1778 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1779 client_integration_test.go:316: Testing garbage collection...17802026/10/01 09:15:27 OK 20251218171726_add_pins.sql (19.82ms)17812026-10-01 09:15:27.390 UTC [14110] ERROR: relation "goose_db_version" does not exist at character 3617822026-10-01 09:15:27.390 UTC [14110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17832026/10/01 09:15:27 INFO lead: released remote=192.0.2.1:123417842026/10/01 09:15:27 OK 20260628120000_add_object_size_and_stats.sql (20.44ms)17852026/10/01 09:15:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures17862026/10/01 09:15:27 INFO Garbage collection started17872026/10/01 09:15:27 INFO Aborted multipart uploads count=017882026/10/01 09:15:27 OK 20260905000000_add_claims.sql (11.6ms)17892026/10/01 09:15:27 WARN Force mode enabled - objects will be deleted immediately without grace period17902026/10/01 09:15:27 OK 20260920000000_drop_claims.sql (15.79ms)17912026/10/01 09:15:27 OK 20260923120000_add_pushes.sql (4.07ms)17922026/10/01 09:15:27 goose: successfully migrated database to version: 2026092312000017932026/10/01 09:15:27 OK 1_commit_pending_closure.sql (1.25ms)17942026/10/01 09:15:27 OK 2_object_stats_trigger.sql (221.17µs)17952026/10/01 09:15:27 OK 3_commit_push.sql (170.25µs)17962026/10/01 09:15:27 goose: up to current file version: 317972026/10/01 09:15:27 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=017982026/10/01 09:15:27 INFO lead: acquired remote=192.0.2.1:123417992026/10/01 09:15:27 INFO lead: released remote=192.0.2.1:12341800--- PASS: TestLeadElectsOneAndHandsOver (2.78s)1801=== CONT TestCacheConfigHandler1802=== RUN TestCacheConfigHandler/full_config,_no_issuer1803=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1804=== RUN TestCacheConfigHandler/no_cache_url_configured1805=== PAUSE TestCacheConfigHandler/no_cache_url_configured1806=== RUN TestCacheConfigHandler/no_signing_keys1807=== PAUSE TestCacheConfigHandler/no_signing_keys1808=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1809=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1810=== CONT TestService_AuthMiddleware_OIDC18112026/10/01 09:15:27 INFO Vacuumed table table=pending_closures18122026/10/01 09:15:27 INFO lead: acquired remote=192.0.2.1:123418132026/10/01 09:15:27 INFO lead: released remote=192.0.2.1:12341814--- PASS: TestLeadEndsOnShutdown (2.84s)1815=== CONT TestCacheStatsHandler18162026/10/01 09:15:27 OK 20241026095416_initial_model.sql (96.09ms)1817--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.68s)1818=== CONT TestClientSharedPathCommittedMidPush18192026/10/01 09:15:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62302/oidc18202026/10/01 09:15:27 OK 20251210153512_drop_unused_gin_index.sql (15.93ms)18212026/10/01 09:15:27 INFO Vacuumed table table=pending_objects18222026/10/01 09:15:27 INFO Vacuumed table table=multipart_uploads18232026/10/01 09:15:27 INFO Vacuumed table table=closures18242026/10/01 09:15:27 OK 20251218171726_add_pins.sql (26.93ms)18252026/10/01 09:15:27 INFO Vacuumed table table=objects18262026/10/01 09:15:27 OK 20260628120000_add_object_size_and_stats.sql (16.58ms)18272026/10/01 09:15:27 OK 20260905000000_add_claims.sql (31.35ms)18282026/10/01 09:15:27 OK 20260920000000_drop_claims.sql (17.23ms)18292026/10/01 09:15:27 OK 20260923120000_add_pushes.sql (9.27ms)18302026/10/01 09:15:27 goose: successfully migrated database to version: 2026092312000018312026/10/01 09:15:27 OK 1_commit_pending_closure.sql (1.2ms)18322026/10/01 09:15:27 OK 2_object_stats_trigger.sql (239.54µs)18332026/10/01 09:15:27 OK 3_commit_push.sql (215.67µs)18342026/10/01 09:15:27 goose: up to current file version: 31835=== NAME TestPinProtectsFromGC1836 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-13789-2688134661/TestPinProtectsFromGC3020826607/001/store/570ldwj6szrf2d66zabdwvwnn1hky91n-pinned-file.txt1837 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-13789-2688134661/TestPinProtectsFromGC3020826607/001/store/sxp4nrhffhfj9mrhxssg3k4lnbshfaxh-unpinned-file.txt1838=== NAME TestClientCADerivations1839 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-13789-2688134661/TestClientCADerivations4071441349/001/store/jarrha4vv3im3yvhkgxnnjbf31sk6rmf-ca-test18402026-10-01 09:15:28.079 UTC [14131] ERROR: relation "goose_db_version" does not exist at character 3618412026-10-01 09:15:28.079 UTC [14131] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1842 client_ca_test.go:139: Found 1 dependencies (including self)18432026/10/01 09:15:28 INFO Received push request method=POST path=/api/pushes18442026-10-01 09:15:28.133 UTC [14142] ERROR: relation "goose_db_version" does not exist at character 3618452026-10-01 09:15:28.133 UTC [14142] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18462026/10/01 09:15:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18472026/10/01 09:15:28 INFO Uploading 570ldwj6szrf2d66zabdwvwnn1hky91n-pinned-file.txt (128B)18482026/10/01 09:15:28 WARN Failed to register uploaded object key=570ldwj6szrf2d66zabdwvwnn1hky91n.ls error="server returned 404: 404 page not found\n"18492026/10/01 09:15:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18502026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"18512026/10/01 09:15:28 INFO Signed narinfos id=1 count=118522026/10/01 09:15:28 INFO Uploading 1 narinfos18532026/10/01 09:15:28 INFO Received complete push request method=POST path=/api/pushes/1/complete18542026/10/01 09:15:28 WARN Failed to register uploaded object key=570ldwj6szrf2d66zabdwvwnn1hky91n.narinfo error="server returned 404: 404 page not found\n"18552026/10/01 09:15:28 INFO Received push request method=POST path=/api/pushes18562026/10/01 09:15:28 INFO Upload complete. (142ms)18572026/10/01 09:15:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18582026/10/01 09:15:28 INFO Uploading jarrha4vv3im3yvhkgxnnjbf31sk6rmf-ca-test (144B)18592026/10/01 09:15:28 OK 20241026095416_initial_model.sql (101.35ms)18602026/10/01 09:15:28 OK 20251210153512_drop_unused_gin_index.sql (13.46ms)18612026/10/01 09:15:28 WARN Failed to register uploaded object key=jarrha4vv3im3yvhkgxnnjbf31sk6rmf.ls error="server returned 404: 404 page not found\n"18622026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18632026/10/01 09:15:28 WARN Failed to register uploaded object key=log/831fgma752prbdir3h14bnxsr79mnvfj-ca-test.drv error="server returned 404: 404 page not found\n"18642026/10/01 09:15:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18652026/10/01 09:15:28 INFO Signed narinfos id=1 count=118662026/10/01 09:15:28 OK 20251218171726_add_pins.sql (9.56ms)18672026/10/01 09:15:28 INFO Uploading 1 narinfos18682026/10/01 09:15:28 INFO Received complete push request method=POST path=/api/pushes/1/complete18692026/10/01 09:15:28 WARN Failed to register uploaded object key=jarrha4vv3im3yvhkgxnnjbf31sk6rmf.narinfo error="server returned 404: 404 page not found\n"18702026/10/01 09:15:28 OK 20260628120000_add_object_size_and_stats.sql (22.92ms)18712026/10/01 09:15:28 INFO Upload complete. (168ms)1872 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientCADerivations4071441349/001/store/jarrha4vv3im3yvhkgxnnjbf31sk6rmf-ca-test1873 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1874 Compression: zstd1875 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1876 NarSize: 1441877 References: 1878 Deriver: /nix/var/nix/builds/nix-13789-2688134661/TestClientCADerivations4071441349/001/store/831fgma752prbdir3h14bnxsr79mnvfj-ca-test.drv1879 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1880 client_ca_test.go:185: Checking for realisation files in S3...1881 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1882 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18832026/10/01 09:15:28 OK 20260905000000_add_claims.sql (12.82ms)18842026/10/01 09:15:28 OK 20241026095416_initial_model.sql (73.7ms)18852026/10/01 09:15:28 INFO Received push request method=POST path=/api/pushes18862026/10/01 09:15:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18872026/10/01 09:15:28 INFO Uploading sxp4nrhffhfj9mrhxssg3k4lnbshfaxh-unpinned-file.txt (128B)18882026/10/01 09:15:28 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)18892026/10/01 09:15:28 OK 20260920000000_drop_claims.sql (8.41ms)18902026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18912026/10/01 09:15:28 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18922026/10/01 09:15:28 WARN Failed to register uploaded object key=sxp4nrhffhfj9mrhxssg3k4lnbshfaxh.ls error="server returned 404: 404 page not found\n"18932026/10/01 09:15:28 INFO Signed narinfos id=2 count=118942026/10/01 09:15:28 INFO Uploading 1 narinfos18952026/10/01 09:15:28 OK 20260923120000_add_pushes.sql (6.16ms)18962026/10/01 09:15:28 goose: successfully migrated database to version: 2026092312000018972026/10/01 09:15:28 INFO Received complete push request method=POST path=/api/pushes/2/complete18982026/10/01 09:15:28 OK 20251218171726_add_pins.sql (7.4ms)18992026/10/01 09:15:28 WARN Failed to register uploaded object key=sxp4nrhffhfj9mrhxssg3k4lnbshfaxh.narinfo error="server returned 404: 404 page not found\n"19002026/10/01 09:15:28 INFO Upload complete. (60ms)19012026/10/01 09:15:28 OK 1_commit_pending_closure.sql (2.19ms)19022026/10/01 09:15:28 OK 2_object_stats_trigger.sql (731.46µs)19032026/10/01 09:15:28 OK 3_commit_push.sql (473.29µs)19042026/10/01 09:15:28 goose: up to current file version: 319052026/10/01 09:15:28 OK 20260628120000_add_object_size_and_stats.sql (21.62ms)19062026/10/01 09:15:28 INFO Received create pin request method=POST path=/api/pins/myapp19072026/10/01 09:15:28 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-13789-2688134661/TestPinProtectsFromGC3020826607/001/store/570ldwj6szrf2d66zabdwvwnn1hky91n-pinned-file.txt narinfo_key=570ldwj6szrf2d66zabdwvwnn1hky91n.narinfo19082026/10/01 09:15:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures19092026/10/01 09:15:28 INFO Garbage collection started19102026/10/01 09:15:28 INFO Aborted multipart uploads count=019112026/10/01 09:15:28 WARN Force mode enabled - objects will be deleted immediately without grace period19122026/10/01 09:15:28 OK 20260905000000_add_claims.sql (37.92ms)1913 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket46?endpoint=http://localhost:62140®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-13789-2688134661/TestClientCADerivations4071441349/001/store'1914 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119152026/10/01 09:15:28 INFO Received uploads request method=POST path=/api/pending_closures19162026/10/01 09:15:28 OK 20260920000000_drop_claims.sql (43.9ms)19172026/10/01 09:15:28 INFO Received uploads request method=POST path=/api/pending_closures19182026/10/01 09:15:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19192026/10/01 09:15:28 INFO Uploading iih8qc1p9ywwpmrbymls9r603a7g82ml-b (248B)19202026/10/01 09:15:28 INFO Uploading f5w36scrq36yncghrd9k1fr049vz0k87-shared-dep (136B)19212026/10/01 09:15:28 OK 20260923120000_add_pushes.sql (26.65ms)19222026/10/01 09:15:28 goose: successfully migrated database to version: 2026092312000019232026/10/01 09:15:28 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=019242026/10/01 09:15:28 OK 1_commit_pending_closure.sql (1.44ms)19252026/10/01 09:15:28 OK 2_object_stats_trigger.sql (226.67µs)19262026/10/01 09:15:28 OK 3_commit_push.sql (191.88µs)19272026/10/01 09:15:28 goose: up to current file version: 319282026/10/01 09:15:28 WARN Failed to register uploaded object key=436bxlbp5hl4cpmsx5rcsb2vvrnrzzxj.ls error="server returned 404: 404 page not found\n"19292026/10/01 09:15:28 WARN Failed to register uploaded object key=f5w36scrq36yncghrd9k1fr049vz0k87.ls error="server returned 404: 404 page not found\n"19302026/10/01 09:15:28 WARN Failed to register uploaded object key=iih8qc1p9ywwpmrbymls9r603a7g82ml.ls error="server returned 404: 404 page not found\n"19312026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19322026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/16gln3lv88xg0p69w2psh2rp3jikwkbpqaa4w3nhjy83q8dsfl4g.nar.zst error="server returned 404: 404 page not found\n"19332026/10/01 09:15:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19342026/10/01 09:15:28 INFO Signed narinfos id=1 count=219352026/10/01 09:15:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign19362026/10/01 09:15:28 INFO Signed narinfos id=2 count=219372026/10/01 09:15:28 INFO Uploading 4 narinfos19382026/10/01 09:15:28 INFO Vacuumed table table=pending_closures19392026/10/01 09:15:28 WARN Failed to register uploaded object key=iih8qc1p9ywwpmrbymls9r603a7g82ml.narinfo error="server returned 404: 404 page not found\n"19402026/10/01 09:15:28 WARN Failed to register uploaded object key=436bxlbp5hl4cpmsx5rcsb2vvrnrzzxj.narinfo error="server returned 404: 404 page not found\n"19412026/10/01 09:15:28 WARN Failed to register uploaded object key=f5w36scrq36yncghrd9k1fr049vz0k87.narinfo error="server returned 404: 404 page not found\n"19422026/10/01 09:15:28 INFO Vacuumed table table=pending_objects19432026/10/01 09:15:28 INFO Vacuumed table table=multipart_uploads1944--- PASS: TestClientCADerivations (3.31s)1945=== CONT TestService_AuthMiddleware_MTLSProxyHeader19462026/10/01 09:15:28 INFO Vacuumed table table=closures19472026/10/01 09:15:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19482026/10/01 09:15:28 WARN Failed to register uploaded object key=f5w36scrq36yncghrd9k1fr049vz0k87.narinfo error="server returned 404: 404 page not found\n"19492026/10/01 09:15:28 INFO Vacuumed table table=objects19502026/10/01 09:15:28 INFO Completed upload id=219512026/10/01 09:15:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19522026/10/01 09:15:28 INFO Completed upload id=119532026/10/01 09:15:28 INFO Upload complete. (166ms)1954=== NAME TestClientFallsBackToClosures1955 client_pushes_test.go:112: Retrieved narinfo from S3:1956 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientFallsBackToClosures513883160/001/store/f5w36scrq36yncghrd9k1fr049vz0k87-shared-dep1957 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1958 Compression: zstd1959 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821960 NarSize: 1361961 References: 1962 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1963 client_pushes_test.go:112: Retrieved narinfo from S3:1964 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientFallsBackToClosures513883160/001/store/436bxlbp5hl4cpmsx5rcsb2vvrnrzzxj-a1965 URL: nar/16gln3lv88xg0p69w2psh2rp3jikwkbpqaa4w3nhjy83q8dsfl4g.nar.zst1966 Compression: zstd1967 NarHash: sha256:16gln3lv88xg0p69w2psh2rp3jikwkbpqaa4w3nhjy83q8dsfl4g1968 NarSize: 2481969 References: /nix/var/nix/builds/nix-13789-2688134661/TestClientFallsBackToClosures513883160/001/store/f5w36scrq36yncghrd9k1fr049vz0k87-shared-dep1970 CA: text:sha256:17msymcpai8r2pd86qc99z2k7zr915n92y0p7m9v4jn7vz9j52c21971 client_pushes_test.go:112: Retrieved narinfo from S3:1972 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientFallsBackToClosures513883160/001/store/iih8qc1p9ywwpmrbymls9r603a7g82ml-b1973 URL: nar/16gln3lv88xg0p69w2psh2rp3jikwkbpqaa4w3nhjy83q8dsfl4g.nar.zst1974 Compression: zstd1975 NarHash: sha256:16gln3lv88xg0p69w2psh2rp3jikwkbpqaa4w3nhjy83q8dsfl4g1976 NarSize: 2481977 References: /nix/var/nix/builds/nix-13789-2688134661/TestClientFallsBackToClosures513883160/001/store/f5w36scrq36yncghrd9k1fr049vz0k87-shared-dep1978 CA: text:sha256:17msymcpai8r2pd86qc99z2k7zr915n92y0p7m9v4jn7vz9j52c21979--- PASS: TestClientFallsBackToClosures (2.27s)1980=== CONT TestService_RequireScope_OIDC19812026/10/01 09:15:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62353/oidc19822026/10/01 09:15:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19832026/10/01 09:15:28 WARN mTLS auth: bound subjects configured but subject DN unavailable19842026/10/01 09:15:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1985--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.60s)1986=== CONT TestService_ReadScope_PublicByDefault19872026-10-01 09:15:28.698 UTC [14180] ERROR: relation "goose_db_version" does not exist at character 3619882026-10-01 09:15:28.698 UTC [14180] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19892026-10-01 09:15:28.699 UTC [14179] ERROR: relation "goose_db_version" does not exist at character 3619902026-10-01 09:15:28.699 UTC [14179] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19912026-10-01 09:15:28.719 UTC [14181] ERROR: relation "goose_db_version" does not exist at character 3619922026-10-01 09:15:28.719 UTC [14181] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19932026/10/01 09:15:28 INFO Received push request method=POST path=/api/pushes19942026/10/01 09:15:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19952026/10/01 09:15:28 INFO Uploading z03infm8wca8v27pnyjh3zhjcvxlz353-a (248B)19962026/10/01 09:15:28 INFO Uploading 7jvb0f4wa3n4xq56llnj70k6x4riir0y-shared-dep (136B)1997--- PASS: TestService_ReadAuthMiddleware (1.69s)1998=== CONT TestFailedS3DeleteKeepsTombstone19992026/10/01 09:15:28 WARN Failed to register uploaded object key=7jvb0f4wa3n4xq56llnj70k6x4riir0y.ls error="server returned 404: 404 page not found\n"20002026/10/01 09:15:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20012026/10/01 09:15:28 WARN Failed to register uploaded object key=yngvcagawmav6zyw835q49x8lj413lby.ls error="server returned 404: 404 page not found\n"20022026/10/01 09:15:28 WARN Failed to register uploaded object key=z03infm8wca8v27pnyjh3zhjcvxlz353.ls error="server returned 404: 404 page not found\n"20032026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20042026/10/01 09:15:28 WARN Failed to register uploaded object key=nar/1z9pq37ajnbksa5w2dhk99ly3n6yyavdbsrsikmmg3aa801x25vc.nar.zst error="server returned 404: 404 page not found\n"20052026/10/01 09:15:28 INFO Signed narinfos id=1 count=320062026/10/01 09:15:28 INFO Uploading 3 narinfos20072026/10/01 09:15:28 WARN Failed to register uploaded object key=yngvcagawmav6zyw835q49x8lj413lby.narinfo error="server returned 404: 404 page not found\n"20082026/10/01 09:15:28 WARN Failed to register uploaded object key=7jvb0f4wa3n4xq56llnj70k6x4riir0y.narinfo error="server returned 404: 404 page not found\n"20092026/10/01 09:15:28 INFO Received complete push request method=POST path=/api/pushes/1/complete20102026/10/01 09:15:28 WARN Failed to register uploaded object key=z03infm8wca8v27pnyjh3zhjcvxlz353.narinfo error="server returned 404: 404 page not found\n"20112026/10/01 09:15:28 OK 20241026095416_initial_model.sql (52.84ms)20122026/10/01 09:15:28 OK 20241026095416_initial_model.sql (52.89ms)20132026/10/01 09:15:28 INFO Upload complete. (102ms)2014=== NAME TestClientPushesUseOnePush2015 client_pushes_test.go:97: Retrieved narinfo from S3:2016 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientPushesUseOnePush561988262/001/store/7jvb0f4wa3n4xq56llnj70k6x4riir0y-shared-dep2017 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2018 Compression: zstd2019 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822020 NarSize: 1362021 References: 2022 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2023 client_pushes_test.go:97: Retrieved narinfo from S3:2024 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientPushesUseOnePush561988262/001/store/z03infm8wca8v27pnyjh3zhjcvxlz353-a2025 URL: nar/1z9pq37ajnbksa5w2dhk99ly3n6yyavdbsrsikmmg3aa801x25vc.nar.zst2026 Compression: zstd2027 NarHash: sha256:1z9pq37ajnbksa5w2dhk99ly3n6yyavdbsrsikmmg3aa801x25vc2028 NarSize: 2482029 References: /nix/var/nix/builds/nix-13789-2688134661/TestClientPushesUseOnePush561988262/001/store/7jvb0f4wa3n4xq56llnj70k6x4riir0y-shared-dep2030 CA: text:sha256:0z6q6vnkzi2phgxfrw2rmxhry86np956a36s1z7c6qsb95birlv12031 client_pushes_test.go:97: Retrieved narinfo from S3:2032 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientPushesUseOnePush561988262/001/store/yngvcagawmav6zyw835q49x8lj413lby-b2033 URL: nar/1z9pq37ajnbksa5w2dhk99ly3n6yyavdbsrsikmmg3aa801x25vc.nar.zst2034 Compression: zstd2035 NarHash: sha256:1z9pq37ajnbksa5w2dhk99ly3n6yyavdbsrsikmmg3aa801x25vc2036 NarSize: 2482037 References: /nix/var/nix/builds/nix-13789-2688134661/TestClientPushesUseOnePush561988262/001/store/7jvb0f4wa3n4xq56llnj70k6x4riir0y-shared-dep2038 CA: text:sha256:0z6q6vnkzi2phgxfrw2rmxhry86np956a36s1z7c6qsb95birlv120392026/10/01 09:15:28 OK 20251210153512_drop_unused_gin_index.sql (6.02ms)20402026/10/01 09:15:28 OK 20251210153512_drop_unused_gin_index.sql (6.11ms)20412026/10/01 09:15:28 OK 20251218171726_add_pins.sql (12.7ms)20422026/10/01 09:15:28 OK 20251218171726_add_pins.sql (13.08ms)20432026/10/01 09:15:28 OK 20241026095416_initial_model.sql (56.5ms)20442026/10/01 09:15:28 OK 20251210153512_drop_unused_gin_index.sql (800.75µs)2045--- PASS: TestClientPushesUseOnePush (2.42s)2046=== CONT TestRedundantMultipartUpload20472026/10/01 09:15:28 OK 20260628120000_add_object_size_and_stats.sql (10.26ms)20482026/10/01 09:15:28 OK 20251218171726_add_pins.sql (2.51ms)20492026/10/01 09:15:28 OK 20260628120000_add_object_size_and_stats.sql (10.79ms)20502026/10/01 09:15:28 OK 20260905000000_add_claims.sql (2.79ms)20512026/10/01 09:15:28 OK 20260905000000_add_claims.sql (3.09ms)20522026/10/01 09:15:28 OK 20260628120000_add_object_size_and_stats.sql (3.49ms)20532026/10/01 09:15:28 OK 20260920000000_drop_claims.sql (1.32ms)20542026/10/01 09:15:28 OK 20260920000000_drop_claims.sql (1.28ms)20552026/10/01 09:15:28 OK 20260923120000_add_pushes.sql (770.13µs)20562026/10/01 09:15:28 goose: successfully migrated database to version: 2026092312000020572026/10/01 09:15:28 OK 20260923120000_add_pushes.sql (1.39ms)20582026/10/01 09:15:28 goose: successfully migrated database to version: 2026092312000020592026/10/01 09:15:28 OK 20260905000000_add_claims.sql (1.95ms)20602026/10/01 09:15:28 OK 1_commit_pending_closure.sql (1.59ms)20612026/10/01 09:15:28 OK 2_object_stats_trigger.sql (278.25µs)20622026/10/01 09:15:28 OK 3_commit_push.sql (273.13µs)20632026/10/01 09:15:28 goose: up to current file version: 320642026/10/01 09:15:28 OK 20260920000000_drop_claims.sql (1.2ms)20652026/10/01 09:15:28 OK 1_commit_pending_closure.sql (1.24ms)20662026/10/01 09:15:28 OK 2_object_stats_trigger.sql (228.21µs)20672026/10/01 09:15:28 OK 3_commit_push.sql (194µs)20682026/10/01 09:15:28 goose: up to current file version: 320692026/10/01 09:15:28 OK 20260923120000_add_pushes.sql (537.25µs)20702026/10/01 09:15:28 goose: successfully migrated database to version: 2026092312000020712026/10/01 09:15:28 OK 1_commit_pending_closure.sql (792.88µs)20722026/10/01 09:15:28 OK 2_object_stats_trigger.sql (192.83µs)20732026/10/01 09:15:28 OK 3_commit_push.sql (154.67µs)20742026/10/01 09:15:28 goose: up to current file version: 32075=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2076=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2077=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2078=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2079=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2080=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2081=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2082=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2083=== CONT TestIsValidUploadKey2084=== RUN TestIsValidUploadKey/narinfo2085=== PAUSE TestIsValidUploadKey/narinfo2086=== RUN TestIsValidUploadKey/nar_zst2087=== PAUSE TestIsValidUploadKey/nar_zst2088=== RUN TestIsValidUploadKey/nar_xz2089=== PAUSE TestIsValidUploadKey/nar_xz2090=== RUN TestIsValidUploadKey/nar_plain2091=== PAUSE TestIsValidUploadKey/nar_plain2092=== RUN TestIsValidUploadKey/listing2093=== PAUSE TestIsValidUploadKey/listing2094=== RUN TestIsValidUploadKey/build_log2095=== PAUSE TestIsValidUploadKey/build_log2096=== RUN TestIsValidUploadKey/build_log_home-manager_file2097=== PAUSE TestIsValidUploadKey/build_log_home-manager_file2098=== RUN TestIsValidUploadKey/build_log_plus_in_name2099=== PAUSE TestIsValidUploadKey/build_log_plus_in_name2100=== RUN TestIsValidUploadKey/build_log_question_mark2101=== PAUSE TestIsValidUploadKey/build_log_question_mark2102=== RUN TestIsValidUploadKey/build_log_equals2103=== PAUSE TestIsValidUploadKey/build_log_equals2104=== RUN TestIsValidUploadKey/realisation2105=== PAUSE TestIsValidUploadKey/realisation2106=== RUN TestIsValidUploadKey/realisation_plus_in_output2107=== PAUSE TestIsValidUploadKey/realisation_plus_in_output2108=== RUN TestIsValidUploadKey/nix-cache-info2109=== PAUSE TestIsValidUploadKey/nix-cache-info2110=== RUN TestIsValidUploadKey/index.html2111=== PAUSE TestIsValidUploadKey/index.html2112=== RUN TestIsValidUploadKey/narinfo_key,_nar_type2113=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type2114=== RUN TestIsValidUploadKey/nar_key,_narinfo_type2115=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type2116=== RUN TestIsValidUploadKey/listing_key,_narinfo_type2117=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type2118=== RUN TestIsValidUploadKey/traversal2119=== PAUSE TestIsValidUploadKey/traversal2120=== RUN TestIsValidUploadKey/traversal_nar2121=== PAUSE TestIsValidUploadKey/traversal_nar2122=== RUN TestIsValidUploadKey/absolute2123=== PAUSE TestIsValidUploadKey/absolute2124=== RUN TestIsValidUploadKey/empty_key2125=== PAUSE TestIsValidUploadKey/empty_key2126=== RUN TestIsValidUploadKey/unknown_type2127=== PAUSE TestIsValidUploadKey/unknown_type2128=== CONT TestParseSize2129--- PASS: TestParseSize (0.00s)2130=== CONT TestProxyWriteTimeout2131=== RUN TestProxyWriteTimeout/narinfo2132=== PAUSE TestProxyWriteTimeout/narinfo2133=== RUN TestProxyWriteTimeout/1_GiB_nar2134=== PAUSE TestProxyWriteTimeout/1_GiB_nar2135=== RUN TestProxyWriteTimeout/10_GiB_nar2136=== PAUSE TestProxyWriteTimeout/10_GiB_nar2137=== RUN TestProxyWriteTimeout/unknown_size2138=== PAUSE TestProxyWriteTimeout/unknown_size2139=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2140--- PASS: TestCacheStatsHandler (1.68s)2141=== CONT TestSkippedUploadsHandler21422026/10/01 09:15:29 INFO Client skipped oversized paths paths=3 nar_bytes=50000000002143--- PASS: TestSkippedUploadsHandler (0.00s)2144=== CONT TestPush_OverlappingRootsStoreOneRowPerKey21452026-10-01 09:15:29.298 UTC [14191] ERROR: relation "goose_db_version" does not exist at character 3621462026-10-01 09:15:29.298 UTC [14191] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21472026-10-01 09:15:29.357 UTC [14193] ERROR: relation "goose_db_version" does not exist at character 3621482026-10-01 09:15:29.357 UTC [14193] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21492026-10-01 09:15:29.357 UTC [14194] ERROR: relation "goose_db_version" does not exist at character 3621502026-10-01 09:15:29.357 UTC [14194] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21512026/10/01 09:15:29 OK 20241026095416_initial_model.sql (29.49ms)21522026/10/01 09:15:29 OK 20251210153512_drop_unused_gin_index.sql (630.46µs)21532026/10/01 09:15:29 OK 20251218171726_add_pins.sql (2.38ms)21542026/10/01 09:15:29 OK 20260628120000_add_object_size_and_stats.sql (2.85ms)21552026/10/01 09:15:29 OK 20260905000000_add_claims.sql (4.76ms)21562026/10/01 09:15:29 OK 20241026095416_initial_model.sql (10.24ms)21572026/10/01 09:15:29 OK 20251210153512_drop_unused_gin_index.sql (516.46µs)21582026/10/01 09:15:29 OK 20241026095416_initial_model.sql (11.29ms)21592026/10/01 09:15:29 OK 20260920000000_drop_claims.sql (862.13µs)21602026/10/01 09:15:29 OK 20251210153512_drop_unused_gin_index.sql (598.79µs)21612026/10/01 09:15:29 OK 20260923120000_add_pushes.sql (1.11ms)21622026/10/01 09:15:29 goose: successfully migrated database to version: 2026092312000021632026/10/01 09:15:29 OK 20251218171726_add_pins.sql (2.35ms)21642026/10/01 09:15:29 OK 20251218171726_add_pins.sql (2.03ms)21652026/10/01 09:15:29 OK 1_commit_pending_closure.sql (1.85ms)21662026/10/01 09:15:29 OK 2_object_stats_trigger.sql (218.79µs)21672026/10/01 09:15:29 OK 3_commit_push.sql (177.96µs)21682026/10/01 09:15:29 goose: up to current file version: 321692026/10/01 09:15:29 OK 20260628120000_add_object_size_and_stats.sql (29.28ms)21702026/10/01 09:15:29 OK 20260628120000_add_object_size_and_stats.sql (30.3ms)21712026/10/01 09:15:29 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02172=== NAME TestClientIntegration2173 client_integration_test.go:323: Objects in database after GC:2174 client_integration_test.go:323: Successfully deleted all objects with GC --force21752026/10/01 09:15:29 OK 20260905000000_add_claims.sql (12.98ms)21762026/10/01 09:15:29 OK 20260905000000_add_claims.sql (14.95ms)2177--- PASS: TestClientIntegration (5.39s)2178=== CONT TestPush_SignsNarinfosOfItsPendingObjects21792026/10/01 09:15:29 OK 20260920000000_drop_claims.sql (12.64ms)21802026/10/01 09:15:29 OK 20260920000000_drop_claims.sql (12.87ms)21812026/10/01 09:15:29 OK 20260923120000_add_pushes.sql (1.4ms)21822026/10/01 09:15:29 goose: successfully migrated database to version: 2026092312000021832026/10/01 09:15:29 OK 20260923120000_add_pushes.sql (1.09ms)21842026/10/01 09:15:29 goose: successfully migrated database to version: 2026092312000021852026/10/01 09:15:29 OK 1_commit_pending_closure.sql (1.35ms)21862026/10/01 09:15:29 OK 1_commit_pending_closure.sql (1.24ms)21872026/10/01 09:15:29 OK 2_object_stats_trigger.sql (261.17µs)21882026/10/01 09:15:29 OK 2_object_stats_trigger.sql (270.42µs)21892026/10/01 09:15:29 OK 3_commit_push.sql (220.63µs)21902026/10/01 09:15:29 goose: up to current file version: 321912026/10/01 09:15:29 OK 3_commit_push.sql (193.46µs)21922026/10/01 09:15:29 goose: up to current file version: 321932026/10/01 09:15:29 INFO Received push request method=POST path=/api/pushes21942026/10/01 09:15:29 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21952026/10/01 09:15:29 INFO Uploading nfl49rwn96yq4laxx65zw271m2ci1pmq-shared-dep (136B)21962026/10/01 09:15:29 INFO Uploading w811gxj701x7lr2ayqpwpkh552svwnsf-top (256B)2197--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.09s)2198=== CONT TestPush_RejectsBadRequests21992026/10/01 09:15:29 WARN Failed to register uploaded object key=w811gxj701x7lr2ayqpwpkh552svwnsf.ls error="server returned 404: 404 page not found\n"22002026/10/01 09:15:29 WARN Failed to register uploaded object key=nar/01q4mmrysapn8pz04g61mz8rckbf7pxp8icsfy1h6gml8lh8s2q3.nar.zst error="server returned 404: 404 page not found\n"22012026/10/01 09:15:29 WARN Failed to register uploaded object key=nfl49rwn96yq4laxx65zw271m2ci1pmq.ls error="server returned 404: 404 page not found\n"22022026/10/01 09:15:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22032026/10/01 09:15:29 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22042026/10/01 09:15:29 INFO Signed narinfos id=1 count=222052026/10/01 09:15:29 INFO Uploading 2 narinfos22062026/10/01 09:15:29 WARN Failed to register uploaded object key=w811gxj701x7lr2ayqpwpkh552svwnsf.narinfo error="server returned 404: 404 page not found\n"22072026/10/01 09:15:29 INFO Received complete push request method=POST path=/api/pushes/1/complete22082026/10/01 09:15:29 WARN Failed to register uploaded object key=nfl49rwn96yq4laxx65zw271m2ci1pmq.narinfo error="server returned 404: 404 page not found\n"22092026/10/01 09:15:29 INFO Upload complete. (133ms)22102026-10-01 09:15:29.637 UTC [14206] ERROR: relation "goose_db_version" does not exist at character 3622112026-10-01 09:15:29.637 UTC [14206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2212=== NAME TestClientSharedPathCommittedMidPush2213 client_integration_test.go:680: Retrieved narinfo from S3:2214 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientSharedPathCommittedMidPush115098381/001/store/nfl49rwn96yq4laxx65zw271m2ci1pmq-shared-dep2215 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2216 Compression: zstd2217 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822218 NarSize: 1362219 References: 2220 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2221 client_integration_test.go:680: Retrieved narinfo from S3:2222 StorePath: /nix/var/nix/builds/nix-13789-2688134661/TestClientSharedPathCommittedMidPush115098381/001/store/w811gxj701x7lr2ayqpwpkh552svwnsf-top2223 URL: nar/01q4mmrysapn8pz04g61mz8rckbf7pxp8icsfy1h6gml8lh8s2q3.nar.zst2224 Compression: zstd2225 NarHash: sha256:01q4mmrysapn8pz04g61mz8rckbf7pxp8icsfy1h6gml8lh8s2q32226 NarSize: 2562227 References: /nix/var/nix/builds/nix-13789-2688134661/TestClientSharedPathCommittedMidPush115098381/001/store/nfl49rwn96yq4laxx65zw271m2ci1pmq-shared-dep2228 CA: text:sha256:1r63nw7m5zyb3vvwdcng8m81aj89j5v4hdbypdakkxgg8l4f4wk02229--- PASS: TestClientSharedPathCommittedMidPush (2.19s)2230=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit22312026-10-01 09:15:29.740 UTC [14208] ERROR: relation "goose_db_version" does not exist at character 3622322026-10-01 09:15:29.740 UTC [14208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22332026/10/01 09:15:29 OK 20241026095416_initial_model.sql (104.84ms)22342026/10/01 09:15:29 OK 20251210153512_drop_unused_gin_index.sql (7.28ms)2235=== RUN TestService_RequireScope_OIDC/builder_may_write2236=== PAUSE TestService_RequireScope_OIDC/builder_may_write2237=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2238=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2239=== RUN TestService_RequireScope_OIDC/ops_may_admin2240=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2241=== RUN TestService_RequireScope_OIDC/ops_may_not_write2242=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2243=== RUN TestService_RequireScope_OIDC/reader_may_not_write2244=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2245=== RUN TestService_RequireScope_OIDC/static_token_may_admin2246=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2247=== RUN TestService_RequireScope_OIDC/static_token_may_write2248=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2249=== RUN TestService_RequireScope_OIDC/reader_may_read2250=== PAUSE TestService_RequireScope_OIDC/reader_may_read2251=== RUN TestService_RequireScope_OIDC/writer_implies_read2252=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2253=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2254=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2255=== CONT TestPush_CompleteCommitsEveryRoot22562026/10/01 09:15:29 OK 20251218171726_add_pins.sql (29.43ms)22572026/10/01 09:15:29 OK 20241026095416_initial_model.sql (83.9ms)22582026/10/01 09:15:29 OK 20251210153512_drop_unused_gin_index.sql (669.42µs)22592026/10/01 09:15:29 OK 20260628120000_add_object_size_and_stats.sql (23.93ms)22602026/10/01 09:15:29 OK 20251218171726_add_pins.sql (12.73ms)22612026/10/01 09:15:29 OK 20260905000000_add_claims.sql (22.44ms)22622026/10/01 09:15:29 OK 20260628120000_add_object_size_and_stats.sql (16.49ms)22632026/10/01 09:15:29 OK 20260920000000_drop_claims.sql (12.74ms)22642026-10-01 09:15:29.898 UTC [14212] ERROR: relation "goose_db_version" does not exist at character 3622652026-10-01 09:15:29.898 UTC [14212] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22662026/10/01 09:15:29 OK 20260905000000_add_claims.sql (18.56ms)22672026/10/01 09:15:29 OK 20260923120000_add_pushes.sql (14.13ms)22682026/10/01 09:15:29 goose: successfully migrated database to version: 2026092312000022692026/10/01 09:15:29 OK 1_commit_pending_closure.sql (3.03ms)22702026/10/01 09:15:29 OK 2_object_stats_trigger.sql (380.83µs)22712026/10/01 09:15:29 OK 3_commit_push.sql (302.25µs)22722026/10/01 09:15:29 goose: up to current file version: 322732026/10/01 09:15:29 OK 20260920000000_drop_claims.sql (17.78ms)22742026/10/01 09:15:29 OK 20260923120000_add_pushes.sql (13.97ms)22752026/10/01 09:15:29 goose: successfully migrated database to version: 2026092312000022762026/10/01 09:15:29 OK 1_commit_pending_closure.sql (1.7ms)22772026/10/01 09:15:29 OK 2_object_stats_trigger.sql (331.29µs)22782026/10/01 09:15:29 OK 3_commit_push.sql (291.42µs)22792026/10/01 09:15:29 goose: up to current file version: 32280--- PASS: TestService_ReadScope_PublicByDefault (1.42s)2281=== CONT TestReadRedirectKeepsNarinfoProxied22822026/10/01 09:15:30 OK 20241026095416_initial_model.sql (118.11ms)22832026/10/01 09:15:30 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)22842026/10/01 09:15:30 OK 20251218171726_add_pins.sql (20.49ms)22852026/10/01 09:15:30 OK 20260628120000_add_object_size_and_stats.sql (10ms)22862026-10-01 09:15:30.108 UTC [14215] ERROR: relation "goose_db_version" does not exist at character 3622872026-10-01 09:15:30.108 UTC [14215] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22882026/10/01 09:15:30 OK 20260905000000_add_claims.sql (25.41ms)22892026/10/01 09:15:30 OK 20260920000000_drop_claims.sql (8.98ms)22902026/10/01 09:15:30 OK 20260923120000_add_pushes.sql (17.38ms)22912026/10/01 09:15:30 goose: successfully migrated database to version: 2026092312000022922026/10/01 09:15:30 OK 1_commit_pending_closure.sql (2.72ms)22932026/10/01 09:15:30 OK 2_object_stats_trigger.sql (510.67µs)22942026/10/01 09:15:30 OK 3_commit_push.sql (362.79µs)22952026/10/01 09:15:30 goose: up to current file version: 322962026/10/01 09:15:30 INFO Received uploads request method=POST path=/api/pending_closures22972026/10/01 09:15:30 OK 20241026095416_initial_model.sql (160.87ms)22982026/10/01 09:15:30 OK 20251210153512_drop_unused_gin_index.sql (15.83ms)22992026/10/01 09:15:30 OK 20251218171726_add_pins.sql (32.19ms)23002026/10/01 09:15:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=023012026/10/01 09:15:30 OK 20260628120000_add_object_size_and_stats.sql (14.09ms)2302=== NAME TestPinProtectsFromGC2303 client_integration_test.go:794: Pin successfully protected closure from garbage collection23042026/10/01 09:15:30 INFO Aborted multipart uploads count=023052026/10/01 09:15:30 WARN Force mode enabled - objects will be deleted immediately without grace period23062026/10/01 09:15:30 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."23072026/10/01 09:15:30 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2308--- PASS: TestFailedS3DeleteKeepsTombstone (1.64s)2309=== CONT TestReadRedirectUsesPublicS3URL23102026/10/01 09:15:30 OK 20260905000000_add_claims.sql (43.43ms)2311--- PASS: TestPinProtectsFromGC (4.42s)2312=== CONT TestClientWithDependencies23132026/10/01 09:15:30 OK 20260920000000_drop_claims.sql (31.98ms)23142026/10/01 09:15:30 INFO Received uploads request method=POST path=/api/pending_closures23152026/10/01 09:15:30 OK 20260923120000_add_pushes.sql (6.46ms)23162026/10/01 09:15:30 goose: successfully migrated database to version: 2026092312000023172026/10/01 09:15:30 OK 1_commit_pending_closure.sql (1.82ms)23182026/10/01 09:15:30 OK 2_object_stats_trigger.sql (298.71µs)23192026/10/01 09:15:30 OK 3_commit_push.sql (254.88µs)23202026/10/01 09:15:30 goose: up to current file version: 323212026/10/01 09:15:30 INFO Received uploads request method=POST path=/api/pending_closures23222026-10-01 09:15:30.629 UTC [14221] ERROR: relation "goose_db_version" does not exist at character 3623232026-10-01 09:15:30.629 UTC [14221] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23242026/10/01 09:15:30 INFO Received uploads request method=POST path=/api/pending_closures23252026/10/01 09:15:30 OK 20241026095416_initial_model.sql (153.87ms)23262026/10/01 09:15:30 OK 20251210153512_drop_unused_gin_index.sql (19.92ms)23272026/10/01 09:15:30 OK 20251218171726_add_pins.sql (48.87ms)23282026/10/01 09:15:30 OK 20260628120000_add_object_size_and_stats.sql (45.93ms)23292026/10/01 09:15:31 OK 20260905000000_add_claims.sql (42.5ms)23302026/10/01 09:15:31 INFO Received push request method=POST path=/api/pushes23312026/10/01 09:15:31 OK 20260920000000_drop_claims.sql (43.55ms)23322026/10/01 09:15:31 OK 20260923120000_add_pushes.sql (40.67ms)23332026/10/01 09:15:31 goose: successfully migrated database to version: 2026092312000023342026/10/01 09:15:31 OK 1_commit_pending_closure.sql (3.93ms)23352026/10/01 09:15:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23362026/10/01 09:15:31 OK 2_object_stats_trigger.sql (1.54ms)23372026/10/01 09:15:31 OK 3_commit_push.sql (1.42ms)23382026/10/01 09:15:31 goose: up to current file version: 32339--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.98s)2340=== CONT TestReadProxyRangeRequest23412026-10-01 09:15:31.235 UTC [14225] ERROR: relation "goose_db_version" does not exist at character 3623422026-10-01 09:15:31.235 UTC [14225] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23432026-10-01 09:15:31.338 UTC [14227] ERROR: relation "goose_db_version" does not exist at character 3623442026-10-01 09:15:31.338 UTC [14227] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23452026/10/01 09:15:31 INFO Received push request method=POST path=/api/pushes23462026/10/01 09:15:31 OK 20241026095416_initial_model.sql (168.69ms)23472026/10/01 09:15:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23482026/10/01 09:15:31 INFO Signed narinfos id=1 count=12349--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.02s)2350=== CONT TestCompletedNarNotReofferedAcrossClosures23512026/10/01 09:15:31 OK 20251210153512_drop_unused_gin_index.sql (5.96ms)23522026/10/01 09:15:31 OK 20251218171726_add_pins.sql (18.89ms)23532026-10-01 09:15:31.472 UTC [14228] ERROR: relation "goose_db_version" does not exist at character 3623542026-10-01 09:15:31.472 UTC [14228] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23552026/10/01 09:15:31 OK 20260628120000_add_object_size_and_stats.sql (15.72ms)23562026/10/01 09:15:31 OK 20260905000000_add_claims.sql (4.95ms)23572026/10/01 09:15:31 OK 20241026095416_initial_model.sql (73.32ms)23582026/10/01 09:15:31 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)23592026/10/01 09:15:31 OK 20260920000000_drop_claims.sql (1.85ms)23602026/10/01 09:15:31 OK 20260923120000_add_pushes.sql (1.44ms)23612026/10/01 09:15:31 goose: successfully migrated database to version: 2026092312000023622026/10/01 09:15:31 OK 20251218171726_add_pins.sql (2.7ms)23632026/10/01 09:15:31 OK 1_commit_pending_closure.sql (1.83ms)23642026-10-01 09:15:31.498 UTC [14231] ERROR: relation "goose_db_version" does not exist at character 3623652026-10-01 09:15:31.498 UTC [14231] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23662026/10/01 09:15:31 OK 2_object_stats_trigger.sql (584.25µs)23672026/10/01 09:15:31 OK 3_commit_push.sql (567.75µs)23682026/10/01 09:15:31 goose: up to current file version: 323692026/10/01 09:15:31 OK 20260628120000_add_object_size_and_stats.sql (4.13ms)23702026/10/01 09:15:31 OK 20241026095416_initial_model.sql (12.53ms)23712026/10/01 09:15:31 OK 20251210153512_drop_unused_gin_index.sql (12.08ms)23722026/10/01 09:15:31 OK 20251218171726_add_pins.sql (28.1ms)23732026/10/01 09:15:31 OK 20260905000000_add_claims.sql (44.72ms)23742026/10/01 09:15:31 OK 20260628120000_add_object_size_and_stats.sql (23.36ms)23752026/10/01 09:15:31 OK 20260920000000_drop_claims.sql (28.11ms)23762026/10/01 09:15:31 OK 20260923120000_add_pushes.sql (2.27ms)23772026/10/01 09:15:31 goose: successfully migrated database to version: 2026092312000023782026/10/01 09:15:31 OK 1_commit_pending_closure.sql (1.7ms)23792026/10/01 09:15:31 OK 2_object_stats_trigger.sql (372.17µs)23802026/10/01 09:15:31 OK 3_commit_push.sql (335.33µs)23812026/10/01 09:15:31 goose: up to current file version: 323822026/10/01 09:15:31 OK 20260905000000_add_claims.sql (19.69ms)23832026/10/01 09:15:31 OK 20260920000000_drop_claims.sql (7.45ms)23842026/10/01 09:15:31 OK 20260923120000_add_pushes.sql (4.73ms)23852026/10/01 09:15:31 goose: successfully migrated database to version: 2026092312000023862026/10/01 09:15:31 OK 1_commit_pending_closure.sql (1.41ms)23872026/10/01 09:15:31 OK 2_object_stats_trigger.sql (321.38µs)23882026/10/01 09:15:31 OK 3_commit_push.sql (245.13µs)23892026/10/01 09:15:31 goose: up to current file version: 323902026/10/01 09:15:31 OK 20241026095416_initial_model.sql (107.62ms)23912026/10/01 09:15:31 OK 20251210153512_drop_unused_gin_index.sql (5.32ms)23922026/10/01 09:15:31 OK 20251218171726_add_pins.sql (22.67ms)23932026/10/01 09:15:31 OK 20260628120000_add_object_size_and_stats.sql (39.04ms)2394=== RUN TestPush_RejectsBadRequests/no_roots2395=== PAUSE TestPush_RejectsBadRequests/no_roots2396=== RUN TestPush_RejectsBadRequests/no_objects2397=== PAUSE TestPush_RejectsBadRequests/no_objects2398=== RUN TestPush_RejectsBadRequests/bad_root2399=== PAUSE TestPush_RejectsBadRequests/bad_root2400=== RUN TestPush_RejectsBadRequests/root_not_in_objects2401=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2402=== CONT TestPresignedUploadRegisteredBeforeCommit24032026/10/01 09:15:31 OK 20260905000000_add_claims.sql (28.87ms)24042026/10/01 09:15:31 OK 20260920000000_drop_claims.sql (47.45ms)24052026/10/01 09:15:31 OK 20260923120000_add_pushes.sql (13.45ms)24062026/10/01 09:15:31 goose: successfully migrated database to version: 2026092312000024072026/10/01 09:15:31 OK 1_commit_pending_closure.sql (2.78ms)24082026/10/01 09:15:31 OK 2_object_stats_trigger.sql (647.96µs)24092026/10/01 09:15:31 OK 3_commit_push.sql (373.29µs)24102026/10/01 09:15:31 goose: up to current file version: 324112026/10/01 09:15:32 INFO Received push request method=POST path=/api/pushes24122026/10/01 09:15:32 INFO Received complete push request method=POST path=/api/pushes/1/complete24132026/10/01 09:15:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24142026/10/01 09:15:32 INFO Received push request method=POST path=/api/pushes24152026/10/01 09:15:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZjdhYWUyZDItNWQ0Yi00NWJkLThjZDQtNDNlYWJmNmM2OGI2LmQxYmIwMzViLWIzZTQtNDdmNy05ZmQ3LWE5ZGY3ODVhZmE2NngxNzkwODQ2MTMwNDc0OTkxMDAw parts=122416--- PASS: TestRedundantMultipartUpload (3.38s)2417=== CONT TestReadRedirectNar24182026-10-01 09:15:32.215 UTC [14235] ERROR: relation "goose_db_version" does not exist at character 3624192026-10-01 09:15:32.215 UTC [14235] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24202026-10-01 09:15:32.215 UTC [14236] ERROR: relation "goose_db_version" does not exist at character 3624212026-10-01 09:15:32.215 UTC [14236] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24222026/10/01 09:15:32 INFO Aborted multipart uploads count=024232026/10/01 09:15:32 WARN Force mode enabled - objects will be deleted immediately without grace period24242026/10/01 09:15:32 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=024252026/10/01 09:15:32 INFO Vacuumed table table=pending_closures24262026/10/01 09:15:32 INFO Vacuumed table table=pending_objects24272026/10/01 09:15:32 INFO Vacuumed table table=multipart_uploads24282026/10/01 09:15:32 INFO Received push request method=POST path=/api/pushes24292026/10/01 09:15:32 INFO Vacuumed table table=closures24302026/10/01 09:15:32 INFO Vacuumed table table=objects24312026/10/01 09:15:32 INFO Received complete push request method=POST path=/api/pushes/2/complete2432--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.66s)2433=== CONT TestReadProxyDisabled24342026/10/01 09:15:32 INFO Received complete push request method=POST path=/api/pushes/1/complete2435--- PASS: TestPush_CompleteCommitsEveryRoot (2.62s)2436=== CONT TestCompleteMultipartUpload_ErrorButObjectExists24372026/10/01 09:15:32 OK 20241026095416_initial_model.sql (154.71ms)24382026/10/01 09:15:32 OK 20241026095416_initial_model.sql (155.59ms)24392026/10/01 09:15:32 OK 20251210153512_drop_unused_gin_index.sql (968.71µs)24402026/10/01 09:15:32 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)24412026/10/01 09:15:32 OK 20251218171726_add_pins.sql (12.88ms)24422026/10/01 09:15:32 OK 20251218171726_add_pins.sql (11.09ms)24432026/10/01 09:15:32 OK 20260628120000_add_object_size_and_stats.sql (37.27ms)24442026/10/01 09:15:32 OK 20260628120000_add_object_size_and_stats.sql (37.45ms)24452026/10/01 09:15:32 OK 20260905000000_add_claims.sql (52.96ms)24462026/10/01 09:15:32 OK 20260905000000_add_claims.sql (60.19ms)24472026/10/01 09:15:32 OK 20260920000000_drop_claims.sql (23.83ms)24482026/10/01 09:15:32 OK 20260920000000_drop_claims.sql (16.57ms)24492026-10-01 09:15:32.573 UTC [14245] ERROR: relation "goose_db_version" does not exist at character 3624502026-10-01 09:15:32.573 UTC [14245] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2451--- PASS: TestReadRedirectKeepsNarinfoProxied (2.58s)2452=== CONT TestService_Rustfstest24532026/10/01 09:15:32 OK 20260923120000_add_pushes.sql (18.27ms)24542026/10/01 09:15:32 goose: successfully migrated database to version: 2026092312000024552026/10/01 09:15:32 OK 20260923120000_add_pushes.sql (19.06ms)24562026/10/01 09:15:32 goose: successfully migrated database to version: 2026092312000024572026/10/01 09:15:32 OK 1_commit_pending_closure.sql (2.79ms)24582026/10/01 09:15:32 OK 1_commit_pending_closure.sql (2.45ms)24592026/10/01 09:15:32 OK 2_object_stats_trigger.sql (421.5µs)24602026/10/01 09:15:32 OK 2_object_stats_trigger.sql (576.33µs)24612026/10/01 09:15:32 OK 3_commit_push.sql (577.42µs)24622026/10/01 09:15:32 goose: up to current file version: 324632026/10/01 09:15:32 OK 3_commit_push.sql (378.79µs)24642026/10/01 09:15:32 goose: up to current file version: 324652026/10/01 09:15:32 OK 20241026095416_initial_model.sql (68.53ms)24662026/10/01 09:15:32 OK 20251210153512_drop_unused_gin_index.sql (7.88ms)24672026/10/01 09:15:32 OK 20251218171726_add_pins.sql (16.34ms)24682026/10/01 09:15:32 OK 20260628120000_add_object_size_and_stats.sql (33.68ms)24692026/10/01 09:15:32 OK 20260905000000_add_claims.sql (46.65ms)24702026/10/01 09:15:32 OK 20260920000000_drop_claims.sql (37.91ms)2471--- PASS: TestReadRedirectUsesPublicS3URL (2.44s)2472=== CONT TestClientMultipleUploads24732026-10-01 09:15:32.835 UTC [14248] ERROR: relation "goose_db_version" does not exist at character 3624742026-10-01 09:15:32.835 UTC [14248] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24752026/10/01 09:15:32 OK 20260923120000_add_pushes.sql (18.71ms)24762026/10/01 09:15:32 goose: successfully migrated database to version: 2026092312000024772026/10/01 09:15:32 OK 1_commit_pending_closure.sql (2.7ms)24782026/10/01 09:15:32 OK 2_object_stats_trigger.sql (757.38µs)24792026/10/01 09:15:32 OK 3_commit_push.sql (480.29µs)24802026/10/01 09:15:32 goose: up to current file version: 324812026/10/01 09:15:32 OK 20241026095416_initial_model.sql (66.66ms)24822026/10/01 09:15:32 OK 20251210153512_drop_unused_gin_index.sql (9.77ms)24832026/10/01 09:15:32 OK 20251218171726_add_pins.sql (20.36ms)24842026/10/01 09:15:33 OK 20260628120000_add_object_size_and_stats.sql (27.14ms)24852026/10/01 09:15:33 OK 20260905000000_add_claims.sql (46.52ms)24862026/10/01 09:15:33 OK 20260920000000_drop_claims.sql (28.05ms)24872026/10/01 09:15:33 OK 20260923120000_add_pushes.sql (22.79ms)24882026/10/01 09:15:33 goose: successfully migrated database to version: 2026092312000024892026/10/01 09:15:33 OK 1_commit_pending_closure.sql (1.7ms)24902026/10/01 09:15:33 OK 2_object_stats_trigger.sql (311.58µs)24912026/10/01 09:15:33 OK 3_commit_push.sql (250.67µs)24922026/10/01 09:15:33 goose: up to current file version: 324932026-10-01 09:15:33.145 UTC [14253] ERROR: relation "goose_db_version" does not exist at character 3624942026-10-01 09:15:33.145 UTC [14253] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2495--- PASS: TestReadProxyRangeRequest (2.12s)2496=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure24972026/10/01 09:15:33 INFO Received uploads request method=POST path=/24982026/10/01 09:15:33 OK 20241026095416_initial_model.sql (104.09ms)24992026/10/01 09:15:33 OK 20251210153512_drop_unused_gin_index.sql (7.38ms)25002026/10/01 09:15:33 OK 20251218171726_add_pins.sql (20.87ms)2501=== NAME TestClientWithDependencies2502 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-13789-2688134661/TestClientWithDependencies1993364907/001/store/p0hjmd7hq0nl8znqi8gpqshqzp7fy0xk-test-script25032026/10/01 09:15:33 OK 20260628120000_add_object_size_and_stats.sql (18.67ms)25042026/10/01 09:15:33 OK 20260905000000_add_claims.sql (11.99ms)25052026-10-01 09:15:33.379 UTC [14258] ERROR: relation "goose_db_version" does not exist at character 3625062026-10-01 09:15:33.379 UTC [14258] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25072026/10/01 09:15:33 OK 20260920000000_drop_claims.sql (11.98ms)2508 client_integration_test.go:615: Found 1 dependencies (including self)25092026/10/01 09:15:33 OK 20260923120000_add_pushes.sql (8.88ms)25102026/10/01 09:15:33 goose: successfully migrated database to version: 2026092312000025112026/10/01 09:15:33 OK 1_commit_pending_closure.sql (1.1ms)25122026/10/01 09:15:33 OK 2_object_stats_trigger.sql (298.08µs)25132026/10/01 09:15:33 OK 3_commit_push.sql (223.79µs)25142026/10/01 09:15:33 goose: up to current file version: 325152026/10/01 09:15:33 INFO Received uploads request method=POST path=/api/pending_closures25162026/10/01 09:15:33 OK 20241026095416_initial_model.sql (53.58ms)25172026/10/01 09:15:33 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)25182026/10/01 09:15:33 INFO Received push request method=POST path=/api/pushes25192026/10/01 09:15:33 OK 20251218171726_add_pins.sql (44.02ms)25202026-10-01 09:15:33.500 UTC [14263] ERROR: relation "goose_db_version" does not exist at character 3625212026-10-01 09:15:33.500 UTC [14263] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25222026-10-01 09:15:33.501 UTC [14264] ERROR: relation "goose_db_version" does not exist at character 3625232026-10-01 09:15:33.501 UTC [14264] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25242026/10/01 09:15:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25252026/10/01 09:15:33 INFO Uploading p0hjmd7hq0nl8znqi8gpqshqzp7fy0xk-test-script (136B)25262026/10/01 09:15:33 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"25272026/10/01 09:15:33 WARN Failed to register uploaded object key=p0hjmd7hq0nl8znqi8gpqshqzp7fy0xk.ls error="server returned 404: 404 page not found\n"25282026/10/01 09:15:33 OK 20260628120000_add_object_size_and_stats.sql (10.82ms)2529=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25302026/10/01 09:15:33 INFO Received request for more parts method=POST path=/25312026/10/01 09:15:33 WARN Failed to register uploaded object key=log/62akgr6qhp3jh234i68ai6h83kp1gss8-test-script.drv error="server returned 404: 404 page not found\n"25322026/10/01 09:15:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25332026/10/01 09:15:33 INFO Signed narinfos id=1 count=125342026/10/01 09:15:33 INFO Uploading 1 narinfos2535=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25362026/10/01 09:15:33 INFO Received complete multipart upload request method=POST path=/25372026/10/01 09:15:33 INFO Received complete push request method=POST path=/api/pushes/1/complete25382026/10/01 09:15:33 WARN Failed to register uploaded object key=p0hjmd7hq0nl8znqi8gpqshqzp7fy0xk.narinfo error="server returned 404: 404 page not found\n"25392026/10/01 09:15:33 INFO Upload complete. (143ms)2540=== NAME TestClientWithDependencies2541 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-13789-2688134661/TestClientWithDependencies1993364907/001/store) requires matching store prefix2542=== CONT TestServerTLSConfig/no_client_CA2543=== CONT TestServerTLSConfig/not_a_PEM_file2544--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2545 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)2546 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2547 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)25482026/10/01 09:15:33 OK 20260905000000_add_claims.sql (69.17ms)2549=== CONT TestServerTLSConfig/missing_CA_file2550--- PASS: TestServerTLSConfig (0.00s)2551 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2552 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2553 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2554=== CONT TestIsValidCachePath/invalid_char_e2555=== CONT TestIsValidCachePath/narinfo2556=== CONT TestIsValidCachePath/traversal_in_middle2557=== CONT TestIsValidCachePath/nar_uncompressed2558=== CONT TestIsValidCachePath/nar_bz22559=== CONT TestIsValidCachePath/nar_xz2560=== CONT TestIsValidCachePath/nar_zst2561=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2562=== CONT TestIsValidCachePath/nix-cache-info2563=== CONT TestIsValidCachePath/traversal_parent2564=== CONT TestIsValidCachePath/index.html2565=== CONT TestIsValidCachePath/realisation2566=== CONT TestIsValidCachePath/leading_slash2567=== CONT TestIsValidCachePath/short_hash2568=== CONT TestIsValidCachePath/wrong_extension2569=== CONT TestIsValidCachePath/log2570=== CONT TestIsValidCachePath/random_path2571=== CONT TestIsValidCachePath/empty2572=== CONT TestIsValidCachePath/invalid_char_u2573=== CONT TestIsValidCachePath/ls2574--- PASS: TestIsValidCachePath (0.00s)2575 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2576 --- PASS: TestIsValidCachePath/narinfo (0.00s)2577 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2578 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2579 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2580 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2581 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2582 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2583 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2584 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2585 --- PASS: TestIsValidCachePath/index.html (0.00s)2586 --- PASS: TestIsValidCachePath/realisation (0.00s)2587 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2588 --- PASS: TestIsValidCachePath/short_hash (0.00s)2589 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2590 --- PASS: TestIsValidCachePath/log (0.00s)2591 --- PASS: TestIsValidCachePath/random_path (0.00s)2592 --- PASS: TestIsValidCachePath/empty (0.00s)2593 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2594 --- PASS: TestIsValidCachePath/ls (0.00s)2595=== CONT TestParseSingleRange/none2596=== CONT TestParseSingleRange/open-ended2597=== CONT TestParseSingleRange/start_far_past_EOF2598=== CONT TestParseSingleRange/start_past_EOF2599=== CONT TestParseSingleRange/single_byte2600=== CONT TestParseSingleRange/suffix_exceeds_size2601=== CONT TestParseSingleRange/suffix2602=== CONT TestParseSingleRange/end_clamped_to_size2603=== CONT TestParseSingleRange/malformed_both_empty2604=== CONT TestParseSingleRange/closed2605=== CONT TestParseSingleRange/malformed_end_before_start2606=== CONT TestParseSingleRange/multi-range_ignored2607=== CONT TestParseSingleRange/malformed_no_dash2608=== CONT TestParseSingleRange/unknown_unit2609--- PASS: TestParseSingleRange (0.00s)2610 --- PASS: TestParseSingleRange/none (0.00s)2611 --- PASS: TestParseSingleRange/open-ended (0.00s)2612 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2613 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2614 --- PASS: TestParseSingleRange/single_byte (0.00s)2615 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2616 --- PASS: TestParseSingleRange/suffix (0.00s)2617 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2618 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2619 --- PASS: TestParseSingleRange/closed (0.00s)2620 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2621 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2622 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2623 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2624=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows26252026/10/01 09:15:33 OK 20260920000000_drop_claims.sql (33.47ms)26262026/10/01 09:15:33 OK 20260923120000_add_pushes.sql (15.39ms)26272026/10/01 09:15:33 goose: successfully migrated database to version: 2026092312000026282026/10/01 09:15:33 OK 1_commit_pending_closure.sql (1.36ms)26292026/10/01 09:15:33 OK 2_object_stats_trigger.sql (645µs)26302026/10/01 09:15:33 OK 3_commit_push.sql (197.13µs)26312026/10/01 09:15:33 goose: up to current file version: 32632--- PASS: TestClientWithDependencies (3.21s)2633=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check26342026/10/01 09:15:33 OK 20241026095416_initial_model.sql (159.86ms)26352026/10/01 09:15:33 OK 20241026095416_initial_model.sql (159.37ms)26362026/10/01 09:15:33 OK 20251210153512_drop_unused_gin_index.sql (6.24ms)26372026/10/01 09:15:33 OK 20251210153512_drop_unused_gin_index.sql (10.61ms)26382026/10/01 09:15:33 INFO Received uploads request method=POST path=/api/pending_closures26392026/10/01 09:15:33 OK 20251218171726_add_pins.sql (35.41ms)26402026/10/01 09:15:33 OK 20251218171726_add_pins.sql (25.18ms)26412026/10/01 09:15:33 OK 20260628120000_add_object_size_and_stats.sql (36.64ms)26422026/10/01 09:15:33 OK 20260628120000_add_object_size_and_stats.sql (38.2ms)26432026/10/01 09:15:33 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst26442026/10/01 09:15:33 INFO Received uploads request method=POST path=/api/pending_closures2645--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.07s)2646=== CONT TestResolveDBConnectionString/flag_wins2647=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2648=== CONT TestResolveDBConnectionString/nothing_configured2649=== CONT TestResolveDBConnectionString/missing_file_is_an_error2650=== CONT TestResolveDBConnectionString/file_when_flag_empty2651=== CONT TestClientErrorHandling/InvalidStorePath2652--- PASS: TestResolveDBConnectionString (0.03s)2653 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2654 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2655 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2656 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2657 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)26582026/10/01 09:15:33 OK 20260905000000_add_claims.sql (95.16ms)26592026/10/01 09:15:33 OK 20260905000000_add_claims.sql (101.31ms)26602026-10-01 09:15:33.876 UTC [14270] ERROR: relation "goose_db_version" does not exist at character 3626612026-10-01 09:15:33.876 UTC [14270] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26622026/10/01 09:15:33 OK 20260920000000_drop_claims.sql (10.05ms)26632026/10/01 09:15:33 OK 20260920000000_drop_claims.sql (3.15ms)26642026/10/01 09:15:33 OK 20260923120000_add_pushes.sql (3.67ms)26652026/10/01 09:15:33 goose: successfully migrated database to version: 2026092312000026662026/10/01 09:15:33 OK 1_commit_pending_closure.sql (1.58ms)26672026/10/01 09:15:33 OK 2_object_stats_trigger.sql (322.63µs)26682026/10/01 09:15:33 OK 3_commit_push.sql (297.54µs)26692026/10/01 09:15:33 goose: up to current file version: 326702026/10/01 09:15:33 OK 20260923120000_add_pushes.sql (7.54ms)26712026/10/01 09:15:33 goose: successfully migrated database to version: 2026092312000026722026/10/01 09:15:33 OK 1_commit_pending_closure.sql (2.05ms)26732026/10/01 09:15:33 OK 2_object_stats_trigger.sql (363.42µs)26742026/10/01 09:15:33 OK 3_commit_push.sql (261.63µs)26752026/10/01 09:15:33 goose: up to current file version: 32676--- PASS: TestReadRedirectNar (1.86s)2677=== CONT TestClientErrorHandling/ServerNotAvailable26782026/10/01 09:15:34 OK 20241026095416_initial_model.sql (177.07ms)26792026/10/01 09:15:34 OK 20251210153512_drop_unused_gin_index.sql (8.31ms)26802026/10/01 09:15:34 OK 20251218171726_add_pins.sql (27.69ms)26812026-10-01 09:15:34.122 UTC [14274] ERROR: relation "goose_db_version" does not exist at character 3626822026-10-01 09:15:34.122 UTC [14274] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26832026/10/01 09:15:34 OK 20260628120000_add_object_size_and_stats.sql (12.4ms)26842026/10/01 09:15:34 OK 20260905000000_add_claims.sql (47.5ms)26852026/10/01 09:15:34 OK 20260920000000_drop_claims.sql (41.46ms)26862026/10/01 09:15:34 OK 20260923120000_add_pushes.sql (8.17ms)26872026/10/01 09:15:34 goose: successfully migrated database to version: 2026092312000026882026/10/01 09:15:34 OK 1_commit_pending_closure.sql (1.62ms)26892026/10/01 09:15:34 OK 2_object_stats_trigger.sql (423.38µs)26902026/10/01 09:15:34 OK 3_commit_push.sql (304.88µs)26912026/10/01 09:15:34 goose: up to current file version: 326922026/10/01 09:15:34 INFO Received uploads request method=POST path=/api/pending_closures26932026/10/01 09:15:34 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/present26942026/10/01 09:15:34 OK 20241026095416_initial_model.sql (180.96ms)26952026/10/01 09:15:34 OK 20251210153512_drop_unused_gin_index.sql (986.92µs)26962026/10/01 09:15:34 OK 20251218171726_add_pins.sql (22.51ms)26972026/10/01 09:15:34 OK 20260628120000_add_object_size_and_stats.sql (20.22ms)26982026/10/01 09:15:34 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=198.809871ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26992026/10/01 09:15:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete27002026/10/01 09:15:34 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjdhYWUyZDItNWQ0Yi00NWJkLThjZDQtNDNlYWJmNmM2OGI2LmJlZWUyMjMzLTVmYWEtNGE0MS05NzkxLTNhY2QwYzY4ZTlmZngxNzkwODQ2MTM0Mjk0MzgwMDAw27012026/10/01 09:15:34 OK 20260905000000_add_claims.sql (145.2ms)27022026/10/01 09:15:34 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjdhYWUyZDItNWQ0Yi00NWJkLThjZDQtNDNlYWJmNmM2OGI2LmJlZWUyMjMzLTVmYWEtNGE0MS05NzkxLTNhY2QwYzY4ZTlmZngxNzkwODQ2MTM0Mjk0MzgwMDAw parts=12703--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.09s)2704=== CONT TestClientErrorHandling/InvalidAuthToken2705--- PASS: TestReadProxyDisabled (2.18s)2706=== CONT TestCacheConfigHandler/full_config,_no_issuer2707=== CONT TestCacheConfigHandler/no_signing_keys2708=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2709=== CONT TestCacheConfigHandler/no_cache_url_configured2710--- PASS: TestCacheConfigHandler (0.00s)2711 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2712 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2713 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2714 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2715=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2716=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected27172026/10/01 09:15:34 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]2718=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2719=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected27202026/10/01 09:15:34 WARN Authentication failed token_preview=eyJhbGciOi...kycoEe5mUg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2721=== CONT TestIsValidUploadKey/narinfo2722=== CONT TestIsValidUploadKey/realisation_plus_in_output2723=== CONT TestIsValidUploadKey/unknown_type2724=== CONT TestIsValidUploadKey/empty_key2725=== CONT TestIsValidUploadKey/absolute2726=== CONT TestIsValidUploadKey/traversal_nar2727=== CONT TestIsValidUploadKey/traversal2728=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2729=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2730=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2731=== CONT TestIsValidUploadKey/index.html2732=== CONT TestProxyWriteTimeout/narinfo2733=== CONT TestIsValidUploadKey/nix-cache-info2734=== CONT TestIsValidUploadKey/realisation2735=== CONT TestIsValidUploadKey/build_log_equals2736=== CONT TestIsValidUploadKey/nar_xz2737=== CONT TestIsValidUploadKey/nar_zst2738=== CONT TestIsValidUploadKey/nar_plain2739=== CONT TestIsValidUploadKey/build_log_question_mark2740=== CONT TestIsValidUploadKey/build_log2741=== CONT TestIsValidUploadKey/listing2742=== CONT TestIsValidUploadKey/build_log_plus_in_name2743=== CONT TestProxyWriteTimeout/10_GiB_nar2744=== CONT TestProxyWriteTimeout/unknown_size2745=== CONT TestProxyWriteTimeout/1_GiB_nar2746--- PASS: TestProxyWriteTimeout (0.00s)2747 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2748 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2749 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2750 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2751=== CONT TestIsValidUploadKey/build_log_home-manager_file2752--- PASS: TestIsValidUploadKey (0.00s)2753 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2754 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2755 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2756 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2757 --- PASS: TestIsValidUploadKey/absolute (0.00s)2758 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2759 --- PASS: TestIsValidUploadKey/traversal (0.00s)2760 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2761 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2762 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2763 --- PASS: TestIsValidUploadKey/index.html (0.00s)2764 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2765 --- PASS: TestIsValidUploadKey/realisation (0.00s)2766 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2767 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2768 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2769 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2770 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2771 --- PASS: TestIsValidUploadKey/build_log (0.00s)2772 --- PASS: TestIsValidUploadKey/listing (0.00s)2773 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2774 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2775=== CONT TestService_RequireScope_OIDC/builder_may_write2776=== CONT TestService_RequireScope_OIDC/static_token_may_admin2777=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2778=== CONT TestService_RequireScope_OIDC/writer_implies_read2779=== CONT TestService_RequireScope_OIDC/reader_may_read2780--- PASS: TestService_AuthMiddleware_OIDC (1.50s)2781 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2782 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2783 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2784 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2785=== CONT TestService_RequireScope_OIDC/static_token_may_write2786=== CONT TestService_RequireScope_OIDC/ops_may_not_write2787=== CONT TestService_RequireScope_OIDC/reader_may_not_write2788=== CONT TestService_RequireScope_OIDC/ops_may_admin2789=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2790=== CONT TestPush_RejectsBadRequests/no_roots27912026/10/01 09:15:34 INFO Received push request method=POST path=/api/pushes2792=== CONT TestPush_RejectsBadRequests/root_not_in_objects27932026/10/01 09:15:34 INFO Received push request method=POST path=/api/pushes2794=== CONT TestPush_RejectsBadRequests/bad_root27952026/10/01 09:15:34 INFO Received push request method=POST path=/api/pushes2796=== CONT TestPush_RejectsBadRequests/no_objects27972026/10/01 09:15:34 INFO Received push request method=POST path=/api/pushes2798--- PASS: TestPush_RejectsBadRequests (2.15s)2799 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2800 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2801 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2802 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)28032026/10/01 09:15:34 OK 20260920000000_drop_claims.sql (41.67ms)2804--- PASS: TestService_RequireScope_OIDC (1.28s)2805 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2806 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2807 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2808 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2809 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2810 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2811 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2812 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2813 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2814 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)28152026/10/01 09:15:34 OK 20260923120000_add_pushes.sql (25.41ms)28162026/10/01 09:15:34 goose: successfully migrated database to version: 2026092312000028172026/10/01 09:15:34 OK 1_commit_pending_closure.sql (2.17ms)28182026/10/01 09:15:34 OK 2_object_stats_trigger.sql (393.58µs)28192026/10/01 09:15:34 OK 3_commit_push.sql (336.63µs)28202026/10/01 09:15:34 goose: up to current file version: 328212026/10/01 09:15:34 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=439.962538ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2822--- PASS: TestService_Rustfstest (2.17s)28232026/10/01 09:15:34 WARN Rate limiter enabled after throttle name=s3-test rate=528242026/10/01 09:15:34 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2825=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2826 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102827 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002828--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.81s)28292026/10/01 09:15:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete28302026/10/01 09:15:34 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZjdhYWUyZDItNWQ0Yi00NWJkLThjZDQtNDNlYWJmNmM2OGI2LjcxYjEyMjQyLTJjMzgtNDBjMi1hNGI4LTQ1NmIyZGUyNmZkN3gxNzkwODQ2MTMzNDU3MDkwMDAw parts=1228312026/10/01 09:15:34 INFO Received uploads request method=POST path=/api/pending_closures2832--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.53s)28332026/10/01 09:15:35 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=772.456572ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28342026-10-01 09:15:35.122 UTC [14281] ERROR: relation "goose_db_version" does not exist at character 3628352026-10-01 09:15:35.122 UTC [14281] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28362026-10-01 09:15:35.122 UTC [14282] ERROR: relation "goose_db_version" does not exist at character 3628372026-10-01 09:15:35.122 UTC [14282] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28382026-10-01 09:15:35.129 UTC [14283] ERROR: relation "goose_db_version" does not exist at character 3628392026-10-01 09:15:35.129 UTC [14283] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28402026/10/01 09:15:35 OK 20241026095416_initial_model.sql (8.89ms)28412026/10/01 09:15:35 OK 20241026095416_initial_model.sql (9.86ms)28422026/10/01 09:15:35 OK 20251210153512_drop_unused_gin_index.sql (595.04µs)28432026/10/01 09:15:35 OK 20251210153512_drop_unused_gin_index.sql (521.33µs)28442026/10/01 09:15:35 OK 20251218171726_add_pins.sql (1.32ms)28452026/10/01 09:15:35 OK 20251218171726_add_pins.sql (1.41ms)28462026/10/01 09:15:35 OK 20241026095416_initial_model.sql (6.39ms)28472026/10/01 09:15:35 OK 20260628120000_add_object_size_and_stats.sql (1.51ms)28482026/10/01 09:15:35 OK 20251210153512_drop_unused_gin_index.sql (758.13µs)28492026/10/01 09:15:35 OK 20260628120000_add_object_size_and_stats.sql (1.61ms)28502026/10/01 09:15:35 OK 20251218171726_add_pins.sql (1.3ms)28512026/10/01 09:15:35 OK 20260905000000_add_claims.sql (1.6ms)28522026/10/01 09:15:35 OK 20260905000000_add_claims.sql (1.77ms)28532026/10/01 09:15:35 OK 20260920000000_drop_claims.sql (1.21ms)28542026/10/01 09:15:35 OK 20260920000000_drop_claims.sql (1.01ms)28552026/10/01 09:15:35 OK 20260923120000_add_pushes.sql (555.25µs)28562026/10/01 09:15:35 goose: successfully migrated database to version: 2026092312000028572026/10/01 09:15:35 OK 1_commit_pending_closure.sql (1.22ms)28582026/10/01 09:15:35 OK 20260628120000_add_object_size_and_stats.sql (3.68ms)28592026/10/01 09:15:35 OK 20260923120000_add_pushes.sql (1.95ms)28602026/10/01 09:15:35 goose: successfully migrated database to version: 2026092312000028612026/10/01 09:15:35 OK 2_object_stats_trigger.sql (426.33µs)28622026/10/01 09:15:35 OK 3_commit_push.sql (399.13µs)28632026/10/01 09:15:35 goose: up to current file version: 328642026/10/01 09:15:35 OK 1_commit_pending_closure.sql (1.34ms)28652026/10/01 09:15:35 OK 20260905000000_add_claims.sql (1.47ms)28662026/10/01 09:15:35 OK 2_object_stats_trigger.sql (378.33µs)28672026/10/01 09:15:35 OK 3_commit_push.sql (300.63µs)28682026/10/01 09:15:35 goose: up to current file version: 328692026/10/01 09:15:35 OK 20260920000000_drop_claims.sql (1.08ms)28702026/10/01 09:15:35 OK 20260923120000_add_pushes.sql (9.7ms)28712026/10/01 09:15:35 goose: successfully migrated database to version: 2026092312000028722026/10/01 09:15:35 OK 1_commit_pending_closure.sql (1.13ms)28732026/10/01 09:15:35 OK 2_object_stats_trigger.sql (250.21µs)28742026/10/01 09:15:35 OK 3_commit_push.sql (206.96µs)28752026/10/01 09:15:35 goose: up to current file version: 32876=== NAME TestClientMultipleUploads2877 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-13789-2688134661/TestClientMultipleUploads3828563460/001/store/y0fkjq090yjixrgv8mnlxmb7d04xyljj-test-file-0.txt2878 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-13789-2688134661/TestClientMultipleUploads3828563460/001/store/6ql1cpb1vc4463knq1yrzv9wiiv49vj1-test-file-1.txt28792026-10-01 09:15:35.314 UTC [14289] ERROR: relation "goose_db_version" does not exist at character 3628802026-10-01 09:15:35.314 UTC [14289] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28812026/10/01 09:15:35 INFO Received uploads request method=POST path=/api/pending_closures28822026/10/01 09:15:35 INFO Aborted multipart uploads count=028832026/10/01 09:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period2884 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-13789-2688134661/TestClientMultipleUploads3828563460/001/store/85q3yv37gdgqvzpwdsj9j42afip8aam2-test-file-2.txt28852026/10/01 09:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=028862026/10/01 09:15:35 INFO Vacuumed table table=pending_closures28872026/10/01 09:15:35 INFO Vacuumed table table=pending_objects28882026/10/01 09:15:35 INFO Vacuumed table table=multipart_uploads28892026/10/01 09:15:35 INFO Vacuumed table table=closures28902026/10/01 09:15:35 INFO Vacuumed table table=objects28912026/10/01 09:15:35 OK 20241026095416_initial_model.sql (68.37ms)28922026/10/01 09:15:35 OK 20251210153512_drop_unused_gin_index.sql (6.18ms)28932026/10/01 09:15:35 INFO Received push request method=POST path=/api/pushes28942026/10/01 09:15:35 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)28952026/10/01 09:15:35 INFO Uploading y0fkjq090yjixrgv8mnlxmb7d04xyljj-test-file-0.txt (160B)28962026/10/01 09:15:35 INFO Uploading 85q3yv37gdgqvzpwdsj9j42afip8aam2-test-file-2.txt (160B)28972026/10/01 09:15:35 INFO Uploading 6ql1cpb1vc4463knq1yrzv9wiiv49vj1-test-file-1.txt (160B)28982026/10/01 09:15:35 OK 20251218171726_add_pins.sql (20.68ms)28992026/10/01 09:15:35 WARN Failed to register uploaded object key=85q3yv37gdgqvzpwdsj9j42afip8aam2.ls error="server returned 404: 404 page not found\n"29002026/10/01 09:15:35 WARN Failed to register uploaded object key=6ql1cpb1vc4463knq1yrzv9wiiv49vj1.ls error="server returned 404: 404 page not found\n"29012026/10/01 09:15:35 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"29022026/10/01 09:15:35 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"29032026/10/01 09:15:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29042026/10/01 09:15:35 WARN Failed to register uploaded object key=y0fkjq090yjixrgv8mnlxmb7d04xyljj.ls error="server returned 404: 404 page not found\n"29052026/10/01 09:15:35 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"29062026/10/01 09:15:35 INFO Signed narinfos id=1 count=329072026/10/01 09:15:35 INFO Uploading 3 narinfos29082026/10/01 09:15:35 OK 20260628120000_add_object_size_and_stats.sql (16.02ms)29092026/10/01 09:15:35 WARN Failed to register uploaded object key=85q3yv37gdgqvzpwdsj9j42afip8aam2.narinfo error="server returned 404: 404 page not found\n"29102026/10/01 09:15:35 INFO Received complete push request method=POST path=/api/pushes/1/complete29112026/10/01 09:15:35 WARN Failed to register uploaded object key=6ql1cpb1vc4463knq1yrzv9wiiv49vj1.narinfo error="server returned 404: 404 page not found\n"29122026/10/01 09:15:35 WARN Failed to register uploaded object key=y0fkjq090yjixrgv8mnlxmb7d04xyljj.narinfo error="server returned 404: 404 page not found\n"29132026/10/01 09:15:35 INFO Upload complete. (98ms)2914 client_integration_test.go:369: Uploaded 3 paths in 129.9875ms29152026/10/01 09:15:35 OK 20260905000000_add_claims.sql (27.25ms)29162026/10/01 09:15:35 OK 20260920000000_drop_claims.sql (15.46ms)29172026/10/01 09:15:35 OK 20260923120000_add_pushes.sql (4.34ms)29182026/10/01 09:15:35 goose: successfully migrated database to version: 2026092312000029192026/10/01 09:15:35 OK 1_commit_pending_closure.sql (1.08ms)29202026/10/01 09:15:35 OK 2_object_stats_trigger.sql (246.96µs)29212026/10/01 09:15:35 OK 3_commit_push.sql (202.63µs)29222026/10/01 09:15:35 goose: up to current file version: 32923--- PASS: TestClientMultipleUploads (2.67s)29242026/10/01 09:15:35 INFO Received uploads request method=POST path=/api/pending_closures29252026/10/01 09:15:35 INFO Aborted multipart uploads count=029262026/10/01 09:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period29272026/10/01 09:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=029282026/10/01 09:15:35 INFO Vacuumed table table=pending_closures29292026/10/01 09:15:35 INFO Vacuumed table table=pending_objects29302026/10/01 09:15:35 INFO Vacuumed table table=multipart_uploads29312026/10/01 09:15:35 INFO Vacuumed table table=closures29322026/10/01 09:15:35 INFO Vacuumed table table=objects2933--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2934 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (1.82s)2935 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (1.95s)29362026/10/01 09:15:35 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.478822325s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29372026/10/01 09:15:35 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29382026/10/01 09:15:35 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29392026/10/01 09:15:37 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-config29402026/10/01 09:15:37 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.686829ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29412026/10/01 09:15:37 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=433.776916ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29422026/10/01 09:15:38 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=773.879501ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29432026/10/01 09:15:38 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.647013503s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29442026/10/01 09:15:40 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"29452026/10/01 09:15:40 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-config29462026/10/01 09:15:40 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.464592ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29472026/10/01 09:15:40 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=375.130314ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29482026/10/01 09:15:41 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=805.1518ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29492026/10/01 09:15:42 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.585163774s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29502026/10/01 09:15:43 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_closures29512026/10/01 09:15:43 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.570488ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29522026/10/01 09:15:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=422.630149ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29532026/10/01 09:15:44 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=772.240833ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29542026/10/01 09:15:45 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.58816671s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2955--- PASS: TestClientErrorHandling (0.00s)2956 --- PASS: TestClientErrorHandling/InvalidStorePath (1.93s)2957 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.35s)2958 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.69s)2959PASS2960{"timestamp":"2026-10-01T09:15:46.734722Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:62461","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}2961{"timestamp":"2026-10-01T09:15:46.734934Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:62197","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}29622026-10-01 09:15:46.843 UTC [13860] LOG: received smart shutdown request29632026-10-01 09:15:46.844 UTC [13860] LOG: background worker "logical replication launcher" (PID 13872) exited with exit code 129642026-10-01 09:15:46.865 UTC [13866] LOG: shutting down29652026-10-01 09:15:46.865 UTC [13866] LOG: checkpoint starting: shutdown immediate29662026-10-01 09:15:48.035 UTC [13866] LOG: checkpoint complete: wrote 12520 buffers (76.4%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 23 recycled; write=0.675 s, sync=0.461 s, total=1.170 s; sync files=26967, longest=0.001 s, average=0.001 s; distance=379969 kB, estimate=379969 kB; lsn=0/18A9D588, redo lsn=0/18A9D58829672026-10-01 09:15:48.040 UTC [13860] LOG: database system is shut down2968Running OIDC tests...2969=== RUN TestAudienceForIssuer2970=== PAUSE TestAudienceForIssuer2971=== RUN TestGlobMatch2972=== PAUSE TestGlobMatch2973=== RUN TestValidateToken_ValidToken2974=== PAUSE TestValidateToken_ValidToken2975=== RUN TestValidateToken_WrongAudience2976=== PAUSE TestValidateToken_WrongAudience2977=== RUN TestValidateToken_Expired2978=== PAUSE TestValidateToken_Expired2979=== RUN TestValidateToken_BoundClaimsMismatch2980=== PAUSE TestValidateToken_BoundClaimsMismatch2981=== RUN TestValidateToken_BoundSubjectMismatch2982=== PAUSE TestValidateToken_BoundSubjectMismatch2983=== RUN TestValidateToken_MultipleProviders2984=== PAUSE TestValidateToken_MultipleProviders2985=== RUN TestValidateToken_NoMatchingProvider2986=== PAUSE TestValidateToken_NoMatchingProvider2987=== RUN TestValidateToken_KubernetesServiceAccount2988=== PAUSE TestValidateToken_KubernetesServiceAccount2989=== RUN TestNewValidator_KubernetesRequiresCA2990=== PAUSE TestNewValidator_KubernetesRequiresCA2991=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2992=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2993=== RUN TestPins_ReservedForMatchingRule2994=== PAUSE TestPins_ReservedForMatchingRule2995=== RUN TestPins_TopLevelShorthand2996=== PAUSE TestPins_TopLevelShorthand2997=== RUN TestPins_ConfigValidation2998=== PAUSE TestPins_ConfigValidation2999=== RUN TestScopes_LegacyProviderDefaultsToWrite3000=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3001=== RUN TestScopes_Rules3002=== PAUSE TestScopes_Rules3003=== RUN TestScopes_ConfigValidation3004=== PAUSE TestScopes_ConfigValidation3005=== CONT TestScopes_Rules3006=== CONT TestValidateToken_MultipleProviders3007=== CONT TestValidateToken_BoundSubjectMismatch3008=== CONT TestValidateToken_NoMatchingProvider3009=== CONT TestPins_ReservedForMatchingRule3010=== CONT TestScopes_ConfigValidation3011=== CONT TestPins_ConfigValidation3012=== CONT TestScopes_LegacyProviderDefaultsToWrite3013=== CONT TestValidateToken_WrongAudience3014=== CONT TestAudienceForIssuer3015--- PASS: TestAudienceForIssuer (0.00s)3016=== CONT TestNewValidator_KubernetesRequiresCA3017--- PASS: TestScopes_ConfigValidation (0.01s)3018=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3019--- PASS: TestPins_ConfigValidation (0.01s)3020=== CONT TestValidateToken_BoundClaimsMismatch30212026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62566/oidc30222026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62568/oidc3023--- PASS: TestScopes_Rules (0.04s)3024=== CONT TestPins_TopLevelShorthand3025--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)3026=== CONT TestValidateToken_ValidToken30272026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62570/oidc3028--- PASS: TestValidateToken_BoundClaimsMismatch (0.04s)3029=== CONT TestValidateToken_KubernetesServiceAccount30302026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62572/oidc3031--- PASS: TestPins_ReservedForMatchingRule (0.06s)3032=== CONT TestGlobMatch3033=== RUN TestGlobMatch/foo_foo3034=== PAUSE TestGlobMatch/foo_foo3035=== RUN TestGlobMatch/foo_bar3036=== PAUSE TestGlobMatch/foo_bar3037=== RUN TestGlobMatch/*_3038=== PAUSE TestGlobMatch/*_3039=== RUN TestGlobMatch/*_anything3040=== PAUSE TestGlobMatch/*_anything3041=== RUN TestGlobMatch/foo*_foo3042=== PAUSE TestGlobMatch/foo*_foo3043=== RUN TestGlobMatch/foo*_foobar3044=== PAUSE TestGlobMatch/foo*_foobar3045=== RUN TestGlobMatch/foo*_bar3046=== PAUSE TestGlobMatch/foo*_bar3047=== RUN TestGlobMatch/*bar_bar3048=== PAUSE TestGlobMatch/*bar_bar3049=== RUN TestGlobMatch/*bar_foobar3050=== PAUSE TestGlobMatch/*bar_foobar3051=== RUN TestGlobMatch/*bar_foo3052=== PAUSE TestGlobMatch/*bar_foo3053=== RUN TestGlobMatch/foo*bar_foobar3054=== PAUSE TestGlobMatch/foo*bar_foobar3055=== RUN TestGlobMatch/foo*bar_foo123bar3056=== PAUSE TestGlobMatch/foo*bar_foo123bar3057=== RUN TestGlobMatch/foo*bar_foobarbaz3058=== PAUSE TestGlobMatch/foo*bar_foobarbaz3059=== RUN TestGlobMatch/*/*_foo/bar3060=== PAUSE TestGlobMatch/*/*_foo/bar3061=== RUN TestGlobMatch/*/*_foo3062=== PAUSE TestGlobMatch/*/*_foo3063=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3064=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3065=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03066=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03067=== RUN TestGlobMatch/refs/*/main_refs/heads/main3068=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3069=== RUN TestGlobMatch/fo?_foo3070=== PAUSE TestGlobMatch/fo?_foo3071=== RUN TestGlobMatch/fo?_fo3072=== PAUSE TestGlobMatch/fo?_fo3073=== RUN TestGlobMatch/fo?_fooo3074=== PAUSE TestGlobMatch/fo?_fooo3075=== RUN TestGlobMatch/?oo_foo3076=== PAUSE TestGlobMatch/?oo_foo3077=== RUN TestGlobMatch/?oo_boo3078=== PAUSE TestGlobMatch/?oo_boo3079=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3080=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3081=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3082=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3083=== CONT TestValidateToken_Expired30842026/10/01 09:15:49 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12330852026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62576/oidc3086--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.06s)3087=== CONT TestGlobMatch/foo_foo3088=== CONT TestGlobMatch/*/*_foo/bar3089=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3090=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3091=== CONT TestGlobMatch/?oo_boo3092=== CONT TestGlobMatch/?oo_foo3093=== CONT TestGlobMatch/fo?_fooo3094=== CONT TestGlobMatch/fo?_fo3095=== CONT TestGlobMatch/fo?_foo3096=== CONT TestGlobMatch/refs/*/main_refs/heads/main3097=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03098=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3099=== CONT TestGlobMatch/*/*_foo3100=== CONT TestGlobMatch/*bar_bar3101=== CONT TestGlobMatch/foo*bar_foobarbaz3102=== CONT TestGlobMatch/foo*bar_foo123bar3103=== CONT TestGlobMatch/foo*bar_foobar3104=== CONT TestGlobMatch/*bar_foo3105=== CONT TestGlobMatch/*bar_foobar3106=== CONT TestGlobMatch/foo*_foo3107=== CONT TestGlobMatch/foo*_bar3108=== CONT TestGlobMatch/foo*_foobar3109=== CONT TestGlobMatch/*_3110=== CONT TestGlobMatch/*_anything3111=== CONT TestGlobMatch/foo_bar3112--- PASS: TestGlobMatch (0.00s)3113 --- PASS: TestGlobMatch/foo_foo (0.00s)3114 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3115 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3116 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3117 --- PASS: TestGlobMatch/?oo_boo (0.00s)3118 --- PASS: TestGlobMatch/?oo_foo (0.00s)3119 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3120 --- PASS: TestGlobMatch/fo?_fo (0.00s)3121 --- PASS: TestGlobMatch/fo?_foo (0.00s)3122 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3123 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3124 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3125 --- PASS: TestGlobMatch/*/*_foo (0.00s)3126 --- PASS: TestGlobMatch/*bar_bar (0.00s)3127 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3128 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3129 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3130 --- PASS: TestGlobMatch/*bar_foo (0.00s)3131 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3132 --- PASS: TestGlobMatch/foo*_foo (0.00s)3133 --- PASS: TestGlobMatch/foo*_bar (0.00s)3134 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3135 --- PASS: TestGlobMatch/*_ (0.00s)3136 --- PASS: TestGlobMatch/*_anything (0.00s)3137 --- PASS: TestGlobMatch/foo_bar (0.00s)3138--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)31392026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62579/oidc31402026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62582/oidc3141--- PASS: TestValidateToken_Expired (0.03s)3142--- PASS: TestValidateToken_WrongAudience (0.10s)31432026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62584/oidc3144--- PASS: TestPins_TopLevelShorthand (0.08s)31452026/10/01 09:15:49 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:625863146--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)31472026/10/01 09:15:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:62581/oidc3148--- PASS: TestValidateToken_NoMatchingProvider (0.13s)31492026/10/01 09:15:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62591/oidc3150--- PASS: TestValidateToken_ValidToken (0.11s)31512026/10/01 09:15:49 http: TLS handshake error from 127.0.0.1:62594: read tcp 127.0.0.1:62593->127.0.0.1:62594: use of closed network connection3152--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)31532026/10/01 09:15:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:62590/oidc31542026/10/01 09:15:49 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:62595/oidc3155--- PASS: TestValidateToken_MultipleProviders (0.19s)3156PASS3157Running hook tests...3158=== RUN TestSendPathsEmpty3159=== PAUSE TestSendPathsEmpty3160=== RUN TestQueueEnqueueAndFetch3161=== PAUSE TestQueueEnqueueAndFetch3162=== RUN TestQueueDeduplication3163=== PAUSE TestQueueDeduplication3164=== RUN TestQueueRemove3165=== PAUSE TestQueueRemove3166=== RUN TestQueueFetchBatchLimit3167=== PAUSE TestQueueFetchBatchLimit3168=== RUN TestQueueRetryMovesToBack3169=== PAUSE TestQueueRetryMovesToBack3170=== RUN TestQueueFetchRemoveLifecycle3171=== PAUSE TestQueueFetchRemoveLifecycle3172=== RUN TestQueueConcurrentWriters3173=== PAUSE TestQueueConcurrentWriters3174=== RUN TestQueueRemoveLargeClosure3175=== PAUSE TestQueueRemoveLargeClosure3176=== RUN TestServerClientIntegration3177=== PAUSE TestServerClientIntegration3178=== RUN TestServerQueueError3179=== PAUSE TestServerQueueError3180=== RUN TestGetListenerSocketActivation3181 server_test.go:210: === RUN TestGetListenerSocketActivation3182 --- PASS: TestGetListenerSocketActivation (0.00s)3183 PASS3184 3185--- PASS: TestGetListenerSocketActivation (0.01s)3186=== RUN TestDrainIsolatesPoisonPath3187=== PAUSE TestDrainIsolatesPoisonPath3188=== RUN TestRunNotBlockedByPoisonHead3189=== PAUSE TestRunNotBlockedByPoisonHead3190=== RUN TestDrainGivesUpWhenServerDown3191=== PAUSE TestDrainGivesUpWhenServerDown3192=== RUN TestFailedPathPrunedByLaterClosure3193=== PAUSE TestFailedPathPrunedByLaterClosure3194=== RUN TestWorkerUploadsAndRemoves3195=== PAUSE TestWorkerUploadsAndRemoves3196=== RUN TestWorkerSkipsGCdPaths3197=== PAUSE TestWorkerSkipsGCdPaths3198=== RUN TestWorkerPrunesClosureDeps3199=== PAUSE TestWorkerPrunesClosureDeps3200=== RUN TestDrainTimeout3201=== PAUSE TestDrainTimeout3202=== CONT TestSendPathsEmpty3203=== CONT TestServerQueueError3204--- PASS: TestSendPathsEmpty (0.00s)3205=== CONT TestServerClientIntegration3206=== CONT TestWorkerUploadsAndRemoves3207=== CONT TestWorkerPrunesClosureDeps3208=== CONT TestWorkerSkipsGCdPaths3209=== CONT TestDrainGivesUpWhenServerDown3210=== CONT TestFailedPathPrunedByLaterClosure3211=== CONT TestQueueRetryMovesToBack3212=== CONT TestQueueRemoveLargeClosure3213=== CONT TestQueueConcurrentWriters32142026/10/01 09:15:49 ERROR Failed to queue paths error="permission denied" count=13215--- PASS: TestServerClientIntegration (0.00s)3216=== CONT TestQueueFetchRemoveLifecycle3217--- PASS: TestServerQueueError (0.00s)3218=== CONT TestQueueRemove32192026/10/01 09:15:49 INFO Upload queue status pending=232202026/10/01 09:15:49 INFO Upload queue status pending=232212026/10/01 09:15:49 INFO Uploading batch count=132222026/10/01 09:15:49 INFO Uploading batch count=232232026/10/01 09:15:49 INFO Uploading batch count=132242026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=132252026/10/01 09:15:49 INFO Uploading batch count=132262026/10/01 09:15:49 INFO Upload queue status pending=23227--- PASS: TestQueueRemove (0.01s)3228=== CONT TestQueueFetchBatchLimit32292026/10/01 09:15:49 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-13789-2688134661/TestWorkerSkipsGCdPaths3068995014/002/nonexistent32302026/10/01 09:15:49 INFO Uploading batch count=232312026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=232322026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainGivesUpWhenServerDown4224321305/002/a32332026/10/01 09:15:49 INFO Uploading batch count=132342026/10/01 09:15:49 INFO Uploading batch count=132352026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainGivesUpWhenServerDown4224321305/002/b3236--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3237=== CONT TestRunNotBlockedByPoisonHead3238--- PASS: TestQueueRetryMovesToBack (0.01s)3239=== CONT TestQueueDeduplication32402026/10/01 09:15:49 INFO Uploading batch count=232412026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=232422026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainGivesUpWhenServerDown4224321305/002/c32432026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainGivesUpWhenServerDown4224321305/002/d32442026/10/01 09:15:49 INFO Uploading batch count=232452026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=232462026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainGivesUpWhenServerDown4224321305/002/e32472026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainGivesUpWhenServerDown4224321305/002/f32482026/10/01 09:15:49 ERROR Drain finished with paths left in queue remaining=103249--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3250=== CONT TestDrainIsolatesPoisonPath3251--- PASS: TestQueueFetchBatchLimit (0.00s)3252=== CONT TestQueueEnqueueAndFetch32532026/10/01 09:15:49 INFO Upload queue status pending=332542026/10/01 09:15:49 INFO Uploading batch count=132552026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=13256--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3257=== CONT TestDrainTimeout3258--- PASS: TestQueueDeduplication (0.00s)32592026/10/01 09:15:49 INFO Uploading batch count=432602026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=432612026/10/01 09:15:49 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13789-2688134661/TestDrainIsolatesPoisonPath2541819674/002/bbb3262--- PASS: TestQueueEnqueueAndFetch (0.00s)32632026/10/01 09:15:49 INFO Uploading batch count=132642026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=132652026/10/01 09:15:49 INFO Uploading batch count=132662026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=132672026/10/01 09:15:49 INFO Uploading batch count=232682026/10/01 09:15:49 INFO Uploading batch count=132692026/10/01 09:15:49 ERROR Upload failed error="upload failed" count=132702026/10/01 09:15:49 ERROR Drain finished with paths left in queue remaining=13271--- PASS: TestDrainIsolatesPoisonPath (0.01s)3272--- PASS: TestWorkerSkipsGCdPaths (0.03s)3273--- PASS: TestWorkerUploadsAndRemoves (0.03s)3274--- PASS: TestWorkerPrunesClosureDeps (0.03s)3275--- PASS: TestQueueRemoveLargeClosure (0.06s)3276--- PASS: TestQueueConcurrentWriters (0.15s)32772026/10/01 09:15:50 ERROR Upload failed error="context deadline exceeded" count=232782026/10/01 09:15:50 ERROR Drain finished with paths left in queue remaining=43279--- PASS: TestDrainTimeout (0.21s)32802026/10/01 09:15:50 INFO Uploading batch count=132812026/10/01 09:15:50 INFO Uploading batch count=132822026/10/01 09:15:50 INFO Uploading batch count=132832026/10/01 09:15:50 ERROR Upload failed error="upload failed" count=132842026/10/01 09:15:50 INFO Uploading batch count=132852026/10/01 09:15:50 ERROR Upload failed error="upload failed" count=132862026/10/01 09:15:50 INFO Uploading batch count=132872026/10/01 09:15:50 ERROR Upload failed error="upload failed" count=132882026/10/01 09:15:50 INFO Uploading batch count=132892026/10/01 09:15:50 ERROR Upload failed error="upload failed" count=132902026/10/01 09:15:50 ERROR Drain finished with paths left in queue remaining=13291--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3292PASS