niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #320
· 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.15s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.01s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96=== CONT TestEncodeNixBase32WithRealHash97--- PASS: TestShellSplit (0.00s)98=== CONT TestScriptTokenEmptyCommand99--- PASS: TestScriptTokenEmptyCommand (0.00s)100=== CONT TestScriptTokenScriptFails101--- PASS: TestEncodeNixBase32WithRealHash (0.00s)102=== CONT TestParsePathInfoJSONMultiplePaths103=== CONT TestPathInfoCACompatibility104=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths105=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths106=== RUN TestPathInfoCACompatibility/null_ca_field107=== CONT TestSetClientTLSDoesNotMutateDefaultTransport108=== PAUSE TestPathInfoCACompatibility/null_ca_field109=== RUN TestPathInfoCACompatibility/old_string_format_-_text110=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text111=== CONT TestResolveStorePath112=== CONT TestPathInfoHashCompatibility113=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)114=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)115=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon116=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon117=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI118=== CONT TestGetStorePathHash119=== RUN TestGetStorePathHash/valid_store_path120=== PAUSE TestGetStorePathHash/valid_store_path121=== CONT TestConvertHashToNix32122=== RUN TestConvertHashToNix32/SRI_format_to_Nix32123=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32124=== RUN TestGetStorePathHash/basename_without_hyphen_should_error125=== RUN TestConvertHashToNix32/already_Nix32_format126=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error127=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive128=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive129=== RUN TestPathInfoCACompatibility/new_structured_format_-_text130=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text131=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method132=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method133=== PAUSE TestConvertHashToNix32/already_Nix32_format134=== RUN TestConvertHashToNix32/invalid_format135=== PAUSE TestConvertHashToNix32/invalid_format136=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess137=== CONT TestRateLimiterFeedback1382026/10/01 09:48:24 WARN Rate limiter enabled after throttle name=server-test rate=5139=== RUN TestRateLimiterFeedback/429_enables_limiter140=== PAUSE TestRateLimiterFeedback/429_enables_limiter141=== RUN TestRateLimiterFeedback/503_enables_limiter142=== PAUSE TestRateLimiterFeedback/503_enables_limiter143=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter144=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter145=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter146=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter147=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths148=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths149=== CONT TestParsePathInfoJSON150=== CONT TestDoWithRetry_BodyReplayedViaGetBody151=== CONT TestFileTokenEmpty152=== RUN TestParsePathInfoJSON/Nix_format153=== PAUSE TestParsePathInfoJSON/Nix_format154=== RUN TestParsePathInfoJSON/Lix_format155=== PAUSE TestParsePathInfoJSON/Lix_format156=== RUN TestParsePathInfoJSON/empty_input157=== PAUSE TestParsePathInfoJSON/empty_input158=== RUN TestParsePathInfoJSON/whitespace_only159=== PAUSE TestParsePathInfoJSON/whitespace_only160=== RUN TestParsePathInfoJSON/invalid_JSON161=== PAUSE TestParsePathInfoJSON/invalid_JSON162=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error163=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error164=== CONT TestScriptTokenBadJSON165=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error166=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error167=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI168=== CONT TestScriptTokenEmptyToken169=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512170=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512171=== CONT TestScriptTokenCachesUntilRefresh1722026/10/01 09:48:24 WARN Rate limiter enabled after throttle name=server-test rate=51732026/10/01 09:48:24 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53094174--- PASS: TestDoServerRequestAttachesToken (0.00s)175=== CONT TestScriptTokenNoExpiryRerunsEveryCall1762026/10/01 09:48:24 WARN Rate limiter backed off name=server-test rate=51772026/10/01 09:48:24 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53094178--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)179=== CONT TestFileTokenReadsAndCaches180--- PASS: TestScriptTokenScriptFails (0.00s)181=== CONT TestFileTokenMissing182=== CONT TestUploadMultipart_SupersededByPeer183--- PASS: TestFileTokenEmpty (0.03s)184=== RUN TestUploadMultipart_SupersededByPeer/exists185=== PAUSE TestUploadMultipart_SupersededByPeer/exists186=== RUN TestUploadMultipart_SupersededByPeer/missing187=== PAUSE TestUploadMultipart_SupersededByPeer/missing188=== CONT TestEncodeNixBase32189=== RUN TestEncodeNixBase32/test_string_hash190=== PAUSE TestEncodeNixBase32/test_string_hash191=== RUN TestEncodeNixBase32/empty_input192=== PAUSE TestEncodeNixBase32/empty_input193=== CONT TestDumpPathWriterError194--- PASS: TestFileTokenMissing (0.05s)195=== CONT TestDumpPathSingleFile196--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.08s)197=== CONT TestDumpPathMatchesNix198--- PASS: TestScriptTokenBadJSON (0.08s)199=== CONT TestStreamPushGivesUpOnDeadServer2002026/10/01 09:48:24 ERROR Upload failed error="connection refused" count=202012026/10/01 09:48:24 ERROR Server seems unavailable, giving up on batch untried=17202--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)203=== CONT TestSetClientTLS204--- PASS: TestScriptTokenEmptyToken (0.08s)205=== CONT TestClientSignaturesByStorePath206--- PASS: TestClientSignaturesByStorePath (0.00s)207=== CONT TestStreamPushReportsSignatures2082026/10/01 09:48:24 ERROR Upload failed error=boom count=1209--- PASS: TestFileTokenReadsAndCaches (0.08s)210=== CONT TestStreamPushRequestLine211--- PASS: TestStreamPushReportsSignatures (0.00s)212=== CONT TestStreamPushBatchesUnderLoad2132026/10/01 09:48:24 ERROR Upload failed error=boom count=1214--- PASS: TestResolveStorePath (0.08s)215=== CONT TestStreamPushIsolatesFailures2162026/10/01 09:48:24 ERROR Upload failed error="bad path" count=3217--- PASS: TestStreamPushIsolatesFailures (0.00s)218=== CONT TestFilterOversizedClosures219=== RUN TestFilterOversizedClosures/no_limit_keeps_everything220=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything221=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped222=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped223=== RUN TestFilterOversizedClosures/all_closures_skipped224=== PAUSE TestFilterOversizedClosures/all_closures_skipped225=== CONT TestPartSizeForNAR226=== RUN TestPartSizeForNAR/zero_stays_at_minimum227=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum228=== RUN TestPartSizeForNAR/small_stays_at_minimum229=== PAUSE TestPartSizeForNAR/small_stays_at_minimum230=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum231=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum232=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts233=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts234=== RUN TestPartSizeForNAR/1_TiB235=== PAUSE TestPartSizeForNAR/1_TiB236=== RUN TestPartSizeForNAR/5_TiB_S3_max_object237=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object238=== RUN TestPartSizeForNAR/capped_at_5_GiB239=== PAUSE TestPartSizeForNAR/capped_at_5_GiB240=== CONT TestUploadMultipart_PartsInParallel241--- PASS: TestStreamPushRequestLine (0.02s)242=== CONT TestRegisterUploadedObjectReusesConnections243=== RUN TestSetClientTLS/rejects_connection_without_client_cert244=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert245=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA246=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA247=== RUN TestSetClientTLS/preserves_debug_logging_transport248=== PAUSE TestSetClientTLS/preserves_debug_logging_transport249=== CONT TestCaseHackSuffix250--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.11s)251=== CONT TestStaticToken252--- PASS: TestStaticToken (0.00s)253=== CONT TestSetClientTLSErrors254--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)255=== CONT TestStreamPushReportsEveryPath256--- PASS: TestStreamPushReportsEveryPath (0.00s)257=== CONT TestShellSplitErrors258--- PASS: TestShellSplitErrors (0.00s)259=== CONT TestPathInfoCACompatibility/null_ca_field260=== CONT TestConvertHashToNix32/SRI_format_to_Nix32261=== CONT TestPathInfoCACompatibility/old_string_format_-_text262=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method263=== CONT TestPathInfoCACompatibility/new_structured_format_-_text264=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive265--- PASS: TestPathInfoCACompatibility (0.00s)266 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)267 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)268 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)269 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)270 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)271=== CONT TestRateLimiterFeedback/429_enables_limiter2722026/10/01 09:48:24 WARN Rate limiter enabled after throttle name=server-test rate=52732026/10/01 09:48:24 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:531672742026/10/01 09:48:24 WARN Rate limiter backed off name=server-test rate=5275=== CONT TestConvertHashToNix32/invalid_format276=== CONT TestConvertHashToNix32/already_Nix32_format277--- PASS: TestConvertHashToNix32 (0.00s)278 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)279 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)280 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)281=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter282=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths283=== CONT TestRateLimiterFeedback/503_enables_limiter2842026/10/01 09:48:24 WARN Rate limiter enabled after throttle name=server-test rate=52852026/10/01 09:48:24 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:531712862026/10/01 09:48:24 WARN Rate limiter backed off name=server-test rate=5287=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths288--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)289 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)290 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)291=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter292--- PASS: TestRateLimiterFeedback (0.00s)293 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)294 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)295 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)296 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)297=== CONT TestParsePathInfoJSON/Nix_format298=== CONT TestParsePathInfoJSON/whitespace_only299=== CONT TestGetStorePathHash/valid_store_path300=== CONT TestParsePathInfoJSON/empty_input301=== CONT TestParsePathInfoJSON/Lix_format302=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error303=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error304=== CONT TestGetStorePathHash/basename_without_hyphen_should_error305--- PASS: TestGetStorePathHash (0.00s)306 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)307 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)308 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)309 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)310=== CONT TestParsePathInfoJSON/invalid_JSON311--- PASS: TestParsePathInfoJSON (0.00s)312 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)313 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)314 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)315 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)316 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)317=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)318=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI319=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512320=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon321--- PASS: TestPathInfoHashCompatibility (0.00s)322 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)323 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)324 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)325 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)326=== CONT TestUploadMultipart_SupersededByPeer/exists327=== CONT TestEncodeNixBase32/test_string_hash328=== CONT TestUploadMultipart_SupersededByPeer/missing329--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)330 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)331 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)332=== CONT TestEncodeNixBase32/empty_input333--- PASS: TestEncodeNixBase32 (0.00s)334 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)335 --- PASS: TestEncodeNixBase32/empty_input (0.00s)336=== CONT TestFilterOversizedClosures/no_limit_keeps_everything337=== CONT TestFilterOversizedClosures/all_closures_skipped3382026/10/01 09:48:24 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=50339=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3402026/10/01 09:48:24 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=2000341=== CONT TestPartSizeForNAR/zero_stays_at_minimum342=== CONT TestPartSizeForNAR/capped_at_5_GiB343=== CONT TestPartSizeForNAR/5_TiB_S3_max_object344=== CONT TestPartSizeForNAR/1_TiB345=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts346=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum347=== CONT TestPartSizeForNAR/small_stays_at_minimum348--- PASS: TestPartSizeForNAR (0.00s)349 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)350 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)351 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)352 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)353 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)354 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)355 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)356=== CONT TestSetClientTLS/rejects_connection_without_client_cert357--- PASS: TestFilterOversizedClosures (0.00s)358 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)359 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)360 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3612026/10/01 09:48:24 http: TLS handshake error from 127.0.0.1:53179: remote error: tls: bad certificate362=== CONT TestSetClientTLS/preserves_debug_logging_transport363=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA364--- PASS: TestScriptTokenCachesUntilRefresh (0.14s)365--- PASS: TestDumpPathSingleFile (0.09s)366=== RUN TestSetClientTLSErrors/missing_cert_file367=== PAUSE TestSetClientTLSErrors/missing_cert_file368=== RUN TestSetClientTLSErrors/missing_key_file369=== PAUSE TestSetClientTLSErrors/missing_key_file370=== RUN TestSetClientTLSErrors/missing_ca_file371=== PAUSE TestSetClientTLSErrors/missing_ca_file372=== RUN TestSetClientTLSErrors/invalid_ca_file373=== PAUSE TestSetClientTLSErrors/invalid_ca_file374=== CONT TestSetClientTLSErrors/missing_cert_file375=== CONT TestSetClientTLSErrors/invalid_ca_file376--- PASS: TestSetClientTLS (0.06s)377 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)378 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)379 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)380=== CONT TestSetClientTLSErrors/missing_ca_file381=== CONT TestSetClientTLSErrors/missing_key_file382--- PASS: TestCaseHackSuffix (0.06s)383--- PASS: TestStreamPushBatchesUnderLoad (0.10s)384--- PASS: TestSetClientTLSErrors (0.10s)385 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)386 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)387 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)388 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)389--- PASS: TestUploadMultipart_PartsInParallel (0.61s)390--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)391--- PASS: TestDumpPathWriterError (1.55s)392--- PASS: TestDumpPathMatchesNix (1.50s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld14".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-79549-3801637548/postgres3399210969/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-79549-3801637548/postgres3399210969/data -l logfile start421422/nix/var/nix/builds/nix-79549-3801637548/postgres3399210969:5432 - no response4232026-10-01 09:48:39.489 UTC [79965] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:48:39.510 UTC [79965] LOG: listening on Unix socket "/nix/var/nix/builds/nix-79549-3801637548/postgres3399210969/.s.PGSQL.5432"4252026-10-01 09:48:39.539 UTC [79972] LOG: database system was shut down at 2026-10-01 09:48:39 UTC4262026-10-01 09:48:39.546 UTC [79965] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-79549-3801637548/postgres3399210969:5432 - accepting connections428{"timestamp":"2026-10-01T09:48:39.826188Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"493c6ccc-2d61-428f-9631-a5a1660ad75c","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}429{"timestamp":"2026-10-01T09:48:39.929464Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9f3c22f8-9e22-4977-9d76-4046fb4ef0ab","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{"timestamp":"2026-10-01T09:48:40.030473Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"994fd62e-6992-4fc7-baca-d473b0bf834f","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)"}431{"timestamp":"2026-10-01T09:48:40.132972Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9aaa279c-3974-4da1-8280-7037b8a6c72f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}432{"timestamp":"2026-10-01T09:48:40.235666Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f6ab220c-8452-4120-a250-f259db1f0bdc","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}433=== RUN TestService_AuthMiddleware434=== PAUSE TestService_AuthMiddleware435=== RUN TestService_AuthMiddleware_MTLSProxyHeader436=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader437=== RUN TestService_AuthMiddleware_MTLSBoundSubjects438=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects439=== RUN TestService_ReadAuthMiddleware440=== PAUSE TestService_ReadAuthMiddleware441=== RUN TestService_AuthMiddleware_OIDC442=== PAUSE TestService_AuthMiddleware_OIDC443=== RUN TestService_RequireScope_OIDC444=== PAUSE TestService_RequireScope_OIDC445=== RUN TestService_ReadScope_PublicByDefault446=== PAUSE TestService_ReadScope_PublicByDefault447=== RUN TestCacheConfigHandler448=== PAUSE TestCacheConfigHandler449=== RUN TestCacheStatsHandler450=== PAUSE TestCacheStatsHandler451=== RUN TestClientCADerivations452=== PAUSE TestClientCADerivations453=== RUN TestClientErrorHandling454=== PAUSE TestClientErrorHandling455=== RUN TestClientIntegration456=== PAUSE TestClientIntegration457=== RUN TestClientMultipleUploads458=== PAUSE TestClientMultipleUploads459=== RUN TestClientWithDependencies460=== PAUSE TestClientWithDependencies461=== RUN TestClientSharedPathCommittedMidPush462=== PAUSE TestClientSharedPathCommittedMidPush463=== RUN TestPinProtectsFromGC464=== PAUSE TestPinProtectsFromGC465=== RUN TestClientPushesUseOnePush466=== PAUSE TestClientPushesUseOnePush467=== RUN TestClientFallsBackToClosures468=== PAUSE TestClientFallsBackToClosures469=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock470=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock471=== RUN TestResolveDBConnectionString472=== PAUSE TestResolveDBConnectionString473=== RUN TestLeadElectsOneAndHandsOver474=== PAUSE TestLeadElectsOneAndHandsOver475=== RUN TestLeadIncumbentWinsAfterRestart4762026-10-01 09:48:43.319 UTC [80058] ERROR: relation "goose_db_version" does not exist at character 364772026-10-01 09:48:43.319 UTC [80058] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4782026/10/01 09:48:43 OK 20241026095416_initial_model.sql (152.56ms)4792026/10/01 09:48:43 OK 20251210153512_drop_unused_gin_index.sql (11.78ms)4802026/10/01 09:48:43 OK 20251218171726_add_pins.sql (29.65ms)4812026/10/01 09:48:43 OK 20260628120000_add_object_size_and_stats.sql (26.72ms)4822026/10/01 09:48:43 OK 20260905000000_add_claims.sql (20.52ms)4832026/10/01 09:48:43 OK 20260920000000_drop_claims.sql (36.8ms)4842026/10/01 09:48:43 OK 20260923120000_add_pushes.sql (4.3ms)4852026/10/01 09:48:43 goose: successfully migrated database to version: 202609231200004862026/10/01 09:48:43 OK 1_commit_pending_closure.sql (1.84ms)4872026/10/01 09:48:43 OK 2_object_stats_trigger.sql (415.29µs)4882026/10/01 09:48:43 OK 3_commit_push.sql (305.33µs)4892026/10/01 09:48:43 goose: up to current file version: 34902026/10/01 09:48:43 INFO lead: acquired remote=192.0.2.1:12344912026/10/01 09:48:44 INFO lead: released remote=192.0.2.1:12344922026/10/01 09:48:44 INFO lead: acquired remote=192.0.2.1:12344932026/10/01 09:48:44 INFO lead: released remote=192.0.2.1:1234494--- PASS: TestLeadIncumbentWinsAfterRestart (4.22s)495=== RUN TestLeadEndsOnShutdown496=== PAUSE TestLeadEndsOnShutdown497=== RUN TestGCAdvisoryLockBlocksConcurrentRun4982026-10-01 09:48:45.699 UTC [80128] ERROR: relation "goose_db_version" does not exist at character 364992026-10-01 09:48:45.699 UTC [80128] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5002026/10/01 09:48:45 OK 20241026095416_initial_model.sql (172.29ms)5012026/10/01 09:48:45 OK 20251210153512_drop_unused_gin_index.sql (14ms)5022026/10/01 09:48:45 OK 20251218171726_add_pins.sql (21.83ms)5032026/10/01 09:48:45 OK 20260628120000_add_object_size_and_stats.sql (9.53ms)5042026/10/01 09:48:46 OK 20260905000000_add_claims.sql (55.06ms)5052026/10/01 09:48:46 OK 20260920000000_drop_claims.sql (28.41ms)5062026/10/01 09:48:46 OK 20260923120000_add_pushes.sql (12.78ms)5072026/10/01 09:48:46 goose: successfully migrated database to version: 202609231200005082026/10/01 09:48:46 OK 1_commit_pending_closure.sql (863.71µs)5092026/10/01 09:48:46 OK 2_object_stats_trigger.sql (192.83µs)5102026/10/01 09:48:46 OK 3_commit_push.sql (138.08µs)5112026/10/01 09:48:46 goose: up to current file version: 3512--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.75s)513=== RUN TestGCBugBareHashReferences514=== PAUSE TestGCBugBareHashReferences515=== RUN TestGCMetrics516=== PAUSE TestGCMetrics517=== RUN TestPushDedupSurvivesConcurrentGC518=== PAUSE TestPushDedupSurvivesConcurrentGC519=== RUN TestDeduplicatedObjectsRecordedAsPending520=== PAUSE TestDeduplicatedObjectsRecordedAsPending521=== RUN TestGCSweepSkipsPendingObjects522=== PAUSE TestGCSweepSkipsPendingObjects523=== RUN TestTombstonedObjectOfferedWithoutWaiting524=== PAUSE TestTombstonedObjectOfferedWithoutWaiting525=== RUN TestGCSweepDeliversEachKeyOnce526=== PAUSE TestGCSweepDeliversEachKeyOnce527=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection528=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection529=== RUN TestForceGCDuringPushOffersSweptObject530=== PAUSE TestForceGCDuringPushOffersSweptObject531=== RUN TestFailedS3DeleteKeepsTombstone532=== PAUSE TestFailedS3DeleteKeepsTombstone533=== RUN TestSweepSkipsRowsLockedByPush534=== PAUSE TestSweepSkipsRowsLockedByPush535=== RUN TestRegisterCompletedObjectNeedsPendingRow536=== PAUSE TestRegisterCompletedObjectNeedsPendingRow537=== RUN TestGetExistingObjectsLocksRows538=== PAUSE TestGetExistingObjectsLocksRows539=== RUN TestSweepRechecksPendingAfterLocking540=== PAUSE TestSweepRechecksPendingAfterLocking541=== RUN TestPushWaitsForSweepHoldingRow542=== PAUSE TestPushWaitsForSweepHoldingRow543=== RUN TestCommitRacingPendingCleanupKeepsObjects544=== PAUSE TestCommitRacingPendingCleanupKeepsObjects545=== RUN TestGCEndsOnShutdown546=== PAUSE TestGCEndsOnShutdown547=== RUN TestGCTaskStore_StartNew548=== PAUSE TestGCTaskStore_StartNew549=== RUN TestGCTaskStore_DeduplicateSameParams550=== PAUSE TestGCTaskStore_DeduplicateSameParams551=== RUN TestGCTaskStore_ConflictDifferentParams552=== PAUSE TestGCTaskStore_ConflictDifferentParams553=== RUN TestGCTaskStore_GetEmpty554=== PAUSE TestGCTaskStore_GetEmpty555=== RUN TestGCTaskStore_GetReturnsLatest556=== PAUSE TestGCTaskStore_GetReturnsLatest557=== RUN TestGCTaskStore_CompletedAllowsNewTask558=== PAUSE TestGCTaskStore_CompletedAllowsNewTask559=== RUN TestGCTaskStore_PhaseUpdates560=== PAUSE TestGCTaskStore_PhaseUpdates561=== RUN TestGCTaskStore_Fail562=== PAUSE TestGCTaskStore_Fail563=== RUN TestGracefulShutdownDrainsInflight564=== PAUSE TestGracefulShutdownDrainsInflight565=== RUN TestService_healthCheckHandler566=== PAUSE TestService_healthCheckHandler567=== RUN TestService_readinessHandler568=== PAUSE TestService_readinessHandler569=== RUN TestGenerateLandingPage570=== PAUSE TestGenerateLandingPage571=== RUN TestCacheConfigHandlerMaxNarSize572=== PAUSE TestCacheConfigHandlerMaxNarSize573=== RUN TestCreatePendingClosureRejectsOversizedNAR574=== PAUSE TestCreatePendingClosureRejectsOversizedNAR575=== RUN TestNARDeduplicationMetadataUploadBug576=== PAUSE TestNARDeduplicationMetadataUploadBug577=== RUN TestMetricsInventory578=== PAUSE TestMetricsInventory579=== RUN TestService_NativeMTLS580=== PAUSE TestService_NativeMTLS581=== RUN TestServerTLSConfig582=== PAUSE TestServerTLSConfig583=== RUN TestMultipartCleanup584=== PAUSE TestMultipartCleanup585=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded586=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded587=== RUN TestPendingCleanupUsesOneCutoff588=== PAUSE TestPendingCleanupUsesOneCutoff589=== RUN TestObjectStatsTrigger590=== PAUSE TestObjectStatsTrigger591=== RUN TestOrphanedObjectsGC592=== PAUSE TestOrphanedObjectsGC593=== RUN TestOrphanedObjectsGCStressTest594=== PAUSE TestOrphanedObjectsGCStressTest595=== RUN TestCreatePin_ReservedPins596=== PAUSE TestCreatePin_ReservedPins597=== RUN TestPresentReportsOnlyClosureRoots598=== PAUSE TestPresentReportsOnlyClosureRoots599=== RUN TestPresentNotReportedWhileGCDeletesClosure600=== PAUSE TestPresentNotReportedWhileGCDeletesClosure601=== RUN TestParseSingleRange602=== PAUSE TestParseSingleRange603=== RUN TestProxyHeadersOnlyTrustedOnSocket604=== PAUSE TestProxyHeadersOnlyTrustedOnSocket605=== RUN TestIsValidCachePath606=== PAUSE TestIsValidCachePath607=== RUN TestReadProxyNarinfo608=== PAUSE TestReadProxyNarinfo609=== RUN TestReadProxyNarinfoAlreadyDecompressed610=== PAUSE TestReadProxyNarinfoAlreadyDecompressed611=== RUN TestReadProxyNarStreaming612=== PAUSE TestReadProxyNarStreaming613=== RUN TestReadProxy404614=== PAUSE TestReadProxy404615=== RUN TestReadProxyInvalidPath616=== PAUSE TestReadProxyInvalidPath617=== RUN TestReadProxyHead618=== PAUSE TestReadProxyHead619=== RUN TestReadProxyConditionalGet620=== PAUSE TestReadProxyConditionalGet621=== RUN TestReadProxyRootRedirectsToIndexHTML622=== PAUSE TestReadProxyRootRedirectsToIndexHTML623=== RUN TestReadProxyDisabled624=== PAUSE TestReadProxyDisabled625=== RUN TestReadRedirectNar626=== PAUSE TestReadRedirectNar627=== RUN TestReadRedirectKeepsNarinfoProxied628=== PAUSE TestReadRedirectKeepsNarinfoProxied629=== RUN TestReadProxyRangeRequest630=== PAUSE TestReadProxyRangeRequest631=== RUN TestReadRedirectUsesPublicS3URL632=== PAUSE TestReadRedirectUsesPublicS3URL633=== RUN TestPush_OverlappingRootsStoreOneRowPerKey634=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey635=== RUN TestPush_CompleteCommitsEveryRoot636=== PAUSE TestPush_CompleteCommitsEveryRoot637=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit638=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit639=== RUN TestPush_RejectsBadRequests640=== PAUSE TestPush_RejectsBadRequests641=== RUN TestPush_SignsNarinfosOfItsPendingObjects642=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects643=== RUN TestRedundantMultipartUpload644=== PAUSE TestRedundantMultipartUpload645=== RUN TestCompleteMultipartUpload_ErrorButObjectExists646=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists647=== RUN TestCompletedNarNotReofferedAcrossClosures648=== PAUSE TestCompletedNarNotReofferedAcrossClosures649=== RUN TestPresignedUploadRegisteredBeforeCommit650=== PAUSE TestPresignedUploadRegisteredBeforeCommit651=== RUN TestService_Rustfstest652=== PAUSE TestService_Rustfstest653=== RUN TestParseSize654=== PAUSE TestParseSize655=== RUN TestSkippedUploadsHandler656=== PAUSE TestSkippedUploadsHandler657=== RUN TestSystemdListenerNotActivated658--- PASS: TestSystemdListenerNotActivated (0.00s)659=== RUN TestWatchdogBeatsWhenHealthy660--- PASS: TestWatchdogBeatsWhenHealthy (0.06s)661=== RUN TestWatchdogSkipsWhenUnhealthy6622026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6692026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6702026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6712026/10/01 09:48:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"672--- PASS: TestWatchdogSkipsWhenUnhealthy (0.22s)673=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle674=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle675=== RUN TestProxyWriteTimeout676=== PAUSE TestProxyWriteTimeout677=== RUN TestIsValidUploadKey678=== PAUSE TestIsValidUploadKey679=== RUN TestUploadHandlersRejectInvalidKeys680=== PAUSE TestUploadHandlersRejectInvalidKeys681=== RUN TestUploadHandlersRejectOversizedBody682=== PAUSE TestUploadHandlersRejectOversizedBody683=== RUN TestService_cleanupPendingClosuresHandler684=== PAUSE TestService_cleanupPendingClosuresHandler685=== RUN TestService_createPendingClosureHandler686=== PAUSE TestService_createPendingClosureHandler687=== RUN TestService_verifyS3Integrity688=== PAUSE TestService_verifyS3Integrity689=== RUN TestCompleteMultipartUnregistered690=== PAUSE TestCompleteMultipartUnregistered691=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT692=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT693=== CONT TestService_AuthMiddleware694=== CONT TestCreatePendingClosureRejectsOversizedNAR695=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT696=== CONT TestCompleteMultipartUnregistered6972026/10/01 09:48:46 INFO Received uploads request method=POST path=/api/pending_closures698=== CONT TestService_verifyS3Integrity699=== CONT TestService_createPendingClosureHandler700=== CONT TestService_cleanupPendingClosuresHandler701=== CONT TestUploadHandlersRejectOversizedBody702=== CONT TestUploadHandlersRejectInvalidKeys703--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)704=== CONT TestIsValidUploadKey705=== RUN TestIsValidUploadKey/narinfo706=== PAUSE TestIsValidUploadKey/narinfo707=== RUN TestIsValidUploadKey/nar_zst708=== PAUSE TestIsValidUploadKey/nar_zst709=== RUN TestIsValidUploadKey/nar_xz710=== PAUSE TestIsValidUploadKey/nar_xz711=== RUN TestIsValidUploadKey/nar_plain712=== PAUSE TestIsValidUploadKey/nar_plain713=== RUN TestIsValidUploadKey/listing714=== PAUSE TestIsValidUploadKey/listing715=== RUN TestIsValidUploadKey/build_log716=== PAUSE TestIsValidUploadKey/build_log717=== RUN TestIsValidUploadKey/build_log_home-manager_file718=== PAUSE TestIsValidUploadKey/build_log_home-manager_file719=== RUN TestIsValidUploadKey/build_log_plus_in_name720=== PAUSE TestIsValidUploadKey/build_log_plus_in_name721=== RUN TestIsValidUploadKey/build_log_question_mark722=== PAUSE TestIsValidUploadKey/build_log_question_mark723=== RUN TestIsValidUploadKey/build_log_equals724=== PAUSE TestIsValidUploadKey/build_log_equals725=== RUN TestIsValidUploadKey/realisation726=== PAUSE TestIsValidUploadKey/realisation727=== RUN TestIsValidUploadKey/realisation_plus_in_output728=== PAUSE TestIsValidUploadKey/realisation_plus_in_output729=== RUN TestIsValidUploadKey/nix-cache-info730=== PAUSE TestIsValidUploadKey/nix-cache-info731=== RUN TestIsValidUploadKey/index.html732=== PAUSE TestIsValidUploadKey/index.html733=== RUN TestIsValidUploadKey/narinfo_key,_nar_type734=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type735=== RUN TestIsValidUploadKey/nar_key,_narinfo_type736=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type737=== RUN TestIsValidUploadKey/listing_key,_narinfo_type738=== CONT TestProxyWriteTimeout739=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info740=== RUN TestProxyWriteTimeout/narinfo741=== PAUSE TestProxyWriteTimeout/narinfo742=== RUN TestProxyWriteTimeout/1_GiB_nar743=== PAUSE TestProxyWriteTimeout/1_GiB_nar744=== RUN TestProxyWriteTimeout/10_GiB_nar745=== PAUSE TestProxyWriteTimeout/10_GiB_nar746=== RUN TestProxyWriteTimeout/unknown_size747=== PAUSE TestProxyWriteTimeout/unknown_size748=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle749=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type750=== RUN TestIsValidUploadKey/traversal751=== PAUSE TestIsValidUploadKey/traversal752=== RUN TestIsValidUploadKey/traversal_nar753=== PAUSE TestIsValidUploadKey/traversal_nar754=== RUN TestIsValidUploadKey/absolute755=== PAUSE TestIsValidUploadKey/absolute756=== RUN TestIsValidUploadKey/empty_key757=== PAUSE TestIsValidUploadKey/empty_key758=== RUN TestIsValidUploadKey/unknown_type759=== PAUSE TestIsValidUploadKey/unknown_type760=== CONT TestSkippedUploadsHandler761=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info762=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal763=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal764=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key765=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key766=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key767=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key768=== CONT TestParseSize769--- PASS: TestParseSize (0.00s)770=== CONT TestService_Rustfstest7712026/10/01 09:48:46 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000772--- PASS: TestSkippedUploadsHandler (0.01s)773=== CONT TestPresignedUploadRegisteredBeforeCommit774=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart775=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart776=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts777=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts778=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure779=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure780=== CONT TestCompletedNarNotReofferedAcrossClosures7812026-10-01 09:48:50.611 UTC [80296] ERROR: relation "goose_db_version" does not exist at character 367822026-10-01 09:48:50.611 UTC [80296] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7832026-10-01 09:48:50.776 UTC [80297] ERROR: relation "goose_db_version" does not exist at character 367842026-10-01 09:48:50.776 UTC [80297] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7852026-10-01 09:48:50.844 UTC [80298] ERROR: relation "goose_db_version" does not exist at character 367862026-10-01 09:48:50.844 UTC [80298] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7872026-10-01 09:48:50.887 UTC [80301] ERROR: relation "goose_db_version" does not exist at character 367882026-10-01 09:48:50.887 UTC [80301] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7892026-10-01 09:48:50.969 UTC [80314] ERROR: relation "goose_db_version" does not exist at character 367902026-10-01 09:48:50.969 UTC [80314] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7912026-10-01 09:48:51.074 UTC [80316] ERROR: relation "goose_db_version" does not exist at character 367922026-10-01 09:48:51.074 UTC [80316] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026-10-01 09:48:51.128 UTC [80321] ERROR: relation "goose_db_version" does not exist at character 367942026-10-01 09:48:51.128 UTC [80321] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026-10-01 09:48:51.181 UTC [80323] ERROR: relation "goose_db_version" does not exist at character 367962026-10-01 09:48:51.181 UTC [80323] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026/10/01 09:48:51 OK 20241026095416_initial_model.sql (482.08ms)7982026-10-01 09:48:51.232 UTC [80328] ERROR: relation "goose_db_version" does not exist at character 367992026-10-01 09:48:51.232 UTC [80328] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8002026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (23.98ms)8012026/10/01 09:48:51 OK 20251218171726_add_pins.sql (86.64ms)8022026-10-01 09:48:51.346 UTC [80331] ERROR: relation "goose_db_version" does not exist at character 368032026-10-01 09:48:51.346 UTC [80331] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (83.77ms)8052026/10/01 09:48:51 OK 20241026095416_initial_model.sql (513.53ms)8062026/10/01 09:48:51 OK 20241026095416_initial_model.sql (472.98ms)8072026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (15.02ms)8082026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (17.33ms)8092026/10/01 09:48:51 OK 20241026095416_initial_model.sql (427.36ms)8102026/10/01 09:48:51 OK 20251218171726_add_pins.sql (57.86ms)8112026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (14.57ms)8122026/10/01 09:48:51 OK 20260905000000_add_claims.sql (126.78ms)8132026/10/01 09:48:51 OK 20251218171726_add_pins.sql (78.69ms)8142026/10/01 09:48:51 OK 20251218171726_add_pins.sql (70.3ms)8152026/10/01 09:48:51 OK 20241026095416_initial_model.sql (469.42ms)8162026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (94.65ms)8172026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (26.36ms)8182026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (86.21ms)8192026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (94.94ms)8202026/10/01 09:48:51 OK 20260920000000_drop_claims.sql (142.78ms)8212026/10/01 09:48:51 OK 20241026095416_initial_model.sql (455.85ms)8222026/10/01 09:48:51 OK 20241026095416_initial_model.sql (436.46ms)8232026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (36.33ms)8242026/10/01 09:48:51 OK 20260923120000_add_pushes.sql (45.61ms)8252026/10/01 09:48:51 goose: successfully migrated database to version: 202609231200008262026/10/01 09:48:51 OK 20251218171726_add_pins.sql (110.14ms)8272026/10/01 09:48:51 OK 1_commit_pending_closure.sql (3.49ms)8282026/10/01 09:48:51 OK 2_object_stats_trigger.sql (443.33µs)8292026/10/01 09:48:51 OK 3_commit_push.sql (321.63µs)8302026/10/01 09:48:51 goose: up to current file version: 38312026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (27.48ms)8322026/10/01 09:48:51 OK 20260905000000_add_claims.sql (169.85ms)8332026/10/01 09:48:51 OK 20241026095416_initial_model.sql (409.53ms)8342026/10/01 09:48:51 OK 20251218171726_add_pins.sql (59.48ms)8352026/10/01 09:48:51 OK 20241026095416_initial_model.sql (471.32ms)8362026/10/01 09:48:51 OK 20251218171726_add_pins.sql (52.49ms)8372026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (14.77ms)8382026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (8.46ms)8392026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (74.23ms)8402026/10/01 09:48:51 OK 20260905000000_add_claims.sql (190.05ms)8412026/10/01 09:48:51 OK 20260905000000_add_claims.sql (151.41ms)8422026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (63.93ms)8432026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (73.31ms)8442026/10/01 09:48:51 OK 20251218171726_add_pins.sql (77.16ms)8452026/10/01 09:48:51 OK 20260920000000_drop_claims.sql (127.07ms)8462026/10/01 09:48:51 OK 20251218171726_add_pins.sql (101.09ms)8472026/10/01 09:48:51 OK 20260920000000_drop_claims.sql (111.55ms)8482026/10/01 09:48:51 OK 20260920000000_drop_claims.sql (113.24ms)8492026/10/01 09:48:51 OK 20260923120000_add_pushes.sql (45.9ms)8502026/10/01 09:48:51 goose: successfully migrated database to version: 202609231200008512026/10/01 09:48:51 OK 1_commit_pending_closure.sql (2.93ms)8522026/10/01 09:48:51 OK 2_object_stats_trigger.sql (342.67µs)8532026/10/01 09:48:51 OK 3_commit_push.sql (240.58µs)8542026/10/01 09:48:51 goose: up to current file version: 38552026/10/01 09:48:51 OK 20260923120000_add_pushes.sql (21.52ms)8562026/10/01 09:48:51 goose: successfully migrated database to version: 202609231200008572026/10/01 09:48:51 OK 1_commit_pending_closure.sql (1.21ms)8582026/10/01 09:48:51 OK 2_object_stats_trigger.sql (270.04µs)8592026/10/01 09:48:51 OK 3_commit_push.sql (213.83µs)8602026/10/01 09:48:51 goose: up to current file version: 38612026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (63.64ms)8622026/10/01 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (86.16ms)8632026/10/01 09:48:51 OK 20241026095416_initial_model.sql (499.13ms)8642026/10/01 09:48:51 OK 20260905000000_add_claims.sql (165.9ms)8652026/10/01 09:48:51 OK 20260923120000_add_pushes.sql (40.12ms)8662026/10/01 09:48:51 goose: successfully migrated database to version: 202609231200008672026/10/01 09:48:51 OK 1_commit_pending_closure.sql (1.46ms)8682026/10/01 09:48:51 OK 2_object_stats_trigger.sql (300.42µs)8692026/10/01 09:48:51 OK 3_commit_push.sql (252.08µs)8702026/10/01 09:48:51 goose: up to current file version: 38712026/10/01 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (36.06ms)8722026/10/01 09:48:52 OK 20260905000000_add_claims.sql (172.52ms)8732026/10/01 09:48:52 OK 20260905000000_add_claims.sql (176.12ms)8742026/10/01 09:48:52 OK 20251218171726_add_pins.sql (78.09ms)8752026/10/01 09:48:52 OK 20260920000000_drop_claims.sql (107.33ms)8762026/10/01 09:48:52 OK 20260920000000_drop_claims.sql (85.68ms)8772026/10/01 09:48:52 OK 20260905000000_add_claims.sql (153.33ms)8782026/10/01 09:48:52 OK 20260923120000_add_pushes.sql (43.93ms)8792026/10/01 09:48:52 goose: successfully migrated database to version: 202609231200008802026/10/01 09:48:52 OK 1_commit_pending_closure.sql (1.96ms)8812026/10/01 09:48:52 OK 2_object_stats_trigger.sql (456.63µs)8822026/10/01 09:48:52 OK 3_commit_push.sql (305.83µs)8832026/10/01 09:48:52 goose: up to current file version: 38842026/10/01 09:48:52 OK 20260920000000_drop_claims.sql (97.09ms)8852026/10/01 09:48:52 OK 20260905000000_add_claims.sql (174.92ms)8862026/10/01 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (87.1ms)8872026/10/01 09:48:52 OK 20260923120000_add_pushes.sql (56.55ms)8882026/10/01 09:48:52 goose: successfully migrated database to version: 202609231200008892026/10/01 09:48:52 OK 20260923120000_add_pushes.sql (36.21ms)8902026/10/01 09:48:52 goose: successfully migrated database to version: 202609231200008912026/10/01 09:48:52 OK 1_commit_pending_closure.sql (2.68ms)8922026/10/01 09:48:52 OK 1_commit_pending_closure.sql (2.02ms)8932026/10/01 09:48:52 OK 2_object_stats_trigger.sql (547.17µs)8942026/10/01 09:48:52 OK 2_object_stats_trigger.sql (550.42µs)8952026/10/01 09:48:52 OK 3_commit_push.sql (406.58µs)8962026/10/01 09:48:52 goose: up to current file version: 38972026/10/01 09:48:52 OK 3_commit_push.sql (378.58µs)8982026/10/01 09:48:52 goose: up to current file version: 38992026/10/01 09:48:52 OK 20260920000000_drop_claims.sql (67.84ms)9002026/10/01 09:48:52 OK 20260920000000_drop_claims.sql (93.41ms)9012026/10/01 09:48:52 OK 20260923120000_add_pushes.sql (50.12ms)9022026/10/01 09:48:52 goose: successfully migrated database to version: 202609231200009032026/10/01 09:48:52 OK 1_commit_pending_closure.sql (1.94ms)9042026/10/01 09:48:52 OK 2_object_stats_trigger.sql (234.25µs)9052026/10/01 09:48:52 OK 3_commit_push.sql (148.38µs)9062026/10/01 09:48:52 goose: up to current file version: 39072026/10/01 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures9082026/10/01 09:48:52 OK 20260923120000_add_pushes.sql (30.25ms)9092026/10/01 09:48:52 goose: successfully migrated database to version: 202609231200009102026/10/01 09:48:52 OK 20260905000000_add_claims.sql (96.38ms)9112026/10/01 09:48:52 OK 1_commit_pending_closure.sql (3.35ms)9122026/10/01 09:48:52 OK 2_object_stats_trigger.sql (378.75µs)9132026/10/01 09:48:52 OK 3_commit_push.sql (161.75µs)9142026/10/01 09:48:52 goose: up to current file version: 39152026/10/01 09:48:52 OK 20260920000000_drop_claims.sql (130.96ms)9162026/10/01 09:48:52 OK 20260923120000_add_pushes.sql (29.6ms)9172026/10/01 09:48:52 goose: successfully migrated database to version: 202609231200009182026/10/01 09:48:52 OK 1_commit_pending_closure.sql (3.37ms)9192026/10/01 09:48:52 OK 2_object_stats_trigger.sql (671.71µs)9202026/10/01 09:48:52 OK 3_commit_push.sql (469.71µs)9212026/10/01 09:48:52 goose: up to current file version: 39222026/10/01 09:48:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"923--- PASS: TestService_AuthMiddleware (6.16s)924=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9252026/10/01 09:48:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9262026/10/01 09:48:53 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst927--- PASS: TestCompleteMultipartUnregistered (6.66s)928=== CONT TestRedundantMultipartUpload9292026/10/01 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures9302026/10/01 09:48:54 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9312026/10/01 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures932--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.69s)933=== CONT TestPush_SignsNarinfosOfItsPendingObjects9342026/10/01 09:48:54 INFO Received cleanup request method=DELETE path=/api/pending_closures9352026/10/01 09:48:54 INFO Aborted multipart uploads count=0 kept=09362026/10/01 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures9372026/10/01 09:48:54 INFO Received cleanup request method=DELETE path=/api/pending_closures9382026/10/01 09:48:54 INFO Aborted multipart uploads count=1 kept=09392026/10/01 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9402026-10-01 09:48:54.916 UTC [80314] ERROR: Closure does not exist: id=19412026-10-01 09:48:54.916 UTC [80314] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE9422026-10-01 09:48:54.916 UTC [80314] STATEMENT: -- name: CommitPendingClosure :exec943 SELECT commit_pending_closure($1::bigint)944 945--- PASS: TestService_cleanupPendingClosuresHandler (8.32s)946=== CONT TestPush_RejectsBadRequests9472026/10/01 09:48:55 INFO Received uploads request method=POST path=/api/pending_closures9482026/10/01 09:48:55 INFO Received uploads request method=POST path=/api/pending_closures9492026/10/01 09:48:55 INFO Received uploads request method=POST path=/api/pending_closures9502026/10/01 09:48:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete951--- PASS: TestService_Rustfstest (9.42s)952=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9532026/10/01 09:48:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLmViOGY2YTczLTAwYmUtNDlkOS04ZWQ1LTRmODc4NmZkYzBmNXgxNzkwODQ4MTMyMzY2NDA3MDAw parts=109542026/10/01 09:48:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9552026/10/01 09:48:56 INFO Completed upload id=19562026/10/01 09:48:56 INFO Received uploads request method=POST path=/api/pending_closures9572026/10/01 09:48:56 INFO Received uploads request method=POST path=/api/pending_closures9582026/10/01 09:48:56 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9592026/10/01 09:48:56 WARN Found objects in DB but missing from S3, will re-upload count=1960--- PASS: TestService_verifyS3Integrity (9.49s)961=== CONT TestPush_CompleteCommitsEveryRoot9622026/10/01 09:48:56 INFO Received uploads request method=POST path=/api/pending_closures9632026/10/01 09:48:57 INFO Received uploads request method=POST path=/api/pending_closures964--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (11.05s)965=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9662026/10/01 09:48:58 INFO Received uploads request method=POST path=/api/pending_closures9672026/10/01 09:48:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9682026/10/01 09:48:58 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLjAxNWUzMGQ1LTMyNjUtNDM2MC04NmJhLTIyNTc0MTA0MmY5MngxNzkwODQ4MTM1NDAwMTg5MDAw parts=109692026/10/01 09:48:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9702026/10/01 09:48:58 INFO Completed upload id=19712026/10/01 09:48:58 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009722026/10/01 09:48:58 INFO Received uploads request method=POST path=/api/pending_closures9732026/10/01 09:48:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures9742026/10/01 09:48:58 INFO Aborted multipart uploads count=0 kept=09752026/10/01 09:48:58 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=09762026/10/01 09:48:58 INFO Vacuumed table table=pending_closures9772026/10/01 09:48:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9782026/10/01 09:48:59 INFO Vacuumed table table=pending_objects9792026/10/01 09:48:59 INFO Vacuumed table table=multipart_uploads9802026/10/01 09:48:59 INFO Vacuumed table table=closures9812026/10/01 09:48:59 INFO Vacuumed table table=objects9822026/10/01 09:48:59 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000983--- PASS: TestService_createPendingClosureHandler (12.72s)984=== CONT TestReadRedirectUsesPublicS3URL9852026-10-01 09:48:59.606 UTC [80459] ERROR: relation "goose_db_version" does not exist at character 369862026-10-01 09:48:59.606 UTC [80459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9872026-10-01 09:48:59.966 UTC [80468] ERROR: relation "goose_db_version" does not exist at character 369882026-10-01 09:48:59.966 UTC [80468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9892026/10/01 09:49:00 OK 20241026095416_initial_model.sql (468.06ms)9902026/10/01 09:49:00 OK 20251210153512_drop_unused_gin_index.sql (41.46ms)9912026/10/01 09:49:00 OK 20251218171726_add_pins.sql (69.93ms)9922026/10/01 09:49:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9932026/10/01 09:49:00 OK 20260628120000_add_object_size_and_stats.sql (93.41ms)9942026/10/01 09:49:00 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLjUwMTIzYTdiLWIxY2QtNDVlMC1iMzliLTYyZjZhZjIyM2YzMXgxNzkwODQ4MTM2ODEwNzk3MDAw parts=129952026/10/01 09:49:00 INFO Received uploads request method=POST path=/api/pending_closures996--- PASS: TestCompletedNarNotReofferedAcrossClosures (13.86s)997=== CONT TestReadProxyRangeRequest9982026/10/01 09:49:00 OK 20260905000000_add_claims.sql (211.62ms)9992026/10/01 09:49:00 OK 20260920000000_drop_claims.sql (41.83ms)10002026/10/01 09:49:00 OK 20241026095416_initial_model.sql (522.29ms)10012026-10-01 09:49:00.666 UTC [80487] ERROR: relation "goose_db_version" does not exist at character 3610022026-10-01 09:49:00.666 UTC [80487] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10032026/10/01 09:49:00 OK 20251210153512_drop_unused_gin_index.sql (25.22ms)10042026/10/01 09:49:00 OK 20260923120000_add_pushes.sql (40.19ms)10052026/10/01 09:49:00 goose: successfully migrated database to version: 2026092312000010062026/10/01 09:49:00 OK 1_commit_pending_closure.sql (890.58µs)10072026/10/01 09:49:00 OK 2_object_stats_trigger.sql (254.96µs)10082026/10/01 09:49:00 OK 3_commit_push.sql (179.63µs)10092026/10/01 09:49:00 goose: up to current file version: 310102026/10/01 09:49:00 OK 20251218171726_add_pins.sql (102.94ms)10112026/10/01 09:49:00 OK 20260628120000_add_object_size_and_stats.sql (79.93ms)10122026/10/01 09:49:00 OK 20260905000000_add_claims.sql (126.74ms)10132026/10/01 09:49:01 OK 20260920000000_drop_claims.sql (98.13ms)10142026-10-01 09:49:01.099 UTC [80496] ERROR: relation "goose_db_version" does not exist at character 3610152026-10-01 09:49:01.099 UTC [80496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10162026/10/01 09:49:01 OK 20260923120000_add_pushes.sql (35.65ms)10172026/10/01 09:49:01 goose: successfully migrated database to version: 2026092312000010182026/10/01 09:49:01 OK 1_commit_pending_closure.sql (919.54µs)10192026/10/01 09:49:01 OK 2_object_stats_trigger.sql (214.58µs)10202026/10/01 09:49:01 OK 3_commit_push.sql (197.5µs)10212026/10/01 09:49:01 goose: up to current file version: 310222026/10/01 09:49:01 INFO Received uploads request method=POST path=/api/pending_closures10232026/10/01 09:49:01 OK 20241026095416_initial_model.sql (382.94ms)10242026/10/01 09:49:01 OK 20251210153512_drop_unused_gin_index.sql (13.78ms)10252026/10/01 09:49:01 OK 20251218171726_add_pins.sql (61.61ms)10262026/10/01 09:49:01 OK 20260628120000_add_object_size_and_stats.sql (83.01ms)10272026/10/01 09:49:01 OK 20260905000000_add_claims.sql (292.75ms)10282026/10/01 09:49:01 OK 20241026095416_initial_model.sql (482.06ms)10292026/10/01 09:49:01 OK 20251210153512_drop_unused_gin_index.sql (21.4ms)10302026/10/01 09:49:01 OK 20251218171726_add_pins.sql (67.97ms)10312026/10/01 09:49:01 OK 20260920000000_drop_claims.sql (99.95ms)10322026/10/01 09:49:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10332026/10/01 09:49:01 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLjM0YjIwMTViLTI5NjYtNGIzMS05NDk4LTA0YTI4OGEzZTA0YXgxNzkwODQ4MTQxMjgyNTA5MDAw10342026/10/01 09:49:01 INFO Received uploads request method=POST path=/api/pending_closures10352026/10/01 09:49:01 OK 20260923120000_add_pushes.sql (60.58ms)10362026/10/01 09:49:01 goose: successfully migrated database to version: 2026092312000010372026/10/01 09:49:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLjM0YjIwMTViLTI5NjYtNGIzMS05NDk4LTA0YTI4OGEzZTA0YXgxNzkwODQ4MTQxMjgyNTA5MDAw parts=11038--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (9.09s)1039=== CONT TestReadRedirectKeepsNarinfoProxied10402026/10/01 09:49:01 OK 1_commit_pending_closure.sql (4.07ms)10412026/10/01 09:49:01 OK 2_object_stats_trigger.sql (1.39ms)10422026/10/01 09:49:01 OK 3_commit_push.sql (226.04µs)10432026/10/01 09:49:01 goose: up to current file version: 310442026/10/01 09:49:01 OK 20260628120000_add_object_size_and_stats.sql (87.24ms)10452026/10/01 09:49:01 INFO Received uploads request method=POST path=/api/pending_closures10462026/10/01 09:49:02 OK 20260905000000_add_claims.sql (202.12ms)10472026-10-01 09:49:02.136 UTC [80504] ERROR: relation "goose_db_version" does not exist at character 3610482026-10-01 09:49:02.136 UTC [80504] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10492026/10/01 09:49:02 OK 20260920000000_drop_claims.sql (120.07ms)10502026/10/01 09:49:02 OK 20260923120000_add_pushes.sql (29.44ms)10512026/10/01 09:49:02 goose: successfully migrated database to version: 2026092312000010522026/10/01 09:49:02 OK 1_commit_pending_closure.sql (2.78ms)10532026/10/01 09:49:02 OK 2_object_stats_trigger.sql (272.04µs)10542026/10/01 09:49:02 OK 3_commit_push.sql (203.75µs)10552026/10/01 09:49:02 goose: up to current file version: 310562026-10-01 09:49:02.249 UTC [80507] ERROR: relation "goose_db_version" does not exist at character 3610572026-10-01 09:49:02.249 UTC [80507] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10582026/10/01 09:49:02 INFO Received push request method=POST path=/api/pushes10592026/10/01 09:49:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10602026/10/01 09:49:02 INFO Signed narinfos id=1 count=11061--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (8.34s)1062=== CONT TestReadRedirectNar10632026/10/01 09:49:02 OK 20241026095416_initial_model.sql (463.71ms)10642026/10/01 09:49:02 OK 20251210153512_drop_unused_gin_index.sql (25.91ms)10652026/10/01 09:49:02 OK 20251218171726_add_pins.sql (71.21ms)10662026/10/01 09:49:02 OK 20241026095416_initial_model.sql (469.28ms)10672026/10/01 09:49:02 OK 20251210153512_drop_unused_gin_index.sql (22.32ms)10682026/10/01 09:49:02 OK 20260628120000_add_object_size_and_stats.sql (102.78ms)10692026/10/01 09:49:02 OK 20251218171726_add_pins.sql (76.1ms)10702026/10/01 09:49:03 OK 20260628120000_add_object_size_and_stats.sql (84.69ms)1071=== RUN TestPush_RejectsBadRequests/no_roots1072=== PAUSE TestPush_RejectsBadRequests/no_roots1073=== RUN TestPush_RejectsBadRequests/no_objects1074=== PAUSE TestPush_RejectsBadRequests/no_objects1075=== RUN TestPush_RejectsBadRequests/bad_root1076=== PAUSE TestPush_RejectsBadRequests/bad_root1077=== RUN TestPush_RejectsBadRequests/root_not_in_objects1078=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1079=== CONT TestReadProxyDisabled10802026/10/01 09:49:03 OK 20260905000000_add_claims.sql (192.27ms)10812026/10/01 09:49:03 OK 20260905000000_add_claims.sql (147.16ms)10822026/10/01 09:49:03 OK 20260920000000_drop_claims.sql (111.64ms)10832026/10/01 09:49:03 OK 20260920000000_drop_claims.sql (83.63ms)10842026/10/01 09:49:03 OK 20260923120000_add_pushes.sql (39.45ms)10852026/10/01 09:49:03 goose: successfully migrated database to version: 2026092312000010862026/10/01 09:49:03 OK 1_commit_pending_closure.sql (2.39ms)10872026/10/01 09:49:03 OK 2_object_stats_trigger.sql (259.42µs)10882026/10/01 09:49:03 OK 3_commit_push.sql (198.42µs)10892026/10/01 09:49:03 goose: up to current file version: 310902026/10/01 09:49:03 OK 20260923120000_add_pushes.sql (25.2ms)10912026/10/01 09:49:03 goose: successfully migrated database to version: 2026092312000010922026/10/01 09:49:03 OK 1_commit_pending_closure.sql (963.21µs)10932026/10/01 09:49:03 OK 2_object_stats_trigger.sql (235.71µs)10942026/10/01 09:49:03 OK 3_commit_push.sql (184.71µs)10952026/10/01 09:49:03 goose: up to current file version: 310962026-10-01 09:49:03.803 UTC [80523] ERROR: relation "goose_db_version" does not exist at character 3610972026-10-01 09:49:03.803 UTC [80523] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10982026/10/01 09:49:03 INFO Received push request method=POST path=/api/pushes10992026/10/01 09:49:04 INFO Received complete push request method=POST path=/api/pushes/1/complete11002026/10/01 09:49:04 INFO Received push request method=POST path=/api/pushes11012026/10/01 09:49:04 INFO Aborted multipart uploads count=0 kept=011022026/10/01 09:49:04 WARN Force mode enabled - objects will be deleted immediately without grace period11032026/10/01 09:49:04 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=011042026/10/01 09:49:04 INFO Vacuumed table table=pending_closures11052026/10/01 09:49:04 INFO Vacuumed table table=pending_objects11062026/10/01 09:49:04 WARN Rate limiter enabled after throttle name=s3-test rate=511072026/10/01 09:49:04 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1108=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1109 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101110 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001111--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (17.66s)1112=== CONT TestReadProxyRootRedirectsToIndexHTML11132026/10/01 09:49:04 INFO Vacuumed table table=multipart_uploads11142026/10/01 09:49:04 INFO Received push request method=POST path=/api/pushes11152026/10/01 09:49:04 INFO Vacuumed table table=closures11162026/10/01 09:49:04 OK 20241026095416_initial_model.sql (396.6ms)11172026/10/01 09:49:04 OK 20251210153512_drop_unused_gin_index.sql (10.91ms)11182026/10/01 09:49:04 INFO Vacuumed table table=objects11192026/10/01 09:49:04 INFO Received complete push request method=POST path=/api/pushes/2/complete1120--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (8.39s)1121=== CONT TestReadProxyConditionalGet11222026/10/01 09:49:04 OK 20251218171726_add_pins.sql (75.16ms)11232026/10/01 09:49:04 INFO Received complete push request method=POST path=/api/pushes/1/complete11242026/10/01 09:49:04 OK 20260628120000_add_object_size_and_stats.sql (82.17ms)1125--- PASS: TestPush_CompleteCommitsEveryRoot (8.49s)1126=== CONT TestReadProxyHead11272026/10/01 09:49:04 OK 20260905000000_add_claims.sql (107.11ms)11282026-10-01 09:49:04.643 UTC [80541] ERROR: relation "goose_db_version" does not exist at character 3611292026-10-01 09:49:04.643 UTC [80541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11302026/10/01 09:49:04 OK 20260920000000_drop_claims.sql (64.81ms)11312026/10/01 09:49:04 OK 20260923120000_add_pushes.sql (23.33ms)11322026/10/01 09:49:04 goose: successfully migrated database to version: 2026092312000011332026/10/01 09:49:04 OK 1_commit_pending_closure.sql (1.71ms)11342026/10/01 09:49:04 OK 2_object_stats_trigger.sql (196.5µs)11352026/10/01 09:49:04 OK 3_commit_push.sql (145.21µs)11362026/10/01 09:49:04 goose: up to current file version: 311372026/10/01 09:49:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11382026/10/01 09:49:05 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLmUzMTY3NTYwLTI4MGUtNDlhNi1hOTgyLWNiNzU5NWJjZTg2ZngxNzkwODQ4MTQxODc4MjI0MDAw parts=1211392026/10/01 09:49:05 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/01 09:49:05 INFO Received uploads request method=POST path=/api/pending_closures11412026/10/01 09:49:05 OK 20241026095416_initial_model.sql (445.5ms)11422026/10/01 09:49:05 OK 20251210153512_drop_unused_gin_index.sql (17.89ms)11432026/10/01 09:49:05 OK 20251218171726_add_pins.sql (52.52ms)11442026/10/01 09:49:05 INFO Received push request method=POST path=/api/pushes11452026/10/01 09:49:05 OK 20260628120000_add_object_size_and_stats.sql (78.64ms)1146--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.80s)1147=== CONT TestReadProxyInvalidPath11482026/10/01 09:49:05 OK 20260905000000_add_claims.sql (123.18ms)11492026-10-01 09:49:05.541 UTC [80561] ERROR: relation "goose_db_version" does not exist at character 3611502026-10-01 09:49:05.541 UTC [80561] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11512026/10/01 09:49:05 OK 20260920000000_drop_claims.sql (73.73ms)11522026/10/01 09:49:05 OK 20260923120000_add_pushes.sql (29.15ms)11532026/10/01 09:49:05 goose: successfully migrated database to version: 2026092312000011542026/10/01 09:49:05 OK 1_commit_pending_closure.sql (1.15ms)11552026/10/01 09:49:05 OK 2_object_stats_trigger.sql (278.96µs)11562026/10/01 09:49:05 OK 3_commit_push.sql (213µs)11572026/10/01 09:49:05 goose: up to current file version: 311582026/10/01 09:49:06 OK 20241026095416_initial_model.sql (440.17ms)11592026/10/01 09:49:06 OK 20251210153512_drop_unused_gin_index.sql (33.37ms)11602026/10/01 09:49:06 OK 20251218171726_add_pins.sql (67.31ms)1161--- PASS: TestReadRedirectUsesPublicS3URL (6.93s)1162=== CONT TestReadProxy40411632026/10/01 09:49:06 OK 20260628120000_add_object_size_and_stats.sql (96ms)11642026/10/01 09:49:06 OK 20260905000000_add_claims.sql (173ms)11652026/10/01 09:49:06 OK 20260920000000_drop_claims.sql (112.88ms)11662026/10/01 09:49:06 OK 20260923120000_add_pushes.sql (54.42ms)11672026/10/01 09:49:06 goose: successfully migrated database to version: 2026092312000011682026/10/01 09:49:06 OK 1_commit_pending_closure.sql (1.03ms)11692026/10/01 09:49:06 OK 2_object_stats_trigger.sql (245.13µs)11702026/10/01 09:49:06 OK 3_commit_push.sql (213.17µs)11712026/10/01 09:49:06 goose: up to current file version: 31172--- PASS: TestReadProxyRangeRequest (6.93s)1173=== CONT TestReadProxyNarStreaming11742026-10-01 09:49:07.810 UTC [80588] ERROR: relation "goose_db_version" does not exist at character 3611752026-10-01 09:49:07.810 UTC [80588] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11762026/10/01 09:49:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11772026-10-01 09:49:08.435 UTC [80600] ERROR: relation "goose_db_version" does not exist at character 3611782026-10-01 09:49:08.435 UTC [80600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11792026/10/01 09:49:08 OK 20241026095416_initial_model.sql (509.55ms)11802026/10/01 09:49:08 OK 20251210153512_drop_unused_gin_index.sql (28.38ms)11812026/10/01 09:49:08 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLmQwNmM5NGJlLWI0MWYtNDc3Ni1hNmQ2LTdjNzc0ZjEyMGQ4ZXgxNzkwODQ4MTQ1MTYxNzc2MDAw error="Get \"http://127.0.0.1:1/bucket14/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11822026/10/01 09:49:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzBkOGY4YzUtZjliNS00ODVmLTlhNTktMjZlMjU4YTJlNDgwLjA4NjI3ODgyLTQwM2QtNGI3MS04NjVjLTY5NDVhZTM2ZTM5NngxNzkwODQ4MTQ1MDczMTE1MDAw parts=1211832026/10/01 09:49:08 INFO Received cleanup request method=DELETE path=/api/pending_closures11842026/10/01 09:49:08 INFO Aborted multipart uploads count=1 kept=01185--- PASS: TestRedundantMultipartUpload (15.35s)1186=== CONT TestReadProxyNarinfoAlreadyDecompressed11872026/10/01 09:49:08 OK 20251218171726_add_pins.sql (92.12ms)11882026/10/01 09:49:08 OK 20260628120000_add_object_size_and_stats.sql (98.42ms)11892026/10/01 09:49:08 OK 20260905000000_add_claims.sql (189.5ms)11902026-10-01 09:49:08.911 UTC [80606] ERROR: relation "goose_db_version" does not exist at character 3611912026-10-01 09:49:08.911 UTC [80606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11922026/10/01 09:49:09 OK 20260920000000_drop_claims.sql (128.78ms)11932026/10/01 09:49:09 OK 20260923120000_add_pushes.sql (42.81ms)11942026/10/01 09:49:09 goose: successfully migrated database to version: 2026092312000011952026/10/01 09:49:09 OK 1_commit_pending_closure.sql (1.8ms)11962026/10/01 09:49:09 OK 2_object_stats_trigger.sql (424.92µs)11972026/10/01 09:49:09 OK 3_commit_push.sql (337.42µs)11982026/10/01 09:49:09 goose: up to current file version: 311992026/10/01 09:49:09 OK 20241026095416_initial_model.sql (502.01ms)12002026/10/01 09:49:09 OK 20251210153512_drop_unused_gin_index.sql (28.85ms)12012026/10/01 09:49:09 OK 20251218171726_add_pins.sql (69.24ms)12022026/10/01 09:49:09 OK 20260628120000_add_object_size_and_stats.sql (101.14ms)12032026/10/01 09:49:09 OK 20241026095416_initial_model.sql (432.76ms)12042026/10/01 09:49:09 OK 20251210153512_drop_unused_gin_index.sql (30.05ms)12052026/10/01 09:49:09 OK 20260905000000_add_claims.sql (187.06ms)12062026/10/01 09:49:09 OK 20251218171726_add_pins.sql (65.58ms)12072026/10/01 09:49:09 OK 20260920000000_drop_claims.sql (124.55ms)12082026/10/01 09:49:09 OK 20260628120000_add_object_size_and_stats.sql (99.31ms)12092026/10/01 09:49:09 OK 20260923120000_add_pushes.sql (51.94ms)12102026/10/01 09:49:09 goose: successfully migrated database to version: 202609231200001211--- PASS: TestReadRedirectKeepsNarinfoProxied (7.86s)1212=== CONT TestReadProxyNarinfo12132026/10/01 09:49:09 OK 1_commit_pending_closure.sql (2.73ms)12142026/10/01 09:49:09 OK 2_object_stats_trigger.sql (569µs)12152026/10/01 09:49:09 OK 3_commit_push.sql (1.1ms)12162026/10/01 09:49:09 goose: up to current file version: 312172026/10/01 09:49:09 OK 20260905000000_add_claims.sql (182.2ms)12182026/10/01 09:49:09 OK 20260920000000_drop_claims.sql (88.77ms)12192026/10/01 09:49:10 OK 20260923120000_add_pushes.sql (38.16ms)12202026/10/01 09:49:10 goose: successfully migrated database to version: 2026092312000012212026/10/01 09:49:10 OK 1_commit_pending_closure.sql (3.44ms)12222026/10/01 09:49:10 OK 2_object_stats_trigger.sql (642.08µs)12232026/10/01 09:49:10 OK 3_commit_push.sql (487.67µs)12242026/10/01 09:49:10 goose: up to current file version: 31225--- PASS: TestReadRedirectNar (7.83s)1226=== CONT TestIsValidCachePath1227=== RUN TestIsValidCachePath/narinfo1228=== PAUSE TestIsValidCachePath/narinfo1229=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1230=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1231=== RUN TestIsValidCachePath/nar_zst1232=== PAUSE TestIsValidCachePath/nar_zst1233=== RUN TestIsValidCachePath/nar_xz1234=== PAUSE TestIsValidCachePath/nar_xz1235=== RUN TestIsValidCachePath/nar_bz21236=== PAUSE TestIsValidCachePath/nar_bz21237=== RUN TestIsValidCachePath/nar_uncompressed1238=== PAUSE TestIsValidCachePath/nar_uncompressed1239=== RUN TestIsValidCachePath/ls1240=== PAUSE TestIsValidCachePath/ls1241=== RUN TestIsValidCachePath/log1242=== PAUSE TestIsValidCachePath/log1243=== RUN TestIsValidCachePath/realisation1244=== PAUSE TestIsValidCachePath/realisation1245=== RUN TestIsValidCachePath/nix-cache-info1246=== PAUSE TestIsValidCachePath/nix-cache-info1247=== RUN TestIsValidCachePath/index.html1248=== PAUSE TestIsValidCachePath/index.html1249=== RUN TestIsValidCachePath/traversal_parent1250=== PAUSE TestIsValidCachePath/traversal_parent1251=== RUN TestIsValidCachePath/traversal_in_middle1252=== PAUSE TestIsValidCachePath/traversal_in_middle1253=== RUN TestIsValidCachePath/invalid_char_e1254=== PAUSE TestIsValidCachePath/invalid_char_e1255=== RUN TestIsValidCachePath/invalid_char_u1256=== PAUSE TestIsValidCachePath/invalid_char_u1257=== RUN TestIsValidCachePath/random_path1258=== PAUSE TestIsValidCachePath/random_path1259=== RUN TestIsValidCachePath/empty1260=== PAUSE TestIsValidCachePath/empty1261=== RUN TestIsValidCachePath/leading_slash1262=== PAUSE TestIsValidCachePath/leading_slash1263=== RUN TestIsValidCachePath/wrong_extension1264=== PAUSE TestIsValidCachePath/wrong_extension1265=== RUN TestIsValidCachePath/short_hash1266=== PAUSE TestIsValidCachePath/short_hash1267=== CONT TestProxyHeadersOnlyTrustedOnSocket12682026-10-01 09:49:10.635 UTC [80628] ERROR: relation "goose_db_version" does not exist at character 3612692026-10-01 09:49:10.635 UTC [80628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12702026-10-01 09:49:10.740 UTC [80629] ERROR: relation "goose_db_version" does not exist at character 3612712026-10-01 09:49:10.740 UTC [80629] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1272--- PASS: TestReadProxyDisabled (7.95s)1273=== CONT TestParseSingleRange1274=== RUN TestParseSingleRange/none1275=== PAUSE TestParseSingleRange/none1276=== RUN TestParseSingleRange/unknown_unit1277=== PAUSE TestParseSingleRange/unknown_unit1278=== RUN TestParseSingleRange/multi-range_ignored1279=== PAUSE TestParseSingleRange/multi-range_ignored1280=== RUN TestParseSingleRange/malformed_no_dash1281=== PAUSE TestParseSingleRange/malformed_no_dash1282=== RUN TestParseSingleRange/malformed_both_empty1283=== PAUSE TestParseSingleRange/malformed_both_empty1284=== RUN TestParseSingleRange/malformed_end_before_start1285=== PAUSE TestParseSingleRange/malformed_end_before_start1286=== RUN TestParseSingleRange/closed1287=== PAUSE TestParseSingleRange/closed1288=== RUN TestParseSingleRange/open-ended1289=== PAUSE TestParseSingleRange/open-ended1290=== RUN TestParseSingleRange/end_clamped_to_size1291=== PAUSE TestParseSingleRange/end_clamped_to_size1292=== RUN TestParseSingleRange/suffix1293=== PAUSE TestParseSingleRange/suffix1294=== RUN TestParseSingleRange/suffix_exceeds_size1295=== PAUSE TestParseSingleRange/suffix_exceeds_size1296=== RUN TestParseSingleRange/single_byte1297=== PAUSE TestParseSingleRange/single_byte1298=== RUN TestParseSingleRange/start_past_EOF1299=== PAUSE TestParseSingleRange/start_past_EOF1300=== RUN TestParseSingleRange/start_far_past_EOF1301=== PAUSE TestParseSingleRange/start_far_past_EOF1302=== CONT TestPresentNotReportedWhileGCDeletesClosure13032026-10-01 09:49:11.139 UTC [80632] ERROR: relation "goose_db_version" does not exist at character 3613042026-10-01 09:49:11.139 UTC [80632] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13052026/10/01 09:49:11 OK 20241026095416_initial_model.sql (519.88ms)13062026/10/01 09:49:11 OK 20251210153512_drop_unused_gin_index.sql (19.37ms)13072026/10/01 09:49:11 OK 20241026095416_initial_model.sql (469.34ms)13082026/10/01 09:49:11 OK 20251210153512_drop_unused_gin_index.sql (29.63ms)13092026/10/01 09:49:11 OK 20251218171726_add_pins.sql (86.23ms)13102026/10/01 09:49:11 OK 20251218171726_add_pins.sql (52.42ms)13112026/10/01 09:49:11 OK 20260628120000_add_object_size_and_stats.sql (56.5ms)13122026/10/01 09:49:11 OK 20260628120000_add_object_size_and_stats.sql (62.04ms)13132026/10/01 09:49:11 OK 20260905000000_add_claims.sql (109.06ms)13142026/10/01 09:49:11 OK 20241026095416_initial_model.sql (398.93ms)13152026/10/01 09:49:11 OK 20260905000000_add_claims.sql (138.37ms)13162026/10/01 09:49:11 OK 20251210153512_drop_unused_gin_index.sql (12.42ms)13172026/10/01 09:49:11 OK 20260920000000_drop_claims.sql (103.56ms)13182026/10/01 09:49:11 OK 20260923120000_add_pushes.sql (33.7ms)13192026/10/01 09:49:11 goose: successfully migrated database to version: 2026092312000013202026/10/01 09:49:11 OK 1_commit_pending_closure.sql (1.95ms)13212026/10/01 09:49:11 OK 2_object_stats_trigger.sql (425.38µs)13222026/10/01 09:49:11 OK 3_commit_push.sql (359.63µs)13232026/10/01 09:49:11 goose: up to current file version: 313242026/10/01 09:49:11 OK 20260920000000_drop_claims.sql (81.63ms)13252026/10/01 09:49:11 OK 20251218171726_add_pins.sql (70.17ms)13262026/10/01 09:49:11 OK 20260923120000_add_pushes.sql (41.8ms)13272026/10/01 09:49:11 goose: successfully migrated database to version: 2026092312000013282026/10/01 09:49:11 OK 1_commit_pending_closure.sql (1.65ms)13292026/10/01 09:49:11 OK 2_object_stats_trigger.sql (349µs)13302026/10/01 09:49:11 OK 3_commit_push.sql (311.42µs)13312026/10/01 09:49:11 goose: up to current file version: 313322026/10/01 09:49:11 OK 20260628120000_add_object_size_and_stats.sql (66.86ms)13332026-10-01 09:49:11.847 UTC [80642] ERROR: relation "goose_db_version" does not exist at character 3613342026-10-01 09:49:11.847 UTC [80642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13352026/10/01 09:49:11 OK 20260905000000_add_claims.sql (34.44ms)13362026/10/01 09:49:11 OK 20260920000000_drop_claims.sql (61.8ms)13372026/10/01 09:49:11 OK 20260923120000_add_pushes.sql (23.07ms)13382026/10/01 09:49:11 goose: successfully migrated database to version: 2026092312000013392026/10/01 09:49:11 OK 1_commit_pending_closure.sql (3.6ms)13402026/10/01 09:49:11 OK 2_object_stats_trigger.sql (286.75µs)13412026/10/01 09:49:11 OK 3_commit_push.sql (1.59ms)13422026/10/01 09:49:11 goose: up to current file version: 313432026-10-01 09:49:12.144 UTC [80647] ERROR: relation "goose_db_version" does not exist at character 3613442026-10-01 09:49:12.144 UTC [80647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1345--- PASS: TestReadProxyConditionalGet (7.74s)1346=== CONT TestPresentReportsOnlyClosureRoots13472026/10/01 09:49:12 OK 20241026095416_initial_model.sql (329.17ms)13482026/10/01 09:49:12 OK 20251210153512_drop_unused_gin_index.sql (26.65ms)13492026/10/01 09:49:12 OK 20251218171726_add_pins.sql (52.32ms)13502026/10/01 09:49:12 OK 20260628120000_add_object_size_and_stats.sql (86.72ms)13512026/10/01 09:49:12 OK 20260905000000_add_claims.sql (169.81ms)1352--- PASS: TestReadProxyRootRedirectsToIndexHTML (8.43s)1353=== CONT TestCreatePin_ReservedPins13542026/10/01 09:49:12 OK 20241026095416_initial_model.sql (478.44ms)13552026/10/01 09:49:12 OK 20260920000000_drop_claims.sql (156.88ms)13562026/10/01 09:49:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53871/oidc13572026/10/01 09:49:12 OK 20251210153512_drop_unused_gin_index.sql (24ms)13582026/10/01 09:49:12 OK 20260923120000_add_pushes.sql (48.96ms)13592026/10/01 09:49:12 goose: successfully migrated database to version: 2026092312000013602026/10/01 09:49:12 OK 1_commit_pending_closure.sql (1.11ms)13612026/10/01 09:49:12 OK 2_object_stats_trigger.sql (347µs)13622026/10/01 09:49:12 OK 3_commit_push.sql (222.79µs)13632026/10/01 09:49:12 goose: up to current file version: 313642026/10/01 09:49:12 OK 20251218171726_add_pins.sql (81.21ms)13652026/10/01 09:49:12 OK 20260628120000_add_object_size_and_stats.sql (85.04ms)13662026/10/01 09:49:13 OK 20260905000000_add_claims.sql (149.91ms)13672026/10/01 09:49:13 OK 20260920000000_drop_claims.sql (111.79ms)13682026/10/01 09:49:13 OK 20260923120000_add_pushes.sql (31.91ms)13692026/10/01 09:49:13 goose: successfully migrated database to version: 2026092312000013702026/10/01 09:49:13 OK 1_commit_pending_closure.sql (2.05ms)13712026/10/01 09:49:13 OK 2_object_stats_trigger.sql (492µs)13722026/10/01 09:49:13 OK 3_commit_push.sql (323.96µs)13732026/10/01 09:49:13 goose: up to current file version: 31374--- PASS: TestReadProxyHead (8.68s)1375=== CONT TestOrphanedObjectsGCStressTest13762026-10-01 09:49:13.410 UTC [80654] ERROR: relation "goose_db_version" does not exist at character 3613772026-10-01 09:49:13.410 UTC [80654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1378--- PASS: TestReadProxyInvalidPath (8.36s)1379=== CONT TestOrphanedObjectsGC13802026/10/01 09:49:14 OK 20241026095416_initial_model.sql (480.25ms)13812026/10/01 09:49:14 OK 20251210153512_drop_unused_gin_index.sql (34.69ms)13822026/10/01 09:49:14 OK 20251218171726_add_pins.sql (79.59ms)13832026/10/01 09:49:14 OK 20260628120000_add_object_size_and_stats.sql (77.97ms)13842026-10-01 09:49:14.394 UTC [80667] ERROR: relation "goose_db_version" does not exist at character 3613852026-10-01 09:49:14.394 UTC [80667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13862026/10/01 09:49:14 OK 20260905000000_add_claims.sql (127.31ms)1387--- PASS: TestReadProxy404 (8.24s)1388=== CONT TestObjectStatsTrigger13892026/10/01 09:49:14 OK 20260920000000_drop_claims.sql (157.62ms)13902026/10/01 09:49:14 OK 20260923120000_add_pushes.sql (37.03ms)13912026/10/01 09:49:14 goose: successfully migrated database to version: 2026092312000013922026/10/01 09:49:14 OK 1_commit_pending_closure.sql (1.4ms)13932026/10/01 09:49:14 OK 2_object_stats_trigger.sql (334.5µs)13942026/10/01 09:49:14 OK 3_commit_push.sql (260.33µs)13952026/10/01 09:49:14 goose: up to current file version: 313962026/10/01 09:49:15 OK 20241026095416_initial_model.sql (572.88ms)13972026/10/01 09:49:15 OK 20251210153512_drop_unused_gin_index.sql (27.73ms)13982026/10/01 09:49:15 OK 20251218171726_add_pins.sql (93.61ms)13992026/10/01 09:49:15 OK 20260628120000_add_object_size_and_stats.sql (94.56ms)1400--- PASS: TestReadProxyNarStreaming (8.07s)1401=== CONT TestPendingCleanupUsesOneCutoff14022026/10/01 09:49:15 OK 20260905000000_add_claims.sql (170.66ms)14032026/10/01 09:49:15 OK 20260920000000_drop_claims.sql (154.31ms)14042026/10/01 09:49:15 OK 20260923120000_add_pushes.sql (71.89ms)14052026/10/01 09:49:15 goose: successfully migrated database to version: 2026092312000014062026/10/01 09:49:15 OK 1_commit_pending_closure.sql (2.86ms)14072026/10/01 09:49:15 OK 2_object_stats_trigger.sql (557.71µs)14082026/10/01 09:49:15 OK 3_commit_push.sql (469.92µs)14092026/10/01 09:49:15 goose: up to current file version: 314102026-10-01 09:49:16.098 UTC [80682] ERROR: relation "goose_db_version" does not exist at character 3614112026-10-01 09:49:16.098 UTC [80682] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1412--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.95s)1413=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded14142026-10-01 09:49:16.658 UTC [80685] ERROR: relation "goose_db_version" does not exist at character 3614152026-10-01 09:49:16.658 UTC [80685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14162026/10/01 09:49:16 OK 20241026095416_initial_model.sql (562.21ms)14172026/10/01 09:49:16 OK 20251210153512_drop_unused_gin_index.sql (43.8ms)14182026/10/01 09:49:16 OK 20251218171726_add_pins.sql (70.05ms)14192026/10/01 09:49:17 OK 20260628120000_add_object_size_and_stats.sql (104.76ms)14202026/10/01 09:49:17 OK 20260905000000_add_claims.sql (146.45ms)14212026/10/01 09:49:17 OK 20241026095416_initial_model.sql (443.04ms)14222026/10/01 09:49:17 OK 20251210153512_drop_unused_gin_index.sql (29.83ms)14232026/10/01 09:49:17 OK 20260920000000_drop_claims.sql (113.59ms)14242026/10/01 09:49:17 OK 20251218171726_add_pins.sql (73.37ms)14252026/10/01 09:49:17 OK 20260923120000_add_pushes.sql (36.44ms)14262026/10/01 09:49:17 goose: successfully migrated database to version: 2026092312000014272026/10/01 09:49:17 OK 1_commit_pending_closure.sql (1.51ms)14282026/10/01 09:49:17 OK 2_object_stats_trigger.sql (324.04µs)14292026/10/01 09:49:17 OK 3_commit_push.sql (293.71µs)14302026/10/01 09:49:17 goose: up to current file version: 314312026-10-01 09:49:17.425 UTC [80691] ERROR: relation "goose_db_version" does not exist at character 3614322026-10-01 09:49:17.425 UTC [80691] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14332026/10/01 09:49:17 OK 20260628120000_add_object_size_and_stats.sql (77.79ms)14342026/10/01 09:49:17 OK 20260905000000_add_claims.sql (153.37ms)14352026/10/01 09:49:17 OK 20260920000000_drop_claims.sql (145.48ms)14362026/10/01 09:49:17 OK 20260923120000_add_pushes.sql (42.04ms)14372026/10/01 09:49:17 goose: successfully migrated database to version: 2026092312000014382026/10/01 09:49:17 OK 1_commit_pending_closure.sql (2.71ms)14392026/10/01 09:49:17 OK 2_object_stats_trigger.sql (552.33µs)14402026/10/01 09:49:17 OK 3_commit_push.sql (312.96µs)14412026/10/01 09:49:17 goose: up to current file version: 314422026/10/01 09:49:18 OK 20241026095416_initial_model.sql (490.08ms)14432026/10/01 09:49:18 OK 20251210153512_drop_unused_gin_index.sql (43.54ms)1444--- PASS: TestReadProxyNarinfo (8.47s)1445=== CONT TestMultipartCleanup14462026/10/01 09:49:18 OK 20251218171726_add_pins.sql (79.67ms)14472026/10/01 09:49:18 OK 20260628120000_add_object_size_and_stats.sql (82.53ms)14482026/10/01 09:49:18 OK 20260905000000_add_claims.sql (156.76ms)14492026/10/01 09:49:18 OK 20260920000000_drop_claims.sql (138.42ms)14502026/10/01 09:49:18 OK 20260923120000_add_pushes.sql (40.74ms)14512026/10/01 09:49:18 goose: successfully migrated database to version: 2026092312000014522026/10/01 09:49:18 OK 1_commit_pending_closure.sql (1.02ms)14532026/10/01 09:49:18 OK 2_object_stats_trigger.sql (253.83µs)14542026/10/01 09:49:18 OK 3_commit_push.sql (202.79µs)14552026/10/01 09:49:18 goose: up to current file version: 314562026-10-01 09:49:18.671 UTC [80708] ERROR: relation "goose_db_version" does not exist at character 3614572026-10-01 09:49:18.671 UTC [80708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14582026/10/01 09:49:18 INFO Starting HTTP server address=/nix/var/nix/builds/nix-79549-3801637548/TestProxyHeadersOnlyTrustedOnSocket2902037414/001/proxy.sock14592026/10/01 09:49:18 INFO Starting HTTP server address=127.0.0.1:5393214602026/10/01 09:49:18 WARN mTLS auth: subject not in bound subjects subject="CN=someone"14612026/10/01 09:49:18 INFO Shutdown signal received, draining in-flight requests timeout=10s1462--- PASS: TestProxyHeadersOnlyTrustedOnSocket (8.34s)1463=== CONT TestServerTLSConfig1464=== RUN TestServerTLSConfig/no_client_CA1465=== PAUSE TestServerTLSConfig/no_client_CA1466=== RUN TestServerTLSConfig/missing_CA_file1467=== PAUSE TestServerTLSConfig/missing_CA_file1468=== RUN TestServerTLSConfig/not_a_PEM_file1469=== PAUSE TestServerTLSConfig/not_a_PEM_file1470=== CONT TestService_NativeMTLS14712026/10/01 09:49:19 OK 20241026095416_initial_model.sql (474.42ms)14722026/10/01 09:49:19 OK 20251210153512_drop_unused_gin_index.sql (37.77ms)14732026/10/01 09:49:19 OK 20251218171726_add_pins.sql (80.21ms)14742026/10/01 09:49:19 OK 20260628120000_add_object_size_and_stats.sql (248.39ms)14752026-10-01 09:49:19.753 UTC [80720] ERROR: relation "goose_db_version" does not exist at character 3614762026-10-01 09:49:19.753 UTC [80720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14772026/10/01 09:49:19 OK 20260905000000_add_claims.sql (153.85ms)14782026/10/01 09:49:19 OK 20260920000000_drop_claims.sql (147.9ms)14792026/10/01 09:49:20 OK 20260923120000_add_pushes.sql (43.66ms)14802026/10/01 09:49:20 goose: successfully migrated database to version: 2026092312000014812026/10/01 09:49:20 OK 1_commit_pending_closure.sql (1.8ms)14822026/10/01 09:49:20 OK 2_object_stats_trigger.sql (407.29µs)14832026/10/01 09:49:20 OK 3_commit_push.sql (293.88µs)14842026/10/01 09:49:20 goose: up to current file version: 31485--- PASS: TestPresentNotReportedWhileGCDeletesClosure (9.13s)1486=== CONT TestMetricsInventory14872026-10-01 09:49:20.303 UTC [80725] ERROR: relation "goose_db_version" does not exist at character 3614882026-10-01 09:49:20.303 UTC [80725] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14892026/10/01 09:49:20 OK 20241026095416_initial_model.sql (572.51ms)14902026/10/01 09:49:20 OK 20251210153512_drop_unused_gin_index.sql (44.58ms)14912026/10/01 09:49:20 OK 20251218171726_add_pins.sql (58.47ms)14922026/10/01 09:49:20 OK 20260628120000_add_object_size_and_stats.sql (86.83ms)1493--- PASS: TestPresentReportsOnlyClosureRoots (8.55s)1494=== CONT TestNARDeduplicationMetadataUploadBug14952026/10/01 09:49:20 OK 20260905000000_add_claims.sql (146.7ms)14962026/10/01 09:49:20 OK 20260920000000_drop_claims.sql (81.08ms)14972026-10-01 09:49:20.907 UTC [80739] ERROR: relation "goose_db_version" does not exist at character 3614982026-10-01 09:49:20.907 UTC [80739] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14992026/10/01 09:49:20 OK 20241026095416_initial_model.sql (448.38ms)15002026/10/01 09:49:20 OK 20260923120000_add_pushes.sql (38.6ms)15012026/10/01 09:49:20 goose: successfully migrated database to version: 2026092312000015022026/10/01 09:49:20 OK 1_commit_pending_closure.sql (1.57ms)15032026/10/01 09:49:20 OK 2_object_stats_trigger.sql (341.96µs)15042026/10/01 09:49:20 OK 3_commit_push.sql (292.29µs)15052026/10/01 09:49:20 goose: up to current file version: 315062026/10/01 09:49:20 OK 20251210153512_drop_unused_gin_index.sql (31.55ms)15072026/10/01 09:49:21 OK 20251218171726_add_pins.sql (63.89ms)15082026/10/01 09:49:21 OK 20260628120000_add_object_size_and_stats.sql (87.6ms)15092026/10/01 09:49:21 OK 20260905000000_add_claims.sql (149.01ms)15102026/10/01 09:49:21 OK 20260920000000_drop_claims.sql (105.21ms)15112026/10/01 09:49:21 OK 20241026095416_initial_model.sql (393.73ms)15122026/10/01 09:49:21 OK 20260923120000_add_pushes.sql (51.38ms)15132026/10/01 09:49:21 goose: successfully migrated database to version: 2026092312000015142026/10/01 09:49:21 OK 1_commit_pending_closure.sql (2.19ms)15152026/10/01 09:49:21 OK 2_object_stats_trigger.sql (444.29µs)15162026/10/01 09:49:21 OK 3_commit_push.sql (374.29µs)15172026/10/01 09:49:21 goose: up to current file version: 315182026/10/01 09:49:21 OK 20251210153512_drop_unused_gin_index.sql (24.14ms)15192026/10/01 09:49:21 OK 20251218171726_add_pins.sql (68.56ms)15202026/10/01 09:49:21 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15212026/10/01 09:49:21 WARN Refused reserved pin name=worker-x86_64-linux15222026/10/01 09:49:21 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15232026/10/01 09:49:21 INFO Received create pin request method=POST path=/api/pins/my-app15242026/10/01 09:49:21 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15252026-10-01 09:49:21.518 UTC [80743] ERROR: relation "goose_db_version" does not exist at character 3615262026-10-01 09:49:21.518 UTC [80743] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1527--- PASS: TestCreatePin_ReservedPins (8.84s)1528=== CONT TestGCSweepSkipsPendingObjects15292026/10/01 09:49:21 OK 20260628120000_add_object_size_and_stats.sql (98.96ms)15302026/10/01 09:49:21 OK 20260905000000_add_claims.sql (173.55ms)15312026/10/01 09:49:21 OK 20260920000000_drop_claims.sql (103.41ms)15322026/10/01 09:49:21 OK 20260923120000_add_pushes.sql (27.49ms)15332026/10/01 09:49:21 goose: successfully migrated database to version: 2026092312000015342026/10/01 09:49:21 OK 1_commit_pending_closure.sql (1.99ms)15352026/10/01 09:49:21 OK 2_object_stats_trigger.sql (460.63µs)15362026/10/01 09:49:21 OK 3_commit_push.sql (296.38µs)15372026/10/01 09:49:21 goose: up to current file version: 315382026-10-01 09:49:22.058 UTC [80749] ERROR: relation "goose_db_version" does not exist at character 3615392026-10-01 09:49:22.058 UTC [80749] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15402026/10/01 09:49:22 OK 20241026095416_initial_model.sql (447.51ms)15412026/10/01 09:49:22 OK 20251210153512_drop_unused_gin_index.sql (11.63ms)15422026/10/01 09:49:22 OK 20251218171726_add_pins.sql (49.82ms)15432026/10/01 09:49:22 OK 20260628120000_add_object_size_and_stats.sql (111.11ms)15442026/10/01 09:49:22 OK 20260905000000_add_claims.sql (175.7ms)15452026/10/01 09:49:22 OK 20260920000000_drop_claims.sql (168.19ms)15462026/10/01 09:49:22 OK 20260923120000_add_pushes.sql (233.22ms)15472026/10/01 09:49:22 goose: successfully migrated database to version: 2026092312000015482026/10/01 09:49:22 OK 1_commit_pending_closure.sql (3.59ms)15492026/10/01 09:49:22 OK 2_object_stats_trigger.sql (675.88µs)15502026/10/01 09:49:22 OK 3_commit_push.sql (447.79µs)15512026/10/01 09:49:22 goose: up to current file version: 315522026/10/01 09:49:22 OK 20241026095416_initial_model.sql (680.86ms)15532026/10/01 09:49:22 OK 20251210153512_drop_unused_gin_index.sql (23.22ms)15542026/10/01 09:49:23 OK 20251218171726_add_pins.sql (88.24ms)15552026/10/01 09:49:23 OK 20260628120000_add_object_size_and_stats.sql (146.84ms)15562026-10-01 09:49:23.300 UTC [80754] ERROR: relation "goose_db_version" does not exist at character 3615572026-10-01 09:49:23.300 UTC [80754] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15582026/10/01 09:49:23 OK 20260905000000_add_claims.sql (225.7ms)15592026/10/01 09:49:23 OK 20260920000000_drop_claims.sql (134.58ms)15602026/10/01 09:49:23 OK 20260923120000_add_pushes.sql (49.55ms)15612026/10/01 09:49:23 goose: successfully migrated database to version: 2026092312000015622026/10/01 09:49:23 OK 1_commit_pending_closure.sql (3.19ms)15632026/10/01 09:49:23 OK 2_object_stats_trigger.sql (521.75µs)15642026/10/01 09:49:23 OK 3_commit_push.sql (385.33µs)15652026/10/01 09:49:23 goose: up to current file version: 31566--- PASS: TestObjectStatsTrigger (9.33s)1567=== CONT TestCacheConfigHandlerMaxNarSize1568--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1569=== CONT TestGenerateLandingPage1570--- PASS: TestGenerateLandingPage (0.00s)1571=== CONT TestService_readinessHandler15722026/10/01 09:49:24 OK 20241026095416_initial_model.sql (546.4ms)15732026/10/01 09:49:24 OK 20251210153512_drop_unused_gin_index.sql (29.03ms)15742026/10/01 09:49:24 OK 20251218171726_add_pins.sql (62.85ms)15752026/10/01 09:49:24 OK 20260628120000_add_object_size_and_stats.sql (120.05ms)15762026/10/01 09:49:24 INFO Received uploads request method=POST path=/api/pending_closures15772026/10/01 09:49:24 OK 20260905000000_add_claims.sql (187.29ms)15782026/10/01 09:49:24 OK 20260920000000_drop_claims.sql (67.86ms)15792026/10/01 09:49:24 OK 20260923120000_add_pushes.sql (40.86ms)15802026/10/01 09:49:24 goose: successfully migrated database to version: 2026092312000015812026/10/01 09:49:24 OK 1_commit_pending_closure.sql (4.05ms)15822026/10/01 09:49:24 OK 2_object_stats_trigger.sql (275.5µs)15832026/10/01 09:49:24 OK 3_commit_push.sql (228.38µs)15842026/10/01 09:49:24 goose: up to current file version: 315852026/10/01 09:49:24 INFO Received uploads request method=POST path=/api/pending_closures1586=== NAME TestOrphanedObjectsGC1587 orphaned_objects_gc_test.go:290: GC Test Summary:1588 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1589 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1590 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1591 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1592 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1593--- PASS: TestOrphanedObjectsGC (10.84s)1594=== CONT TestService_healthCheckHandler15952026/10/01 09:49:24 INFO Received cleanup request method=DELETE path=/api/pending_closures15962026-10-01 09:49:24.716 UTC [80780] ERROR: relation "goose_db_version" does not exist at character 3615972026-10-01 09:49:24.716 UTC [80780] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15982026/10/01 09:49:25 INFO Received uploads request method=POST path=/api/pending_closures15992026/10/01 09:49:25 OK 20241026095416_initial_model.sql (472.43ms)16002026/10/01 09:49:25 OK 20251210153512_drop_unused_gin_index.sql (19.04ms)1601--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (8.81s)1602=== CONT TestGracefulShutdownDrainsInflight16032026/10/01 09:49:25 INFO Starting HTTP server address=127.0.0.1:5403616042026/10/01 09:49:25 INFO Shutdown signal received, draining in-flight requests timeout=10s16052026-10-01 09:49:25.389 UTC [80797] ERROR: relation "goose_db_version" does not exist at character 3616062026-10-01 09:49:25.389 UTC [80797] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1607--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1608=== CONT TestGCTaskStore_Fail1609--- PASS: TestGCTaskStore_Fail (0.00s)1610=== CONT TestGCTaskStore_PhaseUpdates1611--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1612=== CONT TestGCTaskStore_CompletedAllowsNewTask1613--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1614=== CONT TestGCTaskStore_GetReturnsLatest1615--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1616=== CONT TestGCTaskStore_GetEmpty1617--- PASS: TestGCTaskStore_GetEmpty (0.00s)1618=== CONT TestGCTaskStore_ConflictDifferentParams1619--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1620=== CONT TestGCTaskStore_DeduplicateSameParams1621--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1622=== CONT TestGCTaskStore_StartNew1623--- PASS: TestGCTaskStore_StartNew (0.00s)1624=== CONT TestGCEndsOnShutdown16252026/10/01 09:49:25 OK 20251218171726_add_pins.sql (80.63ms)16262026/10/01 09:49:25 OK 20260628120000_add_object_size_and_stats.sql (99.79ms)16272026/10/01 09:49:25 OK 20260905000000_add_claims.sql (167.69ms)16282026/10/01 09:49:25 OK 20260920000000_drop_claims.sql (117.32ms)16292026/10/01 09:49:25 OK 20260923120000_add_pushes.sql (54.6ms)16302026/10/01 09:49:25 goose: successfully migrated database to version: 2026092312000016312026/10/01 09:49:25 OK 1_commit_pending_closure.sql (3.1ms)16322026/10/01 09:49:25 OK 2_object_stats_trigger.sql (627.21µs)16332026/10/01 09:49:25 OK 3_commit_push.sql (363.83µs)16342026/10/01 09:49:25 goose: up to current file version: 316352026/10/01 09:49:26 OK 20241026095416_initial_model.sql (508.75ms)16362026/10/01 09:49:26 OK 20251210153512_drop_unused_gin_index.sql (35.41ms)16372026/10/01 09:49:26 OK 20251218171726_add_pins.sql (79.14ms)16382026/10/01 09:49:26 OK 20260628120000_add_object_size_and_stats.sql (139.23ms)16392026/10/01 09:49:26 OK 20260905000000_add_claims.sql (264.37ms)16402026/10/01 09:49:26 INFO Received uploads request method=POST path=/api/pending_closures16412026/10/01 09:49:26 OK 20260920000000_drop_claims.sql (132.88ms)16422026/10/01 09:49:26 OK 20260923120000_add_pushes.sql (33.24ms)16432026/10/01 09:49:26 goose: successfully migrated database to version: 2026092312000016442026/10/01 09:49:26 OK 1_commit_pending_closure.sql (1.61ms)16452026/10/01 09:49:26 OK 2_object_stats_trigger.sql (399.38µs)16462026/10/01 09:49:26 OK 3_commit_push.sql (312.58µs)16472026/10/01 09:49:26 goose: up to current file version: 316482026-10-01 09:49:26.855 UTC [80810] ERROR: relation "goose_db_version" does not exist at character 3616492026-10-01 09:49:26.855 UTC [80810] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16502026/10/01 09:49:26 INFO Received cleanup request method=DELETE path=/api/pending_closures16512026/10/01 09:49:26 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket42/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""16522026/10/01 09:49:26 INFO Aborted multipart uploads count=0 kept=116532026/10/01 09:49:26 INFO Received cleanup request method=DELETE path=/api/pending_closures16542026/10/01 09:49:26 INFO Aborted multipart uploads count=1 kept=01655--- PASS: TestMultipartCleanup (8.78s)1656=== CONT TestCommitRacingPendingCleanupKeepsObjects16572026/10/01 09:49:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16582026/10/01 09:49:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1659--- PASS: TestService_NativeMTLS (8.62s)1660=== CONT TestPushWaitsForSweepHoldingRow16612026-10-01 09:49:27.507 UTC [80820] ERROR: relation "goose_db_version" does not exist at character 3616622026-10-01 09:49:27.507 UTC [80820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16632026/10/01 09:49:27 OK 20241026095416_initial_model.sql (642.41ms)16642026/10/01 09:49:27 OK 20251210153512_drop_unused_gin_index.sql (35.91ms)16652026/10/01 09:49:27 OK 20251218171726_add_pins.sql (67.09ms)16662026/10/01 09:49:27 OK 20260628120000_add_object_size_and_stats.sql (71.35ms)16672026/10/01 09:49:27 OK 20260905000000_add_claims.sql (139.59ms)16682026/10/01 09:49:28 OK 20260920000000_drop_claims.sql (142.02ms)16692026/10/01 09:49:28 OK 20260923120000_add_pushes.sql (58.86ms)16702026/10/01 09:49:28 goose: successfully migrated database to version: 2026092312000016712026/10/01 09:49:28 OK 1_commit_pending_closure.sql (3.53ms)16722026/10/01 09:49:28 OK 2_object_stats_trigger.sql (752.33µs)16732026/10/01 09:49:28 OK 3_commit_push.sql (441.21µs)16742026/10/01 09:49:28 goose: up to current file version: 316752026/10/01 09:49:28 OK 20241026095416_initial_model.sql (506.02ms)16762026/10/01 09:49:28 OK 20251210153512_drop_unused_gin_index.sql (24.3ms)16772026/10/01 09:49:28 OK 20251218171726_add_pins.sql (83.49ms)16782026/10/01 09:49:28 OK 20260628120000_add_object_size_and_stats.sql (118.3ms)16792026/10/01 09:49:28 OK 20260905000000_add_claims.sql (166.05ms)16802026/10/01 09:49:28 OK 20260920000000_drop_claims.sql (143.43ms)16812026/10/01 09:49:28 OK 20260923120000_add_pushes.sql (42.39ms)16822026/10/01 09:49:28 goose: successfully migrated database to version: 2026092312000016832026/10/01 09:49:28 OK 1_commit_pending_closure.sql (2.69ms)16842026/10/01 09:49:28 OK 2_object_stats_trigger.sql (612.75µs)16852026/10/01 09:49:28 OK 3_commit_push.sql (441.58µs)16862026/10/01 09:49:28 goose: up to current file version: 31687--- PASS: TestMetricsInventory (8.88s)1688=== CONT TestSweepRechecksPendingAfterLocking16892026-10-01 09:49:29.221 UTC [80837] ERROR: relation "goose_db_version" does not exist at character 3616902026-10-01 09:49:29.221 UTC [80837] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16912026/10/01 09:49:29 OK 20241026095416_initial_model.sql (391.96ms)16922026/10/01 09:49:29 OK 20251210153512_drop_unused_gin_index.sql (16.42ms)16932026/10/01 09:49:29 OK 20251218171726_add_pins.sql (56.47ms)16942026/10/01 09:49:29 OK 20260628120000_add_object_size_and_stats.sql (78.92ms)16952026/10/01 09:49:30 OK 20260905000000_add_claims.sql (133.14ms)16962026/10/01 09:49:30 OK 20260920000000_drop_claims.sql (105.04ms)16972026/10/01 09:49:30 OK 20260923120000_add_pushes.sql (28.25ms)16982026/10/01 09:49:30 goose: successfully migrated database to version: 2026092312000016992026/10/01 09:49:30 OK 1_commit_pending_closure.sql (1.63ms)17002026/10/01 09:49:30 OK 2_object_stats_trigger.sql (378.5µs)17012026/10/01 09:49:30 OK 3_commit_push.sql (326.04µs)17022026/10/01 09:49:30 goose: up to current file version: 31703=== NAME TestNARDeduplicationMetadataUploadBug1704 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-79549-3801637548/TestNARDeduplicationMetadataUploadBug1352495413/001/store/agyi9sf38y99j92srxsnnzb0d9ybripn-file1.txt17052026/10/01 09:49:30 INFO Received push request method=POST path=/api/pushes17062026/10/01 09:49:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17072026/10/01 09:49:30 INFO Uploading agyi9sf38y99j92srxsnnzb0d9ybripn-file1.txt (160B)17082026/10/01 09:49:30 WARN Failed to register uploaded object key=agyi9sf38y99j92srxsnnzb0d9ybripn.ls error="server returned 404: 404 page not found\n"17092026/10/01 09:49:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17102026/10/01 09:49:30 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17112026/10/01 09:49:30 INFO Signed narinfos id=1 count=117122026/10/01 09:49:30 INFO Uploading 1 narinfos17132026/10/01 09:49:30 WARN Failed to register uploaded object key=agyi9sf38y99j92srxsnnzb0d9ybripn.narinfo error="server returned 404: 404 page not found\n"17142026/10/01 09:49:30 INFO Received complete push request method=POST path=/api/pushes/1/complete17152026/10/01 09:49:30 INFO Upload complete. (330ms)1716 metadata_upload_test.go:54: Retrieved narinfo from S3:1717 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestNARDeduplicationMetadataUploadBug1352495413/001/store/agyi9sf38y99j92srxsnnzb0d9ybripn-file1.txt1718 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1719 Compression: zstd1720 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1721 NarSize: 1601722 References: 1723 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1724 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1725 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1726 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}17272026/10/01 09:49:30 INFO Aborted multipart uploads count=1 kept=017282026/10/01 09:49:30 INFO Received uploads request method=POST path=/api/pending_closures17292026/10/01 09:49:30 INFO Received cleanup request method=DELETE path=/api/pending_closures17302026/10/01 09:49:30 INFO Aborted multipart uploads count=1 kept=017312026-10-01 09:49:30.741 UTC [80865] ERROR: relation "goose_db_version" does not exist at character 3617322026-10-01 09:49:30.741 UTC [80865] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1733--- PASS: TestPendingCleanupUsesOneCutoff (15.26s)1734=== CONT TestGetExistingObjectsLocksRows17352026/10/01 09:49:30 INFO Aborted multipart uploads count=0 kept=017362026/10/01 09:49:30 WARN Force mode enabled - objects will be deleted immediately without grace period17372026/10/01 09:49:30 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=01738=== NAME TestNARDeduplicationMetadataUploadBug1739 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-79549-3801637548/TestNARDeduplicationMetadataUploadBug1352495413/001/store/d4b4fdwjsfi5z7y0k84p731l9aal75fk-file2.txt17402026/10/01 09:49:30 INFO Vacuumed table table=pending_closures17412026/10/01 09:49:30 INFO Vacuumed table table=pending_objects17422026/10/01 09:49:30 INFO Vacuumed table table=multipart_uploads17432026/10/01 09:49:30 INFO Vacuumed table table=closures17442026/10/01 09:49:30 INFO Received push request method=POST path=/api/pushes17452026/10/01 09:49:31 INFO Vacuumed table table=objects17462026/10/01 09:49:31 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17472026/10/01 09:49:31 WARN Failed to register uploaded object key=d4b4fdwjsfi5z7y0k84p731l9aal75fk.ls error="server returned 404: 404 page not found\n"17482026/10/01 09:49:31 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17492026/10/01 09:49:31 INFO Signed narinfos id=2 count=117502026/10/01 09:49:31 INFO Uploading 1 narinfos1751--- PASS: TestGCSweepSkipsPendingObjects (9.56s)1752=== CONT TestRegisterCompletedObjectNeedsPendingRow17532026/10/01 09:49:31 INFO Received complete push request method=POST path=/api/pushes/2/complete17542026/10/01 09:49:31 WARN Failed to register uploaded object key=d4b4fdwjsfi5z7y0k84p731l9aal75fk.narinfo error="server returned 404: 404 page not found\n"17552026/10/01 09:49:31 INFO Upload complete. (228ms)1756=== NAME TestNARDeduplicationMetadataUploadBug1757 metadata_upload_test.go:76: Retrieved narinfo from S3:1758 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestNARDeduplicationMetadataUploadBug1352495413/001/store/d4b4fdwjsfi5z7y0k84p731l9aal75fk-file2.txt1759 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1760 Compression: zstd1761 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1762 NarSize: 1601763 References: 1764 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1765 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1766 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1767 {"version":1,"root":{"type":"regular","size":44}}17682026-10-01 09:49:31.164 UTC [80872] ERROR: relation "goose_db_version" does not exist at character 3617692026-10-01 09:49:31.164 UTC [80872] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17702026/10/01 09:49:31 OK 20241026095416_initial_model.sql (420.76ms)17712026/10/01 09:49:31 OK 20251210153512_drop_unused_gin_index.sql (14.6ms)1772--- PASS: TestNARDeduplicationMetadataUploadBug (10.61s)1773=== CONT TestSweepSkipsRowsLockedByPush17742026/10/01 09:49:31 OK 20251218171726_add_pins.sql (39.89ms)17752026/10/01 09:49:31 OK 20260628120000_add_object_size_and_stats.sql (77.16ms)17762026/10/01 09:49:31 OK 20260905000000_add_claims.sql (51.39ms)17772026-10-01 09:49:31.529 UTC [80885] ERROR: relation "goose_db_version" does not exist at character 3617782026-10-01 09:49:31.529 UTC [80885] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17792026/10/01 09:49:31 OK 20260920000000_drop_claims.sql (90.52ms)17802026/10/01 09:49:31 OK 20241026095416_initial_model.sql (268.44ms)17812026/10/01 09:49:31 OK 20251210153512_drop_unused_gin_index.sql (22.06ms)17822026/10/01 09:49:31 OK 20260923120000_add_pushes.sql (32.57ms)17832026/10/01 09:49:31 goose: successfully migrated database to version: 2026092312000017842026/10/01 09:49:31 OK 1_commit_pending_closure.sql (2.82ms)17852026/10/01 09:49:31 OK 2_object_stats_trigger.sql (455.13µs)17862026/10/01 09:49:31 OK 3_commit_push.sql (359.83µs)17872026/10/01 09:49:31 goose: up to current file version: 317882026/10/01 09:49:31 OK 20251218171726_add_pins.sql (57.6ms)17892026/10/01 09:49:31 OK 20260628120000_add_object_size_and_stats.sql (86.38ms)17902026/10/01 09:49:31 OK 20260905000000_add_claims.sql (160.2ms)17912026/10/01 09:49:32 OK 20260920000000_drop_claims.sql (128.57ms)17922026/10/01 09:49:32 OK 20260923120000_add_pushes.sql (44.91ms)17932026/10/01 09:49:32 goose: successfully migrated database to version: 2026092312000017942026/10/01 09:49:32 OK 1_commit_pending_closure.sql (6.07ms)17952026/10/01 09:49:32 OK 2_object_stats_trigger.sql (2.64ms)17962026/10/01 09:49:32 OK 3_commit_push.sql (587.58µs)17972026/10/01 09:49:32 goose: up to current file version: 317982026/10/01 09:49:32 OK 20241026095416_initial_model.sql (411.45ms)17992026/10/01 09:49:32 OK 20251210153512_drop_unused_gin_index.sql (25.18ms)18002026/10/01 09:49:32 WARN readiness check failed error="closed pool"1801--- PASS: TestService_readinessHandler (8.35s)1802=== CONT TestFailedS3DeleteKeepsTombstone18032026/10/01 09:49:32 OK 20251218171726_add_pins.sql (73.13ms)18042026/10/01 09:49:32 OK 20260628120000_add_object_size_and_stats.sql (67.25ms)18052026/10/01 09:49:32 OK 20260905000000_add_claims.sql (147.1ms)18062026/10/01 09:49:32 OK 20260920000000_drop_claims.sql (111.69ms)18072026/10/01 09:49:32 OK 20260923120000_add_pushes.sql (49.91ms)18082026/10/01 09:49:32 goose: successfully migrated database to version: 2026092312000018092026/10/01 09:49:32 OK 1_commit_pending_closure.sql (3.54ms)18102026/10/01 09:49:32 OK 2_object_stats_trigger.sql (972.71µs)18112026/10/01 09:49:32 OK 3_commit_push.sql (679.63µs)18122026/10/01 09:49:32 goose: up to current file version: 31813--- PASS: TestService_healthCheckHandler (8.21s)1814=== CONT TestForceGCDuringPushOffersSweptObject1815=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1816=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1817=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1818=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1819=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection18202026-10-01 09:49:32.991 UTC [80896] ERROR: relation "goose_db_version" does not exist at character 3618212026-10-01 09:49:32.991 UTC [80896] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18222026-10-01 09:49:33.262 UTC [80901] ERROR: relation "goose_db_version" does not exist at character 3618232026-10-01 09:49:33.262 UTC [80901] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1824--- PASS: TestGCEndsOnShutdown (8.14s)1825=== CONT TestGCSweepDeliversEachKeyOnce18262026/10/01 09:49:33 OK 20241026095416_initial_model.sql (507.82ms)18272026/10/01 09:49:33 OK 20251210153512_drop_unused_gin_index.sql (24.13ms)18282026/10/01 09:49:33 OK 20251218171726_add_pins.sql (69.55ms)18292026/10/01 09:49:33 OK 20260628120000_add_object_size_and_stats.sql (87.29ms)18302026/10/01 09:49:33 OK 20241026095416_initial_model.sql (515.6ms)18312026/10/01 09:49:33 OK 20260905000000_add_claims.sql (156.32ms)18322026/10/01 09:49:33 OK 20251210153512_drop_unused_gin_index.sql (15.49ms)18332026/10/01 09:49:34 OK 20260920000000_drop_claims.sql (57.03ms)18342026/10/01 09:49:34 OK 20251218171726_add_pins.sql (52.33ms)18352026/10/01 09:49:34 OK 20260923120000_add_pushes.sql (42.89ms)18362026/10/01 09:49:34 goose: successfully migrated database to version: 2026092312000018372026/10/01 09:49:34 OK 1_commit_pending_closure.sql (3.04ms)18382026/10/01 09:49:34 OK 2_object_stats_trigger.sql (607.13µs)18392026/10/01 09:49:34 OK 3_commit_push.sql (410.67µs)18402026/10/01 09:49:34 goose: up to current file version: 318412026/10/01 09:49:34 OK 20260628120000_add_object_size_and_stats.sql (91.96ms)18422026/10/01 09:49:34 OK 20260905000000_add_claims.sql (166.27ms)18432026/10/01 09:49:34 OK 20260920000000_drop_claims.sql (167.33ms)18442026/10/01 09:49:34 OK 20260923120000_add_pushes.sql (44.71ms)18452026/10/01 09:49:34 goose: successfully migrated database to version: 2026092312000018462026/10/01 09:49:34 OK 1_commit_pending_closure.sql (4.34ms)18472026/10/01 09:49:34 OK 2_object_stats_trigger.sql (2.83ms)18482026/10/01 09:49:34 OK 3_commit_push.sql (1.31ms)18492026/10/01 09:49:34 goose: up to current file version: 318502026/10/01 09:49:35 INFO Aborted multipart uploads count=0 kept=018512026/10/01 09:49:35 WARN Force mode enabled - objects will be deleted immediately without grace period18522026/10/01 09:49: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=018532026-10-01 09:49:35.098 UTC [80916] ERROR: relation "goose_db_version" does not exist at character 3618542026-10-01 09:49:35.098 UTC [80916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18552026/10/01 09:49:35 INFO Vacuumed table table=pending_closures18562026/10/01 09:49:35 INFO Vacuumed table table=pending_objects18572026/10/01 09:49:35 INFO Vacuumed table table=multipart_uploads18582026/10/01 09:49:35 INFO Vacuumed table table=closures18592026/10/01 09:49:35 INFO Vacuumed table table=objects1860--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.26s)1861=== CONT TestTombstonedObjectOfferedWithoutWaiting18622026/10/01 09:49:35 INFO Received uploads request method=POST path=/api/pending_closures18632026/10/01 09:49:35 OK 20241026095416_initial_model.sql (360.93ms)18642026/10/01 09:49:35 OK 20251210153512_drop_unused_gin_index.sql (20.55ms)18652026/10/01 09:49:35 OK 20251218171726_add_pins.sql (46.23ms)18662026/10/01 09:49:35 OK 20260628120000_add_object_size_and_stats.sql (72.43ms)18672026/10/01 09:49:35 OK 20260905000000_add_claims.sql (91.99ms)1868--- PASS: TestPushWaitsForSweepHoldingRow (8.48s)1869=== CONT TestClientWithDependencies18702026/10/01 09:49:35 OK 20260920000000_drop_claims.sql (84.06ms)18712026/10/01 09:49:35 OK 20260923120000_add_pushes.sql (19.15ms)18722026/10/01 09:49:35 goose: successfully migrated database to version: 2026092312000018732026/10/01 09:49:35 OK 1_commit_pending_closure.sql (5.37ms)18742026/10/01 09:49:35 OK 2_object_stats_trigger.sql (490.63µs)18752026/10/01 09:49:35 OK 3_commit_push.sql (344.58µs)18762026/10/01 09:49:35 goose: up to current file version: 318772026-10-01 09:49:36.379 UTC [80930] ERROR: relation "goose_db_version" does not exist at character 3618782026-10-01 09:49:36.379 UTC [80930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18792026/10/01 09:49:36 INFO Aborted multipart uploads count=0 kept=018802026/10/01 09:49:36 WARN Force mode enabled - objects will be deleted immediately without grace period1881=== NAME TestOrphanedObjectsGCStressTest1882 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains18832026/10/01 09:49:36 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=01884 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion18852026/10/01 09:49:36 INFO Vacuumed table table=pending_closures18862026/10/01 09:49:36 OK 20241026095416_initial_model.sql (401.49ms)18872026/10/01 09:49:36 OK 20251210153512_drop_unused_gin_index.sql (16.29ms)18882026/10/01 09:49:36 INFO Vacuumed table table=pending_objects18892026/10/01 09:49:36 INFO Vacuumed table table=multipart_uploads18902026/10/01 09:49:36 INFO Vacuumed table table=closures18912026-10-01 09:49:36.972 UTC [80940] ERROR: relation "goose_db_version" does not exist at character 3618922026-10-01 09:49:36.972 UTC [80940] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18932026/10/01 09:49:36 INFO Vacuumed table table=objects18942026/10/01 09:49:36 OK 20251218171726_add_pins.sql (44.3ms)1895--- PASS: TestSweepRechecksPendingAfterLocking (7.92s)1896=== CONT TestDeduplicatedObjectsRecordedAsPending18972026/10/01 09:49:37 OK 20260628120000_add_object_size_and_stats.sql (61.39ms)18982026/10/01 09:49:37 OK 20260905000000_add_claims.sql (92.14ms)18992026-10-01 09:49:37.200 UTC [80945] ERROR: relation "goose_db_version" does not exist at character 3619002026-10-01 09:49:37.200 UTC [80945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19012026/10/01 09:49:37 OK 20260920000000_drop_claims.sql (75.2ms)19022026/10/01 09:49:37 OK 20260923120000_add_pushes.sql (6.75ms)19032026/10/01 09:49:37 goose: successfully migrated database to version: 2026092312000019042026/10/01 09:49:37 OK 1_commit_pending_closure.sql (1.02ms)19052026/10/01 09:49:37 OK 2_object_stats_trigger.sql (255.29µs)19062026/10/01 09:49:37 OK 3_commit_push.sql (197µs)19072026/10/01 09:49:37 goose: up to current file version: 319082026/10/01 09:49:37 OK 20241026095416_initial_model.sql (257.96ms)19092026/10/01 09:49:37 OK 20251210153512_drop_unused_gin_index.sql (19.41ms)19102026/10/01 09:49:37 OK 20251218171726_add_pins.sql (46.84ms)19112026/10/01 09:49:37 OK 20260628120000_add_object_size_and_stats.sql (66.08ms)19122026-10-01 09:49:37.488 UTC [80948] ERROR: relation "goose_db_version" does not exist at character 3619132026-10-01 09:49:37.488 UTC [80948] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19142026/10/01 09:49:37 OK 20260905000000_add_claims.sql (52.45ms)19152026/10/01 09:49:37 OK 20241026095416_initial_model.sql (267.73ms)19162026/10/01 09:49:37 OK 20251210153512_drop_unused_gin_index.sql (20.69ms)19172026/10/01 09:49:37 OK 20260920000000_drop_claims.sql (76.13ms)19182026/10/01 09:49:37 OK 20260923120000_add_pushes.sql (33.9ms)19192026/10/01 09:49:37 goose: successfully migrated database to version: 2026092312000019202026/10/01 09:49:37 OK 1_commit_pending_closure.sql (857.92µs)19212026/10/01 09:49:37 OK 2_object_stats_trigger.sql (243.75µs)19222026/10/01 09:49:37 OK 3_commit_push.sql (172.54µs)19232026/10/01 09:49:37 goose: up to current file version: 319242026/10/01 09:49:37 OK 20251218171726_add_pins.sql (44.55ms)1925--- PASS: TestGetExistingObjectsLocksRows (6.92s)1926=== CONT TestPushDedupSurvivesConcurrentGC19272026/10/01 09:49:37 OK 20260628120000_add_object_size_and_stats.sql (67.26ms)19282026-10-01 09:49:37.784 UTC [80954] ERROR: relation "goose_db_version" does not exist at character 3619292026-10-01 09:49:37.784 UTC [80954] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19302026/10/01 09:49:37 OK 20260905000000_add_claims.sql (112.23ms)19312026/10/01 09:49:37 OK 20260920000000_drop_claims.sql (73.03ms)19322026/10/01 09:49:37 OK 20260923120000_add_pushes.sql (23.37ms)19332026/10/01 09:49:37 goose: successfully migrated database to version: 2026092312000019342026/10/01 09:49:37 OK 1_commit_pending_closure.sql (997.33µs)19352026/10/01 09:49:37 OK 2_object_stats_trigger.sql (229.29µs)19362026/10/01 09:49:37 OK 3_commit_push.sql (166.88µs)19372026/10/01 09:49:37 goose: up to current file version: 319382026/10/01 09:49:37 OK 20241026095416_initial_model.sql (354.25ms)19392026/10/01 09:49:37 OK 20251210153512_drop_unused_gin_index.sql (22.38ms)19402026/10/01 09:49:38 OK 20251218171726_add_pins.sql (45.71ms)19412026/10/01 09:49:38 OK 20260628120000_add_object_size_and_stats.sql (88.03ms)1942--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.06s)1943=== CONT TestGCMetrics19442026/10/01 09:49:38 OK 20260905000000_add_claims.sql (169.13ms)19452026/10/01 09:49:38 OK 20241026095416_initial_model.sql (451.11ms)19462026/10/01 09:49:38 OK 20251210153512_drop_unused_gin_index.sql (14.98ms)19472026/10/01 09:49:38 OK 20260920000000_drop_claims.sql (101.63ms)19482026/10/01 09:49:38 OK 20260923120000_add_pushes.sql (24.05ms)19492026/10/01 09:49:38 goose: successfully migrated database to version: 2026092312000019502026/10/01 09:49:38 OK 20251218171726_add_pins.sql (44.83ms)19512026/10/01 09:49:38 OK 1_commit_pending_closure.sql (5ms)19522026/10/01 09:49:38 OK 2_object_stats_trigger.sql (535.33µs)19532026/10/01 09:49:38 OK 3_commit_push.sql (373.17µs)19542026/10/01 09:49:38 goose: up to current file version: 319552026/10/01 09:49:38 OK 20260628120000_add_object_size_and_stats.sql (103.39ms)19562026/10/01 09:49:38 OK 20260905000000_add_claims.sql (141.37ms)19572026-10-01 09:49:38.706 UTC [80973] ERROR: relation "goose_db_version" does not exist at character 3619582026-10-01 09:49:38.706 UTC [80973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19592026/10/01 09:49:38 OK 20260920000000_drop_claims.sql (94.09ms)19602026/10/01 09:49:38 OK 20260923120000_add_pushes.sql (41.93ms)19612026/10/01 09:49:38 goose: successfully migrated database to version: 2026092312000019622026/10/01 09:49:38 OK 1_commit_pending_closure.sql (1.15ms)19632026/10/01 09:49:38 OK 2_object_stats_trigger.sql (290.25µs)19642026/10/01 09:49:38 OK 3_commit_push.sql (234.46µs)19652026/10/01 09:49:38 goose: up to current file version: 319662026/10/01 09:49:38 INFO Aborted multipart uploads count=0 kept=019672026/10/01 09:49:38 WARN Force mode enabled - objects will be deleted immediately without grace period19682026/10/01 09:49:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019692026/10/01 09:49:38 INFO Vacuumed table table=pending_closures19702026/10/01 09:49:38 INFO Vacuumed table table=pending_objects19712026/10/01 09:49:38 INFO Vacuumed table table=multipart_uploads19722026/10/01 09:49:38 INFO Vacuumed table table=closures19732026/10/01 09:49:38 INFO Vacuumed table table=objects19742026/10/01 09:49:38 INFO Aborted multipart uploads count=0 kept=019752026/10/01 09:49:38 WARN Force mode enabled - objects will be deleted immediately without grace period19762026/10/01 09:49:39 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=019772026/10/01 09:49:39 INFO Vacuumed table table=pending_closures19782026/10/01 09:49:39 INFO Vacuumed table table=pending_objects19792026/10/01 09:49:39 INFO Vacuumed table table=multipart_uploads19802026/10/01 09:49:39 INFO Vacuumed table table=closures19812026/10/01 09:49:39 INFO Vacuumed table table=objects1982--- PASS: TestSweepSkipsRowsLockedByPush (7.90s)1983=== CONT TestGCBugBareHashReferences19842026/10/01 09:49:39 OK 20241026095416_initial_model.sql (439.92ms)19852026/10/01 09:49:39 INFO Received uploads request method=POST path=/api/pending_closures19862026/10/01 09:49:39 OK 20251210153512_drop_unused_gin_index.sql (17.74ms)19872026/10/01 09:49:39 OK 20251218171726_add_pins.sql (64.7ms)19882026/10/01 09:49:39 OK 20260628120000_add_object_size_and_stats.sql (84.36ms)19892026/10/01 09:49:39 INFO Aborted multipart uploads count=0 kept=019902026/10/01 09:49:39 WARN Force mode enabled - objects will be deleted immediately without grace period19912026/10/01 09:49:39 OK 20260905000000_add_claims.sql (190.63ms)19922026/10/01 09:49:39 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."19932026/10/01 09:49:39 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1994--- PASS: TestFailedS3DeleteKeepsTombstone (7.48s)1995=== CONT TestLeadEndsOnShutdown19962026/10/01 09:49:39 OK 20260920000000_drop_claims.sql (88.32ms)19972026/10/01 09:49:39 OK 20260923120000_add_pushes.sql (132.97ms)19982026/10/01 09:49:39 goose: successfully migrated database to version: 2026092312000019992026/10/01 09:49:39 OK 1_commit_pending_closure.sql (1.45ms)20002026/10/01 09:49:39 OK 2_object_stats_trigger.sql (320.92µs)20012026/10/01 09:49:39 OK 3_commit_push.sql (209.96µs)20022026/10/01 09:49:39 goose: up to current file version: 320032026/10/01 09:49:39 INFO Received uploads request method=POST path=/api/pending_closures20042026-10-01 09:49:39.974 UTC [81002] ERROR: relation "goose_db_version" does not exist at character 3620052026-10-01 09:49:39.974 UTC [81002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2006--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.28s)2007=== CONT TestLeadElectsOneAndHandsOver20082026-10-01 09:49:40.225 UTC [81010] ERROR: relation "goose_db_version" does not exist at character 3620092026-10-01 09:49:40.225 UTC [81010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20102026/10/01 09:49:40 OK 20241026095416_initial_model.sql (294.44ms)20112026/10/01 09:49:40 OK 20251210153512_drop_unused_gin_index.sql (28.71ms)20122026/10/01 09:49:40 INFO Aborted multipart uploads count=0 kept=020132026/10/01 09:49:40 OK 20251218171726_add_pins.sql (71.6ms)20142026/10/01 09:49:40 WARN Force mode enabled - objects will be deleted immediately without grace period20152026/10/01 09:49:40 OK 20260628120000_add_object_size_and_stats.sql (62.21ms)20162026/10/01 09:49:40 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=020172026/10/01 09:49:40 INFO Vacuumed table table=pending_closures20182026/10/01 09:49:40 INFO Vacuumed table table=pending_objects20192026/10/01 09:49:40 INFO Vacuumed table table=multipart_uploads20202026/10/01 09:49:40 INFO Vacuumed table table=closures20212026/10/01 09:49:40 OK 20260905000000_add_claims.sql (116.82ms)20222026/10/01 09:49:40 INFO Vacuumed table table=objects2023--- PASS: TestGCSweepDeliversEachKeyOnce (7.13s)2024=== CONT TestResolveDBConnectionString20252026/10/01 09:49:40 OK 20260920000000_drop_claims.sql (73.94ms)2026=== RUN TestResolveDBConnectionString/flag_wins2027=== PAUSE TestResolveDBConnectionString/flag_wins2028=== RUN TestResolveDBConnectionString/file_when_flag_empty2029=== PAUSE TestResolveDBConnectionString/file_when_flag_empty2030=== RUN TestResolveDBConnectionString/missing_file_is_an_error2031=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error2032=== RUN TestResolveDBConnectionString/PGHOST_allows_empty2033=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty2034=== RUN TestResolveDBConnectionString/nothing_configured2035=== PAUSE TestResolveDBConnectionString/nothing_configured2036=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock20372026/10/01 09:49:40 OK 20241026095416_initial_model.sql (402.19ms)20382026/10/01 09:49:40 OK 20260923120000_add_pushes.sql (50.83ms)20392026/10/01 09:49:40 goose: successfully migrated database to version: 2026092312000020402026/10/01 09:49:40 OK 1_commit_pending_closure.sql (1.26ms)20412026/10/01 09:49:40 OK 2_object_stats_trigger.sql (334.21µs)20422026/10/01 09:49:40 OK 3_commit_push.sql (230.83µs)20432026/10/01 09:49:40 goose: up to current file version: 320442026/10/01 09:49:40 OK 20251210153512_drop_unused_gin_index.sql (18.81ms)20452026/10/01 09:49:40 OK 20251218171726_add_pins.sql (86.06ms)20462026/10/01 09:49:40 OK 20260628120000_add_object_size_and_stats.sql (95.56ms)20472026/10/01 09:49:41 OK 20260905000000_add_claims.sql (143.4ms)20482026/10/01 09:49:41 OK 20260920000000_drop_claims.sql (91.02ms)20492026/10/01 09:49:41 OK 20260923120000_add_pushes.sql (44.06ms)20502026/10/01 09:49:41 goose: successfully migrated database to version: 2026092312000020512026/10/01 09:49:41 OK 1_commit_pending_closure.sql (2.46ms)20522026/10/01 09:49:41 OK 2_object_stats_trigger.sql (389.33µs)20532026/10/01 09:49:41 OK 3_commit_push.sql (271.92µs)20542026/10/01 09:49:41 goose: up to current file version: 320552026/10/01 09:49:41 INFO Received uploads request method=POST path=/api/pending_closures2056--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.25s)2057=== CONT TestClientFallsBackToClosures20582026-10-01 09:49:41.778 UTC [81030] ERROR: relation "goose_db_version" does not exist at character 3620592026-10-01 09:49:41.778 UTC [81030] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20602026/10/01 09:49:42 OK 20241026095416_initial_model.sql (319.72ms)20612026/10/01 09:49:42 OK 20251210153512_drop_unused_gin_index.sql (19.37ms)20622026/10/01 09:49:42 OK 20251218171726_add_pins.sql (49.41ms)20632026/10/01 09:49:42 OK 20260628120000_add_object_size_and_stats.sql (53.08ms)20642026/10/01 09:49:42 OK 20260905000000_add_claims.sql (136.47ms)20652026-10-01 09:49:42.694 UTC [81040] ERROR: relation "goose_db_version" does not exist at character 3620662026-10-01 09:49:42.694 UTC [81040] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20672026/10/01 09:49:42 OK 20260920000000_drop_claims.sql (97.43ms)20682026/10/01 09:49:42 OK 20260923120000_add_pushes.sql (30.82ms)20692026/10/01 09:49:42 goose: successfully migrated database to version: 2026092312000020702026/10/01 09:49:42 OK 1_commit_pending_closure.sql (871.17µs)20712026/10/01 09:49:42 OK 2_object_stats_trigger.sql (258.54µs)20722026/10/01 09:49:42 OK 3_commit_push.sql (210µs)20732026/10/01 09:49:42 goose: up to current file version: 32074=== NAME TestClientWithDependencies2075 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-79549-3801637548/TestClientWithDependencies3245314282/001/store/53ki1yc7ahi033bdqd6b83rd2fq0nsxy-test-script2076 client_integration_test.go:615: Found 1 dependencies (including self)20772026/10/01 09:49:43 INFO Received push request method=POST path=/api/pushes20782026/10/01 09:49:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20792026/10/01 09:49:43 INFO Uploading 53ki1yc7ahi033bdqd6b83rd2fq0nsxy-test-script (136B)20802026-10-01 09:49:43.168 UTC [81048] ERROR: relation "goose_db_version" does not exist at character 3620812026-10-01 09:49:43.168 UTC [81048] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20822026/10/01 09:49:43 WARN Failed to register uploaded object key=53ki1yc7ahi033bdqd6b83rd2fq0nsxy.ls error="server returned 404: 404 page not found\n"20832026/10/01 09:49:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"20842026/10/01 09:49:43 WARN Failed to register uploaded object key=log/h1sa9rfz1j826fy1dzp83991rpwrm7zm-test-script.drv error="server returned 404: 404 page not found\n"20852026/10/01 09:49:43 OK 20241026095416_initial_model.sql (423.86ms)20862026/10/01 09:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20872026/10/01 09:49:43 INFO Signed narinfos id=1 count=120882026/10/01 09:49:43 INFO Uploading 1 narinfos20892026/10/01 09:49:43 OK 20251210153512_drop_unused_gin_index.sql (22.96ms)20902026/10/01 09:49:43 INFO Received complete push request method=POST path=/api/pushes/1/complete20912026/10/01 09:49:43 INFO Received uploads request method=POST path=/api/pending_closures20922026/10/01 09:49:43 WARN Failed to register uploaded object key=53ki1yc7ahi033bdqd6b83rd2fq0nsxy.narinfo error="server returned 404: 404 page not found\n"20932026/10/01 09:49:43 OK 20251218171726_add_pins.sql (70.83ms)20942026/10/01 09:49:43 INFO Upload complete. (388ms)2095 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-79549-3801637548/TestClientWithDependencies3245314282/001/store) requires matching store prefix2096--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.37s)2097=== CONT TestClientPushesUseOnePush20982026/10/01 09:49:43 OK 20260628120000_add_object_size_and_stats.sql (84.36ms)20992026/10/01 09:49:43 OK 20260905000000_add_claims.sql (111.8ms)2100--- PASS: TestClientWithDependencies (7.67s)2101=== CONT TestPinProtectsFromGC21022026/10/01 09:49:43 OK 20260920000000_drop_claims.sql (97.28ms)21032026/10/01 09:49:43 OK 20260923120000_add_pushes.sql (32.29ms)21042026/10/01 09:49:43 goose: successfully migrated database to version: 2026092312000021052026/10/01 09:49:43 OK 1_commit_pending_closure.sql (994.04µs)21062026/10/01 09:49:43 OK 2_object_stats_trigger.sql (246.08µs)21072026/10/01 09:49:43 OK 3_commit_push.sql (184.83µs)21082026/10/01 09:49:43 goose: up to current file version: 321092026/10/01 09:49:43 OK 20241026095416_initial_model.sql (380.08ms)21102026/10/01 09:49:43 OK 20251210153512_drop_unused_gin_index.sql (18.03ms)21112026/10/01 09:49:43 OK 20251218171726_add_pins.sql (45.47ms)21122026/10/01 09:49:43 OK 20260628120000_add_object_size_and_stats.sql (65.42ms)21132026/10/01 09:49:43 OK 20260905000000_add_claims.sql (145.27ms)21142026/10/01 09:49:44 OK 20260920000000_drop_claims.sql (104.33ms)21152026/10/01 09:49:44 OK 20260923120000_add_pushes.sql (26.14ms)21162026/10/01 09:49:44 goose: successfully migrated database to version: 2026092312000021172026/10/01 09:49:44 OK 1_commit_pending_closure.sql (945.29µs)21182026/10/01 09:49:44 OK 2_object_stats_trigger.sql (238.92µs)21192026/10/01 09:49:44 OK 3_commit_push.sql (212.58µs)21202026/10/01 09:49:44 goose: up to current file version: 321212026-10-01 09:49:44.112 UTC [81100] ERROR: relation "goose_db_version" does not exist at character 3621222026-10-01 09:49:44.112 UTC [81100] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21232026/10/01 09:49:44 INFO Received uploads request method=POST path=/api/pending_closures21242026/10/01 09:49:44 INFO Aborted multipart uploads count=0 kept=021252026/10/01 09:49:44 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=021262026/10/01 09:49:44 INFO Vacuumed table table=pending_closures21272026-10-01 09:49:44.693 UTC [81134] ERROR: relation "goose_db_version" does not exist at character 3621282026-10-01 09:49:44.693 UTC [81134] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21292026/10/01 09:49:44 INFO Vacuumed table table=pending_objects21302026/10/01 09:49:44 INFO Vacuumed table table=multipart_uploads21312026/10/01 09:49:44 OK 20241026095416_initial_model.sql (507.02ms)2132=== NAME TestOrphanedObjectsGCStressTest2133 orphaned_objects_gc_test.go:509: Stress test completed successfully:2134 orphaned_objects_gc_test.go:510: - Active objects preserved: 202135 orphaned_objects_gc_test.go:511: - Objects deleted: 2102136 orphaned_objects_gc_test.go:512: - Total GC'd: 2102137--- PASS: TestOrphanedObjectsGCStressTest (31.50s)2138=== CONT TestClientSharedPathCommittedMidPush21392026/10/01 09:49:44 OK 20251210153512_drop_unused_gin_index.sql (16.86ms)21402026/10/01 09:49:44 INFO Vacuumed table table=closures21412026/10/01 09:49:44 INFO Aborted multipart uploads count=0 kept=021422026/10/01 09:49:44 WARN Force mode enabled - objects will be deleted immediately without grace period21432026/10/01 09:49:44 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=021442026/10/01 09:49:44 INFO Vacuumed table table=pending_closures21452026/10/01 09:49:44 INFO Vacuumed table table=pending_objects21462026/10/01 09:49:44 OK 20251218171726_add_pins.sql (63.98ms)21472026/10/01 09:49:44 INFO Vacuumed table table=multipart_uploads21482026/10/01 09:49:44 INFO Vacuumed table table=closures21492026/10/01 09:49:44 INFO Vacuumed table table=objects2150--- PASS: TestGCMetrics (6.70s)2151=== CONT TestCacheConfigHandler2152=== RUN TestCacheConfigHandler/full_config,_no_issuer2153=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2154=== RUN TestCacheConfigHandler/no_cache_url_configured2155=== PAUSE TestCacheConfigHandler/no_cache_url_configured2156=== RUN TestCacheConfigHandler/no_signing_keys2157=== PAUSE TestCacheConfigHandler/no_signing_keys2158=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2159=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2160=== CONT TestClientMultipleUploads21612026/10/01 09:49:44 INFO Vacuumed table table=objects21622026/10/01 09:49:44 INFO Aborted multipart uploads count=0 kept=021632026/10/01 09:49:44 WARN Force mode enabled - objects will be deleted immediately without grace period21642026/10/01 09:49:44 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=021652026/10/01 09:49:44 OK 20260628120000_add_object_size_and_stats.sql (61.28ms)21662026/10/01 09:49:44 INFO Vacuumed table table=pending_closures21672026/10/01 09:49:44 INFO Vacuumed table table=pending_objects21682026/10/01 09:49:44 INFO Vacuumed table table=multipart_uploads21692026/10/01 09:49:45 INFO Vacuumed table table=closures21702026/10/01 09:49:45 OK 20260905000000_add_claims.sql (131.68ms)21712026/10/01 09:49:45 INFO Vacuumed table table=objects2172--- PASS: TestPushDedupSurvivesConcurrentGC (7.37s)2173=== CONT TestClientIntegration21742026/10/01 09:49:45 OK 20260920000000_drop_claims.sql (68.13ms)21752026-10-01 09:49:45.102 UTC [81172] ERROR: relation "goose_db_version" does not exist at character 3621762026-10-01 09:49:45.102 UTC [81172] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21772026/10/01 09:49:45 OK 20260923120000_add_pushes.sql (13.46ms)21782026/10/01 09:49:45 goose: successfully migrated database to version: 2026092312000021792026/10/01 09:49:45 OK 1_commit_pending_closure.sql (953.54µs)21802026/10/01 09:49:45 OK 2_object_stats_trigger.sql (1.42ms)21812026/10/01 09:49:45 OK 20241026095416_initial_model.sql (294.08ms)21822026/10/01 09:49:45 OK 3_commit_push.sql (293.46µs)21832026/10/01 09:49:45 goose: up to current file version: 321842026/10/01 09:49:45 OK 20251210153512_drop_unused_gin_index.sql (28.22ms)21852026/10/01 09:49:45 OK 20251218171726_add_pins.sql (70.76ms)21862026/10/01 09:49:45 OK 20260628120000_add_object_size_and_stats.sql (86.79ms)21872026/10/01 09:49:45 OK 20260905000000_add_claims.sql (141.72ms)21882026-10-01 09:49:45.506 UTC [81182] ERROR: relation "goose_db_version" does not exist at character 3621892026-10-01 09:49:45.506 UTC [81182] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21902026/10/01 09:49:45 OK 20260920000000_drop_claims.sql (89.84ms)21912026/10/01 09:49:45 OK 20260923120000_add_pushes.sql (37.26ms)21922026/10/01 09:49:45 goose: successfully migrated database to version: 2026092312000021932026/10/01 09:49:45 OK 1_commit_pending_closure.sql (916.13µs)21942026/10/01 09:49:45 OK 2_object_stats_trigger.sql (222.88µs)21952026/10/01 09:49:45 OK 3_commit_push.sql (198µs)21962026/10/01 09:49:45 goose: up to current file version: 321972026/10/01 09:49:45 OK 20241026095416_initial_model.sql (366.75ms)21982026/10/01 09:49:45 OK 20251210153512_drop_unused_gin_index.sql (19.57ms)21992026/10/01 09:49:45 OK 20251218171726_add_pins.sql (56.66ms)22002026/10/01 09:49:45 OK 20260628120000_add_object_size_and_stats.sql (68.99ms)22012026/10/01 09:49:45 OK 20260905000000_add_claims.sql (129.96ms)2202--- PASS: TestGCBugBareHashReferences (6.67s)2203=== CONT TestClientErrorHandling2204=== RUN TestClientErrorHandling/InvalidStorePath2205=== PAUSE TestClientErrorHandling/InvalidStorePath2206=== RUN TestClientErrorHandling/InvalidAuthToken2207=== PAUSE TestClientErrorHandling/InvalidAuthToken2208=== RUN TestClientErrorHandling/ServerNotAvailable2209=== PAUSE TestClientErrorHandling/ServerNotAvailable2210=== CONT TestClientCADerivations22112026/10/01 09:49:45 OK 20260920000000_drop_claims.sql (83.56ms)22122026/10/01 09:49:45 OK 20260923120000_add_pushes.sql (21.97ms)22132026/10/01 09:49:45 goose: successfully migrated database to version: 2026092312000022142026/10/01 09:49:45 OK 1_commit_pending_closure.sql (1.84ms)22152026/10/01 09:49:45 OK 2_object_stats_trigger.sql (235.92µs)22162026/10/01 09:49:45 OK 3_commit_push.sql (177.25µs)22172026/10/01 09:49:45 goose: up to current file version: 322182026/10/01 09:49:45 OK 20241026095416_initial_model.sql (369.96ms)22192026/10/01 09:49:46 OK 20251210153512_drop_unused_gin_index.sql (29.77ms)22202026/10/01 09:49:46 INFO lead: acquired remote=192.0.2.1:123422212026/10/01 09:49:46 INFO lead: released remote=192.0.2.1:12342222--- PASS: TestLeadEndsOnShutdown (6.37s)2223=== CONT TestCacheStatsHandler22242026/10/01 09:49:46 OK 20251218171726_add_pins.sql (78.78ms)22252026/10/01 09:49:46 OK 20260628120000_add_object_size_and_stats.sql (68.67ms)22262026-10-01 09:49:46.170 UTC [81199] ERROR: relation "goose_db_version" does not exist at character 3622272026-10-01 09:49:46.170 UTC [81199] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22282026/10/01 09:49:46 OK 20260905000000_add_claims.sql (125.47ms)22292026/10/01 09:49:46 OK 20260920000000_drop_claims.sql (94.19ms)22302026/10/01 09:49:46 OK 20260923120000_add_pushes.sql (22.28ms)22312026/10/01 09:49:46 goose: successfully migrated database to version: 2026092312000022322026/10/01 09:49:46 OK 1_commit_pending_closure.sql (1ms)22332026/10/01 09:49:46 OK 2_object_stats_trigger.sql (243.29µs)22342026/10/01 09:49:46 OK 3_commit_push.sql (188.25µs)22352026/10/01 09:49:46 goose: up to current file version: 322362026/10/01 09:49:46 INFO lead: acquired remote=192.0.2.1:123422372026/10/01 09:49:46 OK 20241026095416_initial_model.sql (364.25ms)22382026/10/01 09:49:46 OK 20251210153512_drop_unused_gin_index.sql (4.17ms)22392026/10/01 09:49:46 INFO lead: released remote=192.0.2.1:123422402026/10/01 09:49:46 OK 20251218171726_add_pins.sql (69.44ms)22412026/10/01 09:49:46 INFO lead: acquired remote=192.0.2.1:123422422026/10/01 09:49:46 INFO lead: released remote=192.0.2.1:12342243--- PASS: TestLeadElectsOneAndHandsOver (6.62s)2244=== CONT TestService_AuthMiddleware_OIDC22452026/10/01 09:49:46 OK 20260628120000_add_object_size_and_stats.sql (54.37ms)22462026/10/01 09:49:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54278/oidc22472026/10/01 09:49:46 OK 20260905000000_add_claims.sql (193.12ms)22482026/10/01 09:49:47 OK 20260920000000_drop_claims.sql (70.27ms)22492026/10/01 09:49:47 OK 20260923120000_add_pushes.sql (29.1ms)22502026/10/01 09:49:47 goose: successfully migrated database to version: 2026092312000022512026/10/01 09:49:47 OK 1_commit_pending_closure.sql (1.82ms)22522026/10/01 09:49:47 OK 2_object_stats_trigger.sql (827.08µs)22532026/10/01 09:49:47 OK 3_commit_push.sql (2.4ms)22542026/10/01 09:49:47 goose: up to current file version: 322552026-10-01 09:49:47.819 UTC [81260] ERROR: relation "goose_db_version" does not exist at character 3622562026-10-01 09:49:47.819 UTC [81260] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22572026-10-01 09:49:48.016 UTC [81267] ERROR: relation "goose_db_version" does not exist at character 3622582026-10-01 09:49:48.016 UTC [81267] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22592026/10/01 09:49:48 OK 20241026095416_initial_model.sql (232.26ms)22602026/10/01 09:49:48 OK 20251210153512_drop_unused_gin_index.sql (10.45ms)22612026/10/01 09:49:48 OK 20251218171726_add_pins.sql (14.93ms)22622026/10/01 09:49:48 OK 20260628120000_add_object_size_and_stats.sql (103.9ms)22632026/10/01 09:49:48 OK 20241026095416_initial_model.sql (162.59ms)22642026/10/01 09:49:48 OK 20251210153512_drop_unused_gin_index.sql (16.35ms)22652026/10/01 09:49:48 OK 20251218171726_add_pins.sql (35.88ms)22662026/10/01 09:49:48 OK 20260905000000_add_claims.sql (83.7ms)22672026/10/01 09:49:48 OK 20260628120000_add_object_size_and_stats.sql (36.32ms)22682026/10/01 09:49:48 OK 20260920000000_drop_claims.sql (69.28ms)22692026-10-01 09:49:48.423 UTC [81287] ERROR: relation "goose_db_version" does not exist at character 3622702026-10-01 09:49:48.423 UTC [81287] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22712026/10/01 09:49:48 INFO Received uploads request method=POST path=/api/pending_closures22722026/10/01 09:49:48 OK 20260905000000_add_claims.sql (81.69ms)22732026/10/01 09:49:48 OK 20260923120000_add_pushes.sql (18.39ms)22742026/10/01 09:49:48 goose: successfully migrated database to version: 2026092312000022752026/10/01 09:49:48 OK 1_commit_pending_closure.sql (969.58µs)22762026/10/01 09:49:48 OK 2_object_stats_trigger.sql (250.21µs)22772026/10/01 09:49:48 OK 3_commit_push.sql (179.42µs)22782026/10/01 09:49:48 goose: up to current file version: 322792026/10/01 09:49:48 INFO Received uploads request method=POST path=/api/pending_closures22802026/10/01 09:49:48 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22812026/10/01 09:49:48 INFO Uploading z9ryys9gknzijvz3w42sk9763p77r795-shared-dep (136B)22822026/10/01 09:49:48 INFO Uploading dmvv2lxgs80sv5148kx0h57aq6j7g3hh-a (248B)22832026/10/01 09:49:48 OK 20260920000000_drop_claims.sql (57.37ms)22842026/10/01 09:49:48 WARN Failed to register uploaded object key=z9ryys9gknzijvz3w42sk9763p77r795.ls error="server returned 404: 404 page not found\n"22852026/10/01 09:49:48 WARN Failed to register uploaded object key=amx0cpby54g8a2s2jz6vla49xc8w9x9n.ls error="server returned 404: 404 page not found\n"22862026/10/01 09:49:48 WARN Failed to register uploaded object key=dmvv2lxgs80sv5148kx0h57aq6j7g3hh.ls error="server returned 404: 404 page not found\n"22872026/10/01 09:49:48 WARN Failed to register uploaded object key=nar/1zqaza1r4fylj3wsz3vyr6fl39i8x3rc9zxbkkd8lw1ij6cya8gx.nar.zst error="server returned 404: 404 page not found\n"22882026/10/01 09:49:48 OK 20260923120000_add_pushes.sql (31.59ms)22892026/10/01 09:49:48 goose: successfully migrated database to version: 2026092312000022902026/10/01 09:49:48 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22912026/10/01 09:49:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22922026/10/01 09:49:48 INFO Signed narinfos id=1 count=222932026/10/01 09:49:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22942026/10/01 09:49:48 INFO Signed narinfos id=2 count=222952026/10/01 09:49:48 INFO Uploading 4 narinfos22962026/10/01 09:49:48 OK 1_commit_pending_closure.sql (1.93ms)22972026/10/01 09:49:48 OK 2_object_stats_trigger.sql (387.71µs)22982026/10/01 09:49:48 OK 3_commit_push.sql (284.83µs)22992026/10/01 09:49:48 goose: up to current file version: 323002026/10/01 09:49:48 WARN Failed to register uploaded object key=amx0cpby54g8a2s2jz6vla49xc8w9x9n.narinfo error="server returned 404: 404 page not found\n"23012026/10/01 09:49:48 WARN Failed to register uploaded object key=dmvv2lxgs80sv5148kx0h57aq6j7g3hh.narinfo error="server returned 404: 404 page not found\n"23022026/10/01 09:49:48 WARN Failed to register uploaded object key=z9ryys9gknzijvz3w42sk9763p77r795.narinfo error="server returned 404: 404 page not found\n"2303--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.87s)2304=== CONT TestService_ReadScope_PublicByDefault23052026/10/01 09:49:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23062026/10/01 09:49:48 WARN Failed to register uploaded object key=z9ryys9gknzijvz3w42sk9763p77r795.narinfo error="server returned 404: 404 page not found\n"23072026/10/01 09:49:48 INFO Completed upload id=123082026/10/01 09:49:48 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete23092026/10/01 09:49:48 INFO Completed upload id=223102026/10/01 09:49:48 INFO Upload complete. (319ms)2311=== NAME TestClientFallsBackToClosures2312 client_pushes_test.go:112: Retrieved narinfo from S3:2313 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientFallsBackToClosures1044791467/001/store/z9ryys9gknzijvz3w42sk9763p77r795-shared-dep2314 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2315 Compression: zstd2316 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822317 NarSize: 1362318 References: 2319 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2320 client_pushes_test.go:112: Retrieved narinfo from S3:2321 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientFallsBackToClosures1044791467/001/store/dmvv2lxgs80sv5148kx0h57aq6j7g3hh-a2322 URL: nar/1zqaza1r4fylj3wsz3vyr6fl39i8x3rc9zxbkkd8lw1ij6cya8gx.nar.zst2323 Compression: zstd2324 NarHash: sha256:1zqaza1r4fylj3wsz3vyr6fl39i8x3rc9zxbkkd8lw1ij6cya8gx2325 NarSize: 2482326 References: /nix/var/nix/builds/nix-79549-3801637548/TestClientFallsBackToClosures1044791467/001/store/z9ryys9gknzijvz3w42sk9763p77r795-shared-dep2327 CA: text:sha256:1nd2pfaivlgaazi6snm2jll7b0wp1nxa8i831rfc0gxripripgnj2328 client_pushes_test.go:112: Retrieved narinfo from S3:2329 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientFallsBackToClosures1044791467/001/store/amx0cpby54g8a2s2jz6vla49xc8w9x9n-b2330 URL: nar/1zqaza1r4fylj3wsz3vyr6fl39i8x3rc9zxbkkd8lw1ij6cya8gx.nar.zst2331 Compression: zstd2332 NarHash: sha256:1zqaza1r4fylj3wsz3vyr6fl39i8x3rc9zxbkkd8lw1ij6cya8gx2333 NarSize: 2482334 References: /nix/var/nix/builds/nix-79549-3801637548/TestClientFallsBackToClosures1044791467/001/store/z9ryys9gknzijvz3w42sk9763p77r795-shared-dep2335 CA: text:sha256:1nd2pfaivlgaazi6snm2jll7b0wp1nxa8i831rfc0gxripripgnj23362026-10-01 09:49:48.718 UTC [81301] ERROR: relation "goose_db_version" does not exist at character 3623372026-10-01 09:49:48.718 UTC [81301] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2338--- PASS: TestClientFallsBackToClosures (7.29s)2339=== CONT TestService_RequireScope_OIDC23402026/10/01 09:49:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54342/oidc23412026/10/01 09:49:48 OK 20241026095416_initial_model.sql (307.1ms)23422026/10/01 09:49:48 OK 20251210153512_drop_unused_gin_index.sql (25.53ms)23432026/10/01 09:49:48 OK 20251218171726_add_pins.sql (40.33ms)23442026-10-01 09:49:48.927 UTC [81309] ERROR: relation "goose_db_version" does not exist at character 3623452026-10-01 09:49:48.927 UTC [81309] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23462026/10/01 09:49:48 OK 20260628120000_add_object_size_and_stats.sql (61.66ms)23472026/10/01 09:49:49 OK 20260905000000_add_claims.sql (119.93ms)23482026/10/01 09:49:49 OK 20260920000000_drop_claims.sql (58.24ms)23492026/10/01 09:49:49 OK 20260923120000_add_pushes.sql (25.35ms)23502026/10/01 09:49:49 goose: successfully migrated database to version: 2026092312000023512026/10/01 09:49:49 OK 1_commit_pending_closure.sql (1.01ms)23522026/10/01 09:49:49 OK 2_object_stats_trigger.sql (239.04µs)23532026/10/01 09:49:49 OK 3_commit_push.sql (205.46µs)23542026/10/01 09:49:49 goose: up to current file version: 323552026/10/01 09:49:49 OK 20241026095416_initial_model.sql (332.7ms)23562026/10/01 09:49:49 OK 20251210153512_drop_unused_gin_index.sql (25.33ms)23572026/10/01 09:49:49 OK 20251218171726_add_pins.sql (53.99ms)23582026/10/01 09:49:49 OK 20260628120000_add_object_size_and_stats.sql (56.79ms)23592026/10/01 09:49:49 OK 20241026095416_initial_model.sql (309.82ms)23602026/10/01 09:49:49 OK 20251210153512_drop_unused_gin_index.sql (9.45ms)23612026/10/01 09:49:49 OK 20260905000000_add_claims.sql (83ms)23622026/10/01 09:49:49 OK 20251218171726_add_pins.sql (43.98ms)23632026/10/01 09:49:49 OK 20260920000000_drop_claims.sql (63.85ms)23642026/10/01 09:49:49 OK 20260628120000_add_object_size_and_stats.sql (85.5ms)23652026/10/01 09:49:49 OK 20260923120000_add_pushes.sql (42.25ms)23662026/10/01 09:49:49 goose: successfully migrated database to version: 2026092312000023672026/10/01 09:49:49 OK 1_commit_pending_closure.sql (884.42µs)23682026/10/01 09:49:49 OK 2_object_stats_trigger.sql (259.5µs)23692026/10/01 09:49:49 OK 3_commit_push.sql (185.92µs)23702026/10/01 09:49:49 goose: up to current file version: 323712026/10/01 09:49:49 OK 20260905000000_add_claims.sql (72.59ms)23722026/10/01 09:49:49 OK 20260920000000_drop_claims.sql (40.44ms)23732026/10/01 09:49:49 OK 20260923120000_add_pushes.sql (22.51ms)23742026/10/01 09:49:49 goose: successfully migrated database to version: 2026092312000023752026/10/01 09:49:49 OK 1_commit_pending_closure.sql (2.18ms)23762026/10/01 09:49:49 OK 2_object_stats_trigger.sql (257.17µs)23772026/10/01 09:49:49 OK 3_commit_push.sql (1.83ms)23782026/10/01 09:49:49 goose: up to current file version: 323792026-10-01 09:49:49.702 UTC [81329] ERROR: relation "goose_db_version" does not exist at character 3623802026-10-01 09:49:49.702 UTC [81329] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23812026/10/01 09:49:49 INFO Received push request method=POST path=/api/pushes23822026-10-01 09:49:49.731 UTC [81331] ERROR: relation "goose_db_version" does not exist at character 3623832026-10-01 09:49:49.731 UTC [81331] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23842026/10/01 09:49:49 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23852026/10/01 09:49:49 INFO Uploading l68cg5m4fsyvk7l1zmm3crgd0048gjxy-b (248B)23862026/10/01 09:49:49 INFO Uploading w9f6b0c2b06jpcs836jss1gz59zl9n4k-shared-dep (136B)23872026/10/01 09:49:49 WARN Failed to register uploaded object key=l68cg5m4fsyvk7l1zmm3crgd0048gjxy.ls error="server returned 404: 404 page not found\n"2388=== NAME TestPinProtectsFromGC2389 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-79549-3801637548/TestPinProtectsFromGC4168366894/001/store/d0av9gigmq0c1cj1g5r42zxhj8ac8njd-pinned-file.txt2390 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-79549-3801637548/TestPinProtectsFromGC4168366894/001/store/g1bvaf1n4mjg8f6f9xwiibvnybd2x81l-unpinned-file.txt23912026/10/01 09:49:49 WARN Failed to register uploaded object key=w9f6b0c2b06jpcs836jss1gz59zl9n4k.ls error="server returned 404: 404 page not found\n"23922026/10/01 09:49:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23932026/10/01 09:49:49 WARN Failed to register uploaded object key=nar/0pmi6z4i5d3skpl60in4say0k4jfhsj9h4v2d9nzawfi5757dxfk.nar.zst error="server returned 404: 404 page not found\n"23942026/10/01 09:49:49 WARN Failed to register uploaded object key=4nbsshrf7dh3vf1pc2xc2x3ssk1ngxnb.ls error="server returned 404: 404 page not found\n"23952026/10/01 09:49:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23962026/10/01 09:49:49 INFO Signed narinfos id=1 count=323972026/10/01 09:49:49 INFO Uploading 3 narinfos23982026/10/01 09:49:49 WARN Failed to register uploaded object key=l68cg5m4fsyvk7l1zmm3crgd0048gjxy.narinfo error="server returned 404: 404 page not found\n"23992026/10/01 09:49:49 WARN Failed to register uploaded object key=4nbsshrf7dh3vf1pc2xc2x3ssk1ngxnb.narinfo error="server returned 404: 404 page not found\n"24002026/10/01 09:49:49 INFO Received complete push request method=POST path=/api/pushes/1/complete24012026/10/01 09:49:49 WARN Failed to register uploaded object key=w9f6b0c2b06jpcs836jss1gz59zl9n4k.narinfo error="server returned 404: 404 page not found\n"24022026/10/01 09:49:49 INFO Received push request method=POST path=/api/pushes24032026/10/01 09:49:49 INFO Upload complete. (270ms)2404=== NAME TestClientPushesUseOnePush2405 client_pushes_test.go:97: Retrieved narinfo from S3:2406 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientPushesUseOnePush2136483670/001/store/w9f6b0c2b06jpcs836jss1gz59zl9n4k-shared-dep2407 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2408 Compression: zstd2409 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822410 NarSize: 1362411 References: 2412 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2413 client_pushes_test.go:97: Retrieved narinfo from S3:2414 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientPushesUseOnePush2136483670/001/store/4nbsshrf7dh3vf1pc2xc2x3ssk1ngxnb-a2415 URL: nar/0pmi6z4i5d3skpl60in4say0k4jfhsj9h4v2d9nzawfi5757dxfk.nar.zst2416 Compression: zstd2417 NarHash: sha256:0pmi6z4i5d3skpl60in4say0k4jfhsj9h4v2d9nzawfi5757dxfk2418 NarSize: 2482419 References: /nix/var/nix/builds/nix-79549-3801637548/TestClientPushesUseOnePush2136483670/001/store/w9f6b0c2b06jpcs836jss1gz59zl9n4k-shared-dep2420 CA: text:sha256:0k9iii9j1y6k4xzhrqawqnlwj87sqbnr5vkl2vqwb42in2kv1p7v2421 client_pushes_test.go:97: Retrieved narinfo from S3:2422 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientPushesUseOnePush2136483670/001/store/l68cg5m4fsyvk7l1zmm3crgd0048gjxy-b2423 URL: nar/0pmi6z4i5d3skpl60in4say0k4jfhsj9h4v2d9nzawfi5757dxfk.nar.zst2424 Compression: zstd2425 NarHash: sha256:0pmi6z4i5d3skpl60in4say0k4jfhsj9h4v2d9nzawfi5757dxfk2426 NarSize: 2482427 References: /nix/var/nix/builds/nix-79549-3801637548/TestClientPushesUseOnePush2136483670/001/store/w9f6b0c2b06jpcs836jss1gz59zl9n4k-shared-dep2428 CA: text:sha256:0k9iii9j1y6k4xzhrqawqnlwj87sqbnr5vkl2vqwb42in2kv1p7v24292026/10/01 09:49:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24302026/10/01 09:49:49 INFO Uploading d0av9gigmq0c1cj1g5r42zxhj8ac8njd-pinned-file.txt (128B)24312026/10/01 09:49:49 WARN Failed to register uploaded object key=d0av9gigmq0c1cj1g5r42zxhj8ac8njd.ls error="server returned 404: 404 page not found\n"24322026/10/01 09:49:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24332026/10/01 09:49:49 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"24342026/10/01 09:49:49 INFO Signed narinfos id=1 count=124352026/10/01 09:49:49 INFO Uploading 1 narinfos24362026/10/01 09:49:50 INFO Received complete push request method=POST path=/api/pushes/1/complete24372026/10/01 09:49:50 WARN Failed to register uploaded object key=d0av9gigmq0c1cj1g5r42zxhj8ac8njd.narinfo error="server returned 404: 404 page not found\n"24382026/10/01 09:49:50 INFO Upload complete. (235ms)2439--- PASS: TestClientPushesUseOnePush (6.71s)2440=== CONT TestService_AuthMiddleware_MTLSBoundSubjects24412026/10/01 09:49:50 OK 20241026095416_initial_model.sql (327.14ms)24422026/10/01 09:49:50 OK 20251210153512_drop_unused_gin_index.sql (16.64ms)24432026/10/01 09:49:50 INFO Received push request method=POST path=/api/pushes24442026/10/01 09:49:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24452026/10/01 09:49:50 INFO Uploading g1bvaf1n4mjg8f6f9xwiibvnybd2x81l-unpinned-file.txt (128B)24462026/10/01 09:49:50 OK 20241026095416_initial_model.sql (319.12ms)24472026/10/01 09:49:50 OK 20251218171726_add_pins.sql (58ms)24482026/10/01 09:49:50 OK 20251210153512_drop_unused_gin_index.sql (14.76ms)24492026/10/01 09:49:50 WARN Failed to register uploaded object key=g1bvaf1n4mjg8f6f9xwiibvnybd2x81l.ls error="server returned 404: 404 page not found\n"24502026/10/01 09:49:50 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign24512026/10/01 09:49:50 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"24522026/10/01 09:49:50 INFO Signed narinfos id=2 count=124532026/10/01 09:49:50 INFO Uploading 1 narinfos24542026/10/01 09:49:50 INFO Received complete push request method=POST path=/api/pushes/2/complete24552026/10/01 09:49:50 WARN Failed to register uploaded object key=g1bvaf1n4mjg8f6f9xwiibvnybd2x81l.narinfo error="server returned 404: 404 page not found\n"24562026/10/01 09:49:50 INFO Upload complete. (166ms)24572026/10/01 09:49:50 OK 20251218171726_add_pins.sql (66.5ms)24582026/10/01 09:49:50 OK 20260628120000_add_object_size_and_stats.sql (88.97ms)24592026/10/01 09:49:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures24602026/10/01 09:49:50 INFO Garbage collection started24612026/10/01 09:49:50 INFO Aborted multipart uploads count=0 kept=024622026/10/01 09:49:50 WARN Force mode enabled - objects will be deleted immediately without grace period24632026/10/01 09:49:50 OK 20260628120000_add_object_size_and_stats.sql (85.56ms)24642026/10/01 09:49:50 OK 20260905000000_add_claims.sql (135.13ms)24652026/10/01 09:49:50 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=024662026/10/01 09:49:50 OK 20260905000000_add_claims.sql (136.1ms)24672026/10/01 09:49:50 INFO Received push request method=POST path=/api/pushes24682026/10/01 09:49:50 OK 20260920000000_drop_claims.sql (85.7ms)24692026/10/01 09:49:50 OK 20260923120000_add_pushes.sql (38.34ms)24702026/10/01 09:49:50 goose: successfully migrated database to version: 2026092312000024712026/10/01 09:49:50 OK 1_commit_pending_closure.sql (979.17µs)24722026/10/01 09:49:50 OK 2_object_stats_trigger.sql (227.46µs)24732026/10/01 09:49:50 OK 3_commit_push.sql (186.75µs)24742026/10/01 09:49:50 goose: up to current file version: 324752026/10/01 09:49:50 INFO Vacuumed table table=pending_closures24762026/10/01 09:49:50 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)24772026/10/01 09:49:50 INFO Uploading 0fhi98ihlnrs7rwd6j5kqsip7nybd57n-top (256B)24782026/10/01 09:49:50 INFO Uploading 2c5f2nl27ikdc5r55y3cr5hvbz2yj2kw-shared-dep (136B)24792026/10/01 09:49:50 OK 20260920000000_drop_claims.sql (102ms)24802026/10/01 09:49:50 WARN Failed to register uploaded object key=0fhi98ihlnrs7rwd6j5kqsip7nybd57n.ls error="server returned 404: 404 page not found\n"24812026/10/01 09:49:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24822026/10/01 09:49:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24832026/10/01 09:49:50 WARN Failed to register uploaded object key=nar/13lxizcc95b5jskf4bhrd8k92k8jp8p8qkg52is72han6lrzaj12.nar.zst error="server returned 404: 404 page not found\n"24842026/10/01 09:49:50 WARN Failed to register uploaded object key=2c5f2nl27ikdc5r55y3cr5hvbz2yj2kw.ls error="server returned 404: 404 page not found\n"24852026/10/01 09:49:50 INFO Signed narinfos id=1 count=224862026/10/01 09:49:50 INFO Uploading 2 narinfos24872026/10/01 09:49:50 OK 20260923120000_add_pushes.sql (18.75ms)24882026/10/01 09:49:50 goose: successfully migrated database to version: 2026092312000024892026/10/01 09:49:50 OK 1_commit_pending_closure.sql (2ms)24902026/10/01 09:49:50 OK 2_object_stats_trigger.sql (268.58µs)24912026/10/01 09:49:50 OK 3_commit_push.sql (221.92µs)24922026/10/01 09:49:50 goose: up to current file version: 324932026/10/01 09:49:50 INFO Vacuumed table table=pending_objects24942026/10/01 09:49:50 INFO Vacuumed table table=multipart_uploads24952026/10/01 09:49:50 INFO Received complete push request method=POST path=/api/pushes/1/complete24962026/10/01 09:49:50 WARN Failed to register uploaded object key=0fhi98ihlnrs7rwd6j5kqsip7nybd57n.narinfo error="server returned 404: 404 page not found\n"24972026/10/01 09:49:50 WARN Failed to register uploaded object key=2c5f2nl27ikdc5r55y3cr5hvbz2yj2kw.narinfo error="server returned 404: 404 page not found\n"24982026/10/01 09:49:50 INFO Vacuumed table table=closures24992026/10/01 09:49:50 INFO Upload complete. (261ms)2500=== NAME TestClientSharedPathCommittedMidPush2501 client_integration_test.go:680: Retrieved narinfo from S3:2502 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientSharedPathCommittedMidPush1527690483/001/store/2c5f2nl27ikdc5r55y3cr5hvbz2yj2kw-shared-dep2503 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2504 Compression: zstd2505 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822506 NarSize: 1362507 References: 2508 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2509 client_integration_test.go:680: Retrieved narinfo from S3:2510 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientSharedPathCommittedMidPush1527690483/001/store/0fhi98ihlnrs7rwd6j5kqsip7nybd57n-top2511 URL: nar/13lxizcc95b5jskf4bhrd8k92k8jp8p8qkg52is72han6lrzaj12.nar.zst2512 Compression: zstd2513 NarHash: sha256:13lxizcc95b5jskf4bhrd8k92k8jp8p8qkg52is72han6lrzaj122514 NarSize: 2562515 References: /nix/var/nix/builds/nix-79549-3801637548/TestClientSharedPathCommittedMidPush1527690483/001/store/2c5f2nl27ikdc5r55y3cr5hvbz2yj2kw-shared-dep2516 CA: text:sha256:0kjhzvwyll3vc26j70jiw7qx6kjb5j60yxzzkzg558mr1ia728f825172026/10/01 09:49:50 INFO Vacuumed table table=objects2518=== NAME TestClientMultipleUploads2519 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-79549-3801637548/TestClientMultipleUploads3923690526/001/store/c1cfl1yarjlsbilh64p24drx9cqi7g0k-test-file-0.txt25202026-10-01 09:49:50.735 UTC [81378] ERROR: relation "goose_db_version" does not exist at character 3625212026-10-01 09:49:50.735 UTC [81378] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2522--- PASS: TestClientSharedPathCommittedMidPush (6.09s)2523=== CONT TestService_ReadAuthMiddleware2524=== NAME TestClientMultipleUploads2525 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-79549-3801637548/TestClientMultipleUploads3923690526/001/store/flvh1m5c67jnv2czqjkijn58g88hdl65-test-file-1.txt2526=== NAME TestClientIntegration2527 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-79549-3801637548/TestClientIntegration2533082798/002/store/6837y0yby7wq6ckb4vkhy2qa190mljzi-test-file.txt2528=== NAME TestClientMultipleUploads2529 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-79549-3801637548/TestClientMultipleUploads3923690526/001/store/20sjf33nfdxf6n7vipzsvxac9cx9h6y8-test-file-2.txt2530--- PASS: TestCacheStatsHandler (5.07s)2531=== CONT TestService_AuthMiddleware_MTLSProxyHeader25322026/10/01 09:49:51 INFO Received push request method=POST path=/api/pushes25332026/10/01 09:49:51 INFO Received push request method=POST path=/api/pushes25342026/10/01 09:49:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25352026/10/01 09:49:51 INFO Uploading 6837y0yby7wq6ckb4vkhy2qa190mljzi-test-file.txt (152B)25362026/10/01 09:49:51 WARN Failed to register uploaded object key=6837y0yby7wq6ckb4vkhy2qa190mljzi.ls error="server returned 404: 404 page not found\n"25372026/10/01 09:49:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25382026/10/01 09:49:51 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)25392026/10/01 09:49:51 INFO Uploading 20sjf33nfdxf6n7vipzsvxac9cx9h6y8-test-file-2.txt (160B)25402026/10/01 09:49:51 INFO Uploading c1cfl1yarjlsbilh64p24drx9cqi7g0k-test-file-0.txt (160B)25412026/10/01 09:49:51 INFO Uploading flvh1m5c67jnv2czqjkijn58g88hdl65-test-file-1.txt (160B)25422026/10/01 09:49:51 INFO Signed narinfos id=1 count=125432026/10/01 09:49:51 INFO Uploading 1 narinfos25442026/10/01 09:49:51 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"25452026/10/01 09:49:51 OK 20241026095416_initial_model.sql (357.44ms)25462026/10/01 09:49:51 OK 20251210153512_drop_unused_gin_index.sql (11.76ms)25472026/10/01 09:49:51 WARN Failed to register uploaded object key=c1cfl1yarjlsbilh64p24drx9cqi7g0k.ls error="server returned 404: 404 page not found\n"25482026/10/01 09:49:51 INFO Received complete push request method=POST path=/api/pushes/1/complete25492026/10/01 09:49:51 WARN Failed to register uploaded object key=6837y0yby7wq6ckb4vkhy2qa190mljzi.narinfo error="server returned 404: 404 page not found\n"25502026/10/01 09:49:51 WARN Failed to register uploaded object key=flvh1m5c67jnv2czqjkijn58g88hdl65.ls error="server returned 404: 404 page not found\n"25512026/10/01 09:49:51 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"25522026/10/01 09:49:51 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"25532026/10/01 09:49:51 WARN Failed to register uploaded object key=20sjf33nfdxf6n7vipzsvxac9cx9h6y8.ls error="server returned 404: 404 page not found\n"25542026/10/01 09:49:51 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"25552026/10/01 09:49:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25562026/10/01 09:49:51 INFO Signed narinfos id=1 count=325572026/10/01 09:49:51 INFO Uploading 3 narinfos25582026/10/01 09:49:51 INFO Upload complete. (267ms)25592026/10/01 09:49:51 OK 20251218171726_add_pins.sql (52.4ms)25602026/10/01 09:49:51 WARN Failed to register uploaded object key=20sjf33nfdxf6n7vipzsvxac9cx9h6y8.narinfo error="server returned 404: 404 page not found\n"25612026/10/01 09:49:51 WARN Failed to register uploaded object key=flvh1m5c67jnv2czqjkijn58g88hdl65.narinfo error="server returned 404: 404 page not found\n"25622026/10/01 09:49:51 INFO Received complete push request method=POST path=/api/pushes/1/complete25632026/10/01 09:49:51 WARN Failed to register uploaded object key=c1cfl1yarjlsbilh64p24drx9cqi7g0k.narinfo error="server returned 404: 404 page not found\n"25642026/10/01 09:49:51 INFO All 1 paths already cached2565=== NAME TestClientIntegration2566 client_integration_test.go:312: Retrieved narinfo from S3:2567 StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientIntegration2533082798/002/store/6837y0yby7wq6ckb4vkhy2qa190mljzi-test-file.txt2568 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2569 Compression: zstd2570 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12571 NarSize: 1522572 References: 2573 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12574 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2575 client_integration_test.go:313: Decompressed .ls content (64 bytes):2576 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2577 client_integration_test.go:316: Testing garbage collection...25782026/10/01 09:49:51 OK 20260628120000_add_object_size_and_stats.sql (68.69ms)25792026/10/01 09:49:51 INFO Upload complete. (299ms)2580=== NAME TestClientMultipleUploads2581 client_integration_test.go:369: Uploaded 3 paths in 335.832834ms25822026/10/01 09:49:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures25832026/10/01 09:49:51 INFO Garbage collection started25842026/10/01 09:49:51 INFO Aborted multipart uploads count=0 kept=025852026/10/01 09:49:51 WARN Force mode enabled - objects will be deleted immediately without grace period25862026/10/01 09:49:51 OK 20260905000000_add_claims.sql (125.1ms)25872026/10/01 09:49:51 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=02588=== CONT TestProxyWriteTimeout/narinfo2589=== CONT TestProxyWriteTimeout/10_GiB_nar2590=== CONT TestProxyWriteTimeout/unknown_size2591=== CONT TestProxyWriteTimeout/1_GiB_nar2592=== CONT TestIsValidUploadKey/narinfo2593--- PASS: TestClientMultipleUploads (6.71s)2594=== CONT TestIsValidUploadKey/realisation_plus_in_output2595--- PASS: TestProxyWriteTimeout (0.00s)2596 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2597 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2598 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2599 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2600=== CONT TestIsValidUploadKey/unknown_type2601=== CONT TestIsValidUploadKey/empty_key2602=== CONT TestIsValidUploadKey/absolute2603=== CONT TestIsValidUploadKey/traversal_nar2604=== CONT TestIsValidUploadKey/traversal2605=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2606=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2607=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2608=== CONT TestIsValidUploadKey/index.html2609=== CONT TestIsValidUploadKey/nix-cache-info2610=== CONT TestIsValidUploadKey/build_log_home-manager_file2611=== CONT TestIsValidUploadKey/nar_plain2612=== CONT TestIsValidUploadKey/build_log2613=== CONT TestIsValidUploadKey/listing2614=== CONT TestIsValidUploadKey/realisation2615=== CONT TestIsValidUploadKey/build_log_question_mark2616=== CONT TestIsValidUploadKey/build_log_plus_in_name2617=== CONT TestIsValidUploadKey/build_log_equals2618=== CONT TestIsValidUploadKey/nar_xz2619=== CONT TestIsValidUploadKey/nar_zst2620--- PASS: TestIsValidUploadKey (0.00s)2621 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2622 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2623 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2624 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2625 --- PASS: TestIsValidUploadKey/absolute (0.00s)2626 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2627 --- PASS: TestIsValidUploadKey/traversal (0.00s)2628 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2629 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2630 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2631 --- PASS: TestIsValidUploadKey/index.html (0.00s)2632 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2633 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2634 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2635 --- PASS: TestIsValidUploadKey/build_log (0.00s)2636 --- PASS: TestIsValidUploadKey/listing (0.00s)2637 --- PASS: TestIsValidUploadKey/realisation (0.00s)2638 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2639 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2640 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2641 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2642 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2643=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info26442026/10/01 09:49:51 INFO Received uploads request method=POST path=/2645=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26462026/10/01 09:49:51 INFO Received complete multipart upload request method=POST path=/2647=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal26482026/10/01 09:49:51 INFO Received uploads request method=POST path=/2649=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26502026/10/01 09:49:51 INFO Received request for more parts method=POST path=/2651--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)2652 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2653 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2654 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2655 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2656=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart26572026/10/01 09:49:51 INFO Received complete multipart upload request method=POST path=/2658=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26592026/10/01 09:49:51 INFO Received uploads request method=POST path=/26602026/10/01 09:49:51 OK 20260920000000_drop_claims.sql (68.79ms)26612026/10/01 09:49:51 INFO Vacuumed table table=pending_closures26622026/10/01 09:49:51 OK 20260923120000_add_pushes.sql (12.88ms)26632026/10/01 09:49:51 goose: successfully migrated database to version: 2026092312000026642026/10/01 09:49:51 OK 1_commit_pending_closure.sql (1.37ms)26652026/10/01 09:49:51 OK 2_object_stats_trigger.sql (485.92µs)26662026/10/01 09:49:51 OK 3_commit_push.sql (344.04µs)26672026/10/01 09:49:51 goose: up to current file version: 326682026/10/01 09:49:51 INFO Vacuumed table table=pending_objects26692026/10/01 09:49:51 INFO Vacuumed table table=multipart_uploads26702026/10/01 09:49:51 INFO Vacuumed table table=closures26712026/10/01 09:49:51 INFO Vacuumed table table=objects26722026-10-01 09:49:51.826 UTC [81425] ERROR: relation "goose_db_version" does not exist at character 3626732026-10-01 09:49:51.826 UTC [81425] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26742026-10-01 09:49:51.828 UTC [81426] ERROR: relation "goose_db_version" does not exist at character 3626752026-10-01 09:49:51.828 UTC [81426] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2676=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts26772026/10/01 09:49:51 INFO Received request for more parts method=POST path=/2678=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2679=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2680=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2681=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2682=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2683=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2684=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2685=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2686=== CONT TestPush_RejectsBadRequests/no_roots26872026/10/01 09:49:51 INFO Received push request method=POST path=/api/pushes2688=== CONT TestPush_RejectsBadRequests/bad_root26892026/10/01 09:49:51 INFO Received push request method=POST path=/api/pushes2690=== CONT TestPush_RejectsBadRequests/root_not_in_objects26912026/10/01 09:49:51 INFO Received push request method=POST path=/api/pushes2692=== CONT TestPush_RejectsBadRequests/no_objects26932026/10/01 09:49:51 INFO Received push request method=POST path=/api/pushes2694=== CONT TestIsValidCachePath/narinfo2695--- PASS: TestPush_RejectsBadRequests (8.20s)2696 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2697 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2698 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2699 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2700=== CONT TestIsValidCachePath/index.html2701=== CONT TestIsValidCachePath/short_hash2702=== CONT TestIsValidCachePath/wrong_extension2703=== CONT TestIsValidCachePath/leading_slash2704=== CONT TestIsValidCachePath/empty2705=== CONT TestIsValidCachePath/random_path2706=== CONT TestIsValidCachePath/invalid_char_u2707=== CONT TestIsValidCachePath/invalid_char_e2708=== CONT TestIsValidCachePath/traversal_in_middle2709=== CONT TestIsValidCachePath/traversal_parent2710=== CONT TestIsValidCachePath/nar_uncompressed2711=== CONT TestIsValidCachePath/nix-cache-info2712=== CONT TestIsValidCachePath/realisation2713=== CONT TestIsValidCachePath/log2714=== CONT TestIsValidCachePath/ls2715=== CONT TestIsValidCachePath/nar_xz2716=== CONT TestIsValidCachePath/nar_bz22717=== CONT TestIsValidCachePath/nar_zst2718=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2719--- PASS: TestIsValidCachePath (0.00s)2720 --- PASS: TestIsValidCachePath/narinfo (0.00s)2721 --- PASS: TestIsValidCachePath/index.html (0.00s)2722 --- PASS: TestIsValidCachePath/short_hash (0.00s)2723 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2724 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2725 --- PASS: TestIsValidCachePath/empty (0.00s)2726 --- PASS: TestIsValidCachePath/random_path (0.00s)2727 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2728 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2729 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2730 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2731 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2732 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2733 --- PASS: TestIsValidCachePath/realisation (0.00s)2734 --- PASS: TestIsValidCachePath/log (0.00s)2735 --- PASS: TestIsValidCachePath/ls (0.00s)2736 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2737 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2738 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2739 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2740=== CONT TestParseSingleRange/none2741=== CONT TestParseSingleRange/open-ended2742=== CONT TestParseSingleRange/start_far_past_EOF2743=== CONT TestParseSingleRange/start_past_EOF2744=== CONT TestParseSingleRange/single_byte2745=== CONT TestParseSingleRange/suffix_exceeds_size2746=== CONT TestParseSingleRange/suffix2747=== CONT TestParseSingleRange/end_clamped_to_size2748=== CONT TestParseSingleRange/closed2749=== CONT TestParseSingleRange/multi-range_ignored2750=== CONT TestParseSingleRange/malformed_no_dash2751=== CONT TestParseSingleRange/unknown_unit2752=== CONT TestParseSingleRange/malformed_end_before_start2753=== CONT TestParseSingleRange/malformed_both_empty2754--- PASS: TestParseSingleRange (0.00s)2755 --- PASS: TestParseSingleRange/none (0.00s)2756 --- PASS: TestParseSingleRange/open-ended (0.00s)2757 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2758 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2759 --- PASS: TestParseSingleRange/single_byte (0.00s)2760 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2761 --- PASS: TestParseSingleRange/suffix (0.00s)2762 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2763 --- PASS: TestParseSingleRange/closed (0.00s)2764 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2765 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2766 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2767 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2768 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2769=== CONT TestServerTLSConfig/no_client_CA2770=== CONT TestServerTLSConfig/not_a_PEM_file2771=== CONT TestServerTLSConfig/missing_CA_file2772=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2773--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2774 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2775 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.37s)2776 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2777--- PASS: TestServerTLSConfig (0.00s)2778 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2779 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2780 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)2781=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2782=== NAME TestClientCADerivations2783 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-79549-3801637548/TestClientCADerivations712900326/001/store/a37qpdx1431rji05drqx59qd0g8s62wi-ca-test27842026/10/01 09:49:52 OK 20241026095416_initial_model.sql (159.52ms)27852026/10/01 09:49:52 OK 20251210153512_drop_unused_gin_index.sql (3.92ms)27862026/10/01 09:49:52 OK 20251218171726_add_pins.sql (31.01ms)27872026/10/01 09:49:52 OK 20241026095416_initial_model.sql (200.3ms)2788 client_ca_test.go:139: Found 1 dependencies (including self)27892026/10/01 09:49:52 OK 20251210153512_drop_unused_gin_index.sql (15.46ms)27902026/10/01 09:49:52 OK 20260628120000_add_object_size_and_stats.sql (56.91ms)27912026/10/01 09:49:52 OK 20251218171726_add_pins.sql (44.13ms)27922026/10/01 09:49:52 OK 20260905000000_add_claims.sql (33.98ms)27932026/10/01 09:49:52 OK 20260628120000_add_object_size_and_stats.sql (46.37ms)27942026/10/01 09:49:52 OK 20260920000000_drop_claims.sql (40.9ms)27952026/10/01 09:49:52 OK 20260923120000_add_pushes.sql (15.95ms)27962026/10/01 09:49:52 goose: successfully migrated database to version: 2026092312000027972026/10/01 09:49:52 OK 1_commit_pending_closure.sql (1.01ms)27982026/10/01 09:49:52 OK 2_object_stats_trigger.sql (265.58µs)27992026/10/01 09:49:52 OK 3_commit_push.sql (203.58µs)28002026/10/01 09:49:52 goose: up to current file version: 328012026/10/01 09:49:52 OK 20260905000000_add_claims.sql (52.14ms)28022026/10/01 09:49:52 OK 20260920000000_drop_claims.sql (39.3ms)28032026/10/01 09:49:52 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=028042026/10/01 09:49:52 INFO Received create pin request method=POST path=/api/pins/myapp28052026/10/01 09:49:52 OK 20260923120000_add_pushes.sql (18.96ms)28062026/10/01 09:49:52 goose: successfully migrated database to version: 2026092312000028072026/10/01 09:49:52 OK 1_commit_pending_closure.sql (2.23ms)28082026/10/01 09:49:52 OK 2_object_stats_trigger.sql (577.92µs)28092026/10/01 09:49:52 OK 3_commit_push.sql (394.79µs)28102026/10/01 09:49:52 goose: up to current file version: 328112026/10/01 09:49:52 INFO Received push request method=POST path=/api/pushes28122026/10/01 09:49:52 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-79549-3801637548/TestPinProtectsFromGC4168366894/001/store/d0av9gigmq0c1cj1g5r42zxhj8ac8njd-pinned-file.txt narinfo_key=d0av9gigmq0c1cj1g5r42zxhj8ac8njd.narinfo28132026/10/01 09:49:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures28142026/10/01 09:49:52 INFO Garbage collection started28152026/10/01 09:49:52 INFO Aborted multipart uploads count=0 kept=028162026/10/01 09:49:52 WARN Force mode enabled - objects will be deleted immediately without grace period28172026/10/01 09:49:52 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=028182026/10/01 09:49:52 INFO Vacuumed table table=pending_closures28192026/10/01 09:49:52 INFO Vacuumed table table=pending_objects28202026/10/01 09:49:52 INFO Vacuumed table table=multipart_uploads28212026/10/01 09:49:52 INFO Vacuumed table table=closures28222026/10/01 09:49:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28232026/10/01 09:49:52 INFO Uploading a37qpdx1431rji05drqx59qd0g8s62wi-ca-test (144B)28242026/10/01 09:49:52 INFO Vacuumed table table=objects28252026/10/01 09:49:52 WARN Failed to register uploaded object key=a37qpdx1431rji05drqx59qd0g8s62wi.ls error="server returned 404: 404 page not found\n"28262026/10/01 09:49:52 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"28272026/10/01 09:49:52 WARN Failed to register uploaded object key=log/rk39xpb33ykxpsy0f4ccsa776dgbnhlk-ca-test.drv error="server returned 404: 404 page not found\n"28282026/10/01 09:49:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28292026/10/01 09:49:52 INFO Signed narinfos id=1 count=128302026/10/01 09:49:52 INFO Uploading 1 narinfos28312026/10/01 09:49:52 INFO Received complete push request method=POST path=/api/pushes/1/complete28322026/10/01 09:49:52 WARN Failed to register uploaded object key=a37qpdx1431rji05drqx59qd0g8s62wi.narinfo error="server returned 404: 404 page not found\n"28332026/10/01 09:49:52 INFO Upload complete. (272ms)2834 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-79549-3801637548/TestClientCADerivations712900326/001/store/a37qpdx1431rji05drqx59qd0g8s62wi-ca-test2835 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2836 Compression: zstd2837 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2838 NarSize: 1442839 References: 2840 Deriver: /nix/var/nix/builds/nix-79549-3801637548/TestClientCADerivations712900326/001/store/rk39xpb33ykxpsy0f4ccsa776dgbnhlk-ca-test.drv2841 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2842 client_ca_test.go:185: Checking for realisation files in S3...2843 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2844 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2845--- PASS: TestService_ReadScope_PublicByDefault (4.03s)2846=== CONT TestResolveDBConnectionString/flag_wins2847=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2848=== CONT TestResolveDBConnectionString/nothing_configured2849=== CONT TestResolveDBConnectionString/missing_file_is_an_error2850=== CONT TestResolveDBConnectionString/file_when_flag_empty2851=== CONT TestCacheConfigHandler/full_config,_no_issuer2852=== CONT TestCacheConfigHandler/no_signing_keys2853=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2854=== CONT TestCacheConfigHandler/no_cache_url_configured2855--- PASS: TestCacheConfigHandler (0.00s)2856 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2857 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2858 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2859 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2860=== CONT TestClientErrorHandling/InvalidStorePath2861--- PASS: TestResolveDBConnectionString (0.03s)2862 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2863 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2864 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2865 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2866 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2867=== NAME TestClientCADerivations2868 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket75?endpoint=http://localhost:53399®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-79549-3801637548/TestClientCADerivations712900326/001/store'2869 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12870--- PASS: TestClientCADerivations (6.93s)2871=== CONT TestClientErrorHandling/ServerNotAvailable2872=== RUN TestService_RequireScope_OIDC/builder_may_write2873=== PAUSE TestService_RequireScope_OIDC/builder_may_write2874=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2875=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2876=== RUN TestService_RequireScope_OIDC/ops_may_admin2877=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2878=== RUN TestService_RequireScope_OIDC/ops_may_not_write2879=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2880=== RUN TestService_RequireScope_OIDC/reader_may_not_write2881=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2882=== RUN TestService_RequireScope_OIDC/static_token_may_admin2883=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2884=== RUN TestService_RequireScope_OIDC/static_token_may_write2885=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2886=== RUN TestService_RequireScope_OIDC/reader_may_read2887=== PAUSE TestService_RequireScope_OIDC/reader_may_read2888=== RUN TestService_RequireScope_OIDC/writer_implies_read2889=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2890=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2891=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2892=== CONT TestClientErrorHandling/InvalidAuthToken28932026/10/01 09:49:53 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/present28942026-10-01 09:49:53.234 UTC [81532] ERROR: relation "goose_db_version" does not exist at character 3628952026-10-01 09:49:53.234 UTC [81532] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28962026/10/01 09:49:53 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.910436ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28972026/10/01 09:49:53 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02898=== NAME TestClientIntegration2899 client_integration_test.go:323: Objects in database after GC:2900 client_integration_test.go:323: Successfully deleted all objects with GC --force2901--- PASS: TestClientIntegration (8.38s)2902=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2903=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected29042026/10/01 09:49:53 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]2905=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2906=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected29072026/10/01 09:49:53 WARN Authentication failed token_preview=eyJhbGciOi...LcrP_YYaJg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2908=== CONT TestService_RequireScope_OIDC/builder_may_write2909=== CONT TestService_RequireScope_OIDC/static_token_may_admin2910=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2911=== CONT TestService_RequireScope_OIDC/static_token_may_write2912=== CONT TestService_RequireScope_OIDC/ops_may_not_write2913=== CONT TestService_RequireScope_OIDC/reader_may_not_write2914=== CONT TestService_RequireScope_OIDC/writer_implies_read2915=== CONT TestService_RequireScope_OIDC/ops_may_admin2916=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2917=== CONT TestService_RequireScope_OIDC/reader_may_read29182026/10/01 09:49:53 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=439.604456ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2919--- PASS: TestService_AuthMiddleware_OIDC (5.21s)2920 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2921 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2922 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2923 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2924--- PASS: TestService_RequireScope_OIDC (4.26s)2925 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2926 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2927 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2928 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2929 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2930 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2931 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2932 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2933 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2934 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)29352026-10-01 09:49:53.451 UTC [81557] ERROR: relation "goose_db_version" does not exist at character 3629362026-10-01 09:49:53.451 UTC [81557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29372026/10/01 09:49:53 OK 20241026095416_initial_model.sql (140.84ms)29382026/10/01 09:49:53 OK 20251210153512_drop_unused_gin_index.sql (7.36ms)29392026/10/01 09:49:53 OK 20251218171726_add_pins.sql (56.73ms)29402026-10-01 09:49:53.530 UTC [81570] ERROR: relation "goose_db_version" does not exist at character 3629412026-10-01 09:49:53.530 UTC [81570] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29422026/10/01 09:49:53 OK 20260628120000_add_object_size_and_stats.sql (24.53ms)29432026/10/01 09:49:53 OK 20260905000000_add_claims.sql (16.36ms)29442026/10/01 09:49:53 OK 20260920000000_drop_claims.sql (54.03ms)29452026/10/01 09:49:53 OK 20260923120000_add_pushes.sql (10.25ms)29462026/10/01 09:49:53 goose: successfully migrated database to version: 2026092312000029472026/10/01 09:49:53 OK 1_commit_pending_closure.sql (1.83ms)29482026/10/01 09:49:53 OK 2_object_stats_trigger.sql (471.13µs)29492026/10/01 09:49:53 OK 3_commit_push.sql (345.29µs)29502026/10/01 09:49:53 goose: up to current file version: 329512026/10/01 09:49:53 OK 20241026095416_initial_model.sql (98.19ms)29522026/10/01 09:49:53 OK 20251210153512_drop_unused_gin_index.sql (9.94ms)29532026/10/01 09:49:53 OK 20251218171726_add_pins.sql (41.81ms)29542026/10/01 09:49:53 OK 20260628120000_add_object_size_and_stats.sql (30.3ms)29552026/10/01 09:49:53 OK 20260905000000_add_claims.sql (61.95ms)29562026/10/01 09:49:53 OK 20241026095416_initial_model.sql (214.44ms)29572026/10/01 09:49:53 OK 20251210153512_drop_unused_gin_index.sql (17.93ms)29582026/10/01 09:49:53 OK 20260920000000_drop_claims.sql (42.24ms)29592026/10/01 09:49:53 OK 20260923120000_add_pushes.sql (22.51ms)29602026/10/01 09:49:53 goose: successfully migrated database to version: 2026092312000029612026/10/01 09:49:53 OK 1_commit_pending_closure.sql (1.72ms)29622026/10/01 09:49:53 OK 2_object_stats_trigger.sql (277.96µs)29632026/10/01 09:49:53 OK 3_commit_push.sql (209.92µs)29642026/10/01 09:49:53 goose: up to current file version: 329652026/10/01 09:49:53 OK 20251218171726_add_pins.sql (32.62ms)29662026/10/01 09:49:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=862.04784ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29672026/10/01 09:49:53 OK 20260628120000_add_object_size_and_stats.sql (67.85ms)29682026/10/01 09:49:53 OK 20260905000000_add_claims.sql (58.12ms)29692026/10/01 09:49:53 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"29702026/10/01 09:49:53 WARN mTLS auth: bound subjects configured but subject DN unavailable29712026/10/01 09:49:53 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2972--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (3.92s)29732026/10/01 09:49:54 OK 20260920000000_drop_claims.sql (67.7ms)29742026/10/01 09:49:54 OK 20260923120000_add_pushes.sql (24.46ms)29752026/10/01 09:49:54 goose: successfully migrated database to version: 2026092312000029762026/10/01 09:49:54 OK 1_commit_pending_closure.sql (1.96ms)29772026/10/01 09:49:54 OK 2_object_stats_trigger.sql (525.42µs)29782026/10/01 09:49:54 OK 3_commit_push.sql (365.96µs)29792026/10/01 09:49:54 goose: up to current file version: 329802026-10-01 09:49:54.286 UTC [81633] ERROR: relation "goose_db_version" does not exist at character 3629812026-10-01 09:49:54.286 UTC [81633] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29822026-10-01 09:49:54.320 UTC [81642] ERROR: relation "goose_db_version" does not exist at character 3629832026-10-01 09:49:54.320 UTC [81642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2984=== NAME TestPinProtectsFromGC2985 client_integration_test.go:840: Pin successfully protected closure from garbage collection2986--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.29s)2987--- PASS: TestPinProtectsFromGC (10.90s)29882026/10/01 09:49:54 OK 20241026095416_initial_model.sql (153.95ms)29892026/10/01 09:49:54 OK 20251210153512_drop_unused_gin_index.sql (4.94ms)29902026/10/01 09:49:54 OK 20241026095416_initial_model.sql (148.72ms)29912026/10/01 09:49:54 OK 20251218171726_add_pins.sql (25.05ms)29922026/10/01 09:49:54 OK 20251210153512_drop_unused_gin_index.sql (10.97ms)29932026/10/01 09:49:54 OK 20251218171726_add_pins.sql (10.15ms)29942026/10/01 09:49:54 OK 20260628120000_add_object_size_and_stats.sql (23.36ms)29952026-10-01 09:49:54.559 UTC [81678] ERROR: relation "goose_db_version" does not exist at character 3629962026-10-01 09:49:54.559 UTC [81678] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29972026/10/01 09:49:54 OK 20260628120000_add_object_size_and_stats.sql (30.89ms)29982026/10/01 09:49:54 OK 20260905000000_add_claims.sql (36.49ms)29992026/10/01 09:49:54 OK 20260920000000_drop_claims.sql (15.24ms)30002026/10/01 09:49:54 OK 20260905000000_add_claims.sql (35.28ms)30012026/10/01 09:49:54 OK 20260923120000_add_pushes.sql (14.22ms)30022026/10/01 09:49:54 goose: successfully migrated database to version: 2026092312000030032026-10-01 09:49:54.630 UTC [81695] ERROR: relation "goose_db_version" does not exist at character 3630042026-10-01 09:49:54.630 UTC [81695] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC30052026/10/01 09:49:54 OK 1_commit_pending_closure.sql (6.13ms)30062026/10/01 09:49:54 OK 2_object_stats_trigger.sql (635.96µs)30072026/10/01 09:49:54 OK 3_commit_push.sql (4.12ms)30082026/10/01 09:49:54 goose: up to current file version: 330092026/10/01 09:49:54 OK 20260920000000_drop_claims.sql (28.61ms)30102026/10/01 09:49:54 OK 20260923120000_add_pushes.sql (12.84ms)30112026/10/01 09:49:54 goose: successfully migrated database to version: 2026092312000030122026/10/01 09:49:54 OK 20241026095416_initial_model.sql (50.68ms)30132026/10/01 09:49:54 OK 1_commit_pending_closure.sql (2.08ms)30142026/10/01 09:49:54 OK 2_object_stats_trigger.sql (407.88µs)30152026/10/01 09:49:54 OK 3_commit_push.sql (361.17µs)30162026/10/01 09:49:54 goose: up to current file version: 330172026/10/01 09:49:54 OK 20251210153512_drop_unused_gin_index.sql (25.27ms)30182026/10/01 09:49:54 OK 20251218171726_add_pins.sql (19.37ms)30192026/10/01 09:49:54 OK 20260628120000_add_object_size_and_stats.sql (16.22ms)30202026/10/01 09:49:54 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.594522101s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30212026/10/01 09:49:54 OK 20241026095416_initial_model.sql (74.45ms)30222026/10/01 09:49:54 OK 20260905000000_add_claims.sql (31.99ms)3023--- PASS: TestService_ReadAuthMiddleware (3.92s)30242026/10/01 09:49:54 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)30252026/10/01 09:49:54 OK 20260920000000_drop_claims.sql (4.26ms)30262026/10/01 09:49:54 OK 20260923120000_add_pushes.sql (4.94ms)30272026/10/01 09:49:54 goose: successfully migrated database to version: 2026092312000030282026/10/01 09:49:54 OK 1_commit_pending_closure.sql (2.24ms)30292026/10/01 09:49:54 OK 2_object_stats_trigger.sql (534.83µs)30302026/10/01 09:49:54 OK 3_commit_push.sql (357.54µs)30312026/10/01 09:49:54 goose: up to current file version: 330322026/10/01 09:49:54 OK 20251218171726_add_pins.sql (26.55ms)30332026/10/01 09:49:54 OK 20260628120000_add_object_size_and_stats.sql (29.95ms)30342026/10/01 09:49:54 OK 20260905000000_add_claims.sql (14.5ms)30352026/10/01 09:49:54 OK 20260920000000_drop_claims.sql (6.13ms)30362026/10/01 09:49:54 OK 20260923120000_add_pushes.sql (11.57ms)30372026/10/01 09:49:54 goose: successfully migrated database to version: 2026092312000030382026/10/01 09:49:54 OK 1_commit_pending_closure.sql (2.62ms)30392026/10/01 09:49:54 OK 2_object_stats_trigger.sql (720µs)30402026/10/01 09:49:54 OK 3_commit_push.sql (476.42µs)30412026/10/01 09:49:54 goose: up to current file version: 330422026/10/01 09:49:55 INFO Received uploads request method=POST path=/api/pending_closures30432026/10/01 09:49:55 INFO Aborted multipart uploads count=0 kept=030442026/10/01 09:49:55 WARN Force mode enabled - objects will be deleted immediately without grace period30452026/10/01 09:49:55 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=030462026/10/01 09:49:55 INFO Vacuumed table table=pending_closures30472026/10/01 09:49:55 INFO Vacuumed table table=pending_objects30482026/10/01 09:49:55 INFO Vacuumed table table=multipart_uploads30492026/10/01 09:49:55 INFO Vacuumed table table=closures30502026/10/01 09:49:55 INFO Vacuumed table table=objects30512026/10/01 09:49:55 INFO Received uploads request method=POST path=/api/pending_closures30522026/10/01 09:49:55 INFO Aborted multipart uploads count=0 kept=030532026/10/01 09:49:55 WARN Force mode enabled - objects will be deleted immediately without grace period30542026/10/01 09:49:55 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=030552026/10/01 09:49:55 INFO Vacuumed table table=pending_closures30562026/10/01 09:49:55 INFO Vacuumed table table=pending_objects30572026/10/01 09:49:55 INFO Vacuumed table table=multipart_uploads30582026/10/01 09:49:55 INFO Vacuumed table table=closures30592026/10/01 09:49:55 INFO Vacuumed table table=objects3060--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3061 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (3.33s)3062 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (3.60s)30632026/10/01 09:49:56 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30642026/10/01 09:49:56 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-config30652026/10/01 09:49:56 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30662026/10/01 09:49:56 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.812826ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30672026/10/01 09:49:56 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.320311ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30682026/10/01 09:49:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=828.596353ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30692026/10/01 09:49:58 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.594540435s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 09:49:59 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"30712026/10/01 09:49:59 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-config30722026/10/01 09:49:59 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=203.352732ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30732026/10/01 09:49:59 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=436.563048ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30742026/10/01 09:50:00 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=756.851984ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30752026/10/01 09:50:01 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.621425075s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30762026/10/01 09:50:02 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_closures30772026/10/01 09:50:02 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=218.087382ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30782026/10/01 09:50:03 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=370.771258ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30792026/10/01 09:50:03 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=785.528057ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30802026/10/01 09:50:04 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.489180152s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3081--- PASS: TestClientErrorHandling (0.00s)3082 --- PASS: TestClientErrorHandling/InvalidStorePath (3.17s)3083 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.49s)3084 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.92s)3085PASS30862026-10-01 09:50:05.993 UTC [79965] LOG: received smart shutdown request30872026-10-01 09:50:05.995 UTC [79965] LOG: background worker "logical replication launcher" (PID 79975) exited with exit code 130882026-10-01 09:50:06.014 UTC [79970] LOG: shutting down30892026-10-01 09:50:06.014 UTC [79970] LOG: checkpoint starting: shutdown immediate30902026-10-01 09:50:07.751 UTC [79970] LOG: checkpoint complete: wrote 12432 buffers (75.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 25 recycled; write=0.921 s, sync=0.774 s, total=1.738 s; sync files=28655, longest=0.013 s, average=0.001 s; distance=403355 kB, estimate=403355 kB; lsn=0/1A173D90, redo lsn=0/1A173D9030912026-10-01 09:50:07.760 UTC [79965] LOG: database system is shut down3092Running OIDC tests...3093=== RUN TestAudienceForIssuer3094=== PAUSE TestAudienceForIssuer3095=== RUN TestGlobMatch3096=== PAUSE TestGlobMatch3097=== RUN TestValidateToken_ValidToken3098=== PAUSE TestValidateToken_ValidToken3099=== RUN TestValidateToken_WrongAudience3100=== PAUSE TestValidateToken_WrongAudience3101=== RUN TestValidateToken_Expired3102=== PAUSE TestValidateToken_Expired3103=== RUN TestValidateToken_BoundClaimsMismatch3104=== PAUSE TestValidateToken_BoundClaimsMismatch3105=== RUN TestValidateToken_BoundSubjectMismatch3106=== PAUSE TestValidateToken_BoundSubjectMismatch3107=== RUN TestValidateToken_MultipleProviders3108=== PAUSE TestValidateToken_MultipleProviders3109=== RUN TestValidateToken_NoMatchingProvider3110=== PAUSE TestValidateToken_NoMatchingProvider3111=== RUN TestValidateToken_KubernetesServiceAccount3112=== PAUSE TestValidateToken_KubernetesServiceAccount3113=== RUN TestNewValidator_KubernetesRequiresCA3114=== PAUSE TestNewValidator_KubernetesRequiresCA3115=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3116=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3117=== RUN TestPins_ReservedForMatchingRule3118=== PAUSE TestPins_ReservedForMatchingRule3119=== RUN TestPins_TopLevelShorthand3120=== PAUSE TestPins_TopLevelShorthand3121=== RUN TestPins_ConfigValidation3122=== PAUSE TestPins_ConfigValidation3123=== RUN TestScopes_LegacyProviderDefaultsToWrite3124=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3125=== RUN TestScopes_Rules3126=== PAUSE TestScopes_Rules3127=== RUN TestScopes_ConfigValidation3128=== PAUSE TestScopes_ConfigValidation3129=== CONT TestAudienceForIssuer3130--- PASS: TestAudienceForIssuer (0.00s)3131=== CONT TestValidateToken_NoMatchingProvider3132=== CONT TestPins_ConfigValidation3133=== CONT TestNewValidator_KubernetesRequiresCA3134=== CONT TestPins_ReservedForMatchingRule3135=== CONT TestValidateToken_KubernetesServiceAccount3136=== CONT TestPins_TopLevelShorthand3137=== CONT TestScopes_Rules3138=== CONT TestScopes_LegacyProviderDefaultsToWrite3139=== CONT TestValidateToken_Expired3140=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3141--- PASS: TestPins_ConfigValidation (0.01s)3142=== CONT TestValidateToken_BoundSubjectMismatch31432026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54712/oidc31442026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54714/oidc3145--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.02s)3146=== CONT TestValidateToken_MultipleProviders3147--- PASS: TestPins_ReservedForMatchingRule (0.02s)3148=== CONT TestValidateToken_ValidToken31492026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54716/oidc3150--- PASS: TestValidateToken_BoundSubjectMismatch (0.02s)3151=== CONT TestValidateToken_WrongAudience31522026/10/01 09:50:09 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:547183153--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)3154=== CONT TestScopes_ConfigValidation3155--- PASS: TestScopes_ConfigValidation (0.00s)3156=== CONT TestValidateToken_BoundClaimsMismatch31572026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54720/oidc3158--- PASS: TestValidateToken_ValidToken (0.03s)3159=== CONT TestGlobMatch3160=== RUN TestGlobMatch/foo_foo3161=== PAUSE TestGlobMatch/foo_foo3162=== RUN TestGlobMatch/foo_bar3163=== PAUSE TestGlobMatch/foo_bar3164=== RUN TestGlobMatch/*_3165=== PAUSE TestGlobMatch/*_3166=== RUN TestGlobMatch/*_anything3167=== PAUSE TestGlobMatch/*_anything3168=== RUN TestGlobMatch/foo*_foo3169=== PAUSE TestGlobMatch/foo*_foo3170=== RUN TestGlobMatch/foo*_foobar3171=== PAUSE TestGlobMatch/foo*_foobar3172=== RUN TestGlobMatch/foo*_bar3173=== PAUSE TestGlobMatch/foo*_bar3174=== RUN TestGlobMatch/*bar_bar3175=== PAUSE TestGlobMatch/*bar_bar3176=== RUN TestGlobMatch/*bar_foobar3177=== PAUSE TestGlobMatch/*bar_foobar3178=== RUN TestGlobMatch/*bar_foo3179=== PAUSE TestGlobMatch/*bar_foo3180=== RUN TestGlobMatch/foo*bar_foobar3181=== PAUSE TestGlobMatch/foo*bar_foobar3182=== RUN TestGlobMatch/foo*bar_foo123bar3183=== PAUSE TestGlobMatch/foo*bar_foo123bar3184=== RUN TestGlobMatch/foo*bar_foobarbaz3185=== PAUSE TestGlobMatch/foo*bar_foobarbaz3186=== RUN TestGlobMatch/*/*_foo/bar3187=== PAUSE TestGlobMatch/*/*_foo/bar3188=== RUN TestGlobMatch/*/*_foo3189=== PAUSE TestGlobMatch/*/*_foo3190=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3191=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3192=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03193=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03194=== RUN TestGlobMatch/refs/*/main_refs/heads/main3195=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3196=== RUN TestGlobMatch/fo?_foo3197=== PAUSE TestGlobMatch/fo?_foo3198=== RUN TestGlobMatch/fo?_fo3199=== PAUSE TestGlobMatch/fo?_fo3200=== RUN TestGlobMatch/fo?_fooo3201=== PAUSE TestGlobMatch/fo?_fooo3202=== RUN TestGlobMatch/?oo_foo3203=== PAUSE TestGlobMatch/?oo_foo3204=== RUN TestGlobMatch/?oo_boo3205=== PAUSE TestGlobMatch/?oo_boo3206=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3207=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3208=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3209=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3210=== CONT TestGlobMatch/foo_foo3211=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3212=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3213=== CONT TestGlobMatch/?oo_boo3214=== CONT TestGlobMatch/?oo_foo3215=== CONT TestGlobMatch/fo?_fooo3216=== CONT TestGlobMatch/fo?_fo3217=== CONT TestGlobMatch/fo?_foo3218=== CONT TestGlobMatch/refs/*/main_refs/heads/main3219=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03220=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3221=== CONT TestGlobMatch/*/*_foo3222=== CONT TestGlobMatch/*/*_foo/bar3223=== CONT TestGlobMatch/foo*bar_foobarbaz3224=== CONT TestGlobMatch/foo*bar_foo123bar3225=== CONT TestGlobMatch/foo*bar_foobar3226=== CONT TestGlobMatch/*bar_foo3227=== CONT TestGlobMatch/*bar_foobar3228=== CONT TestGlobMatch/*bar_bar3229=== CONT TestGlobMatch/foo*_bar3230=== CONT TestGlobMatch/foo*_foobar3231=== CONT TestGlobMatch/foo*_foo3232=== CONT TestGlobMatch/*_anything3233=== CONT TestGlobMatch/*_3234=== CONT TestGlobMatch/foo_bar3235--- PASS: TestGlobMatch (0.00s)3236 --- PASS: TestGlobMatch/foo_foo (0.00s)3237 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3238 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3239 --- PASS: TestGlobMatch/?oo_boo (0.00s)3240 --- PASS: TestGlobMatch/?oo_foo (0.00s)3241 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3242 --- PASS: TestGlobMatch/fo?_fo (0.00s)3243 --- PASS: TestGlobMatch/fo?_foo (0.00s)3244 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3245 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3246 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3247 --- PASS: TestGlobMatch/*/*_foo (0.00s)3248 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3249 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3250 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3251 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3252 --- PASS: TestGlobMatch/*bar_foo (0.00s)3253 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3254 --- PASS: TestGlobMatch/*bar_bar (0.00s)3255 --- PASS: TestGlobMatch/foo*_bar (0.00s)3256 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3257 --- PASS: TestGlobMatch/foo*_foo (0.00s)3258 --- PASS: TestGlobMatch/*_anything (0.00s)3259 --- PASS: TestGlobMatch/*_ (0.00s)3260 --- PASS: TestGlobMatch/foo_bar (0.00s)32612026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54722/oidc3262--- PASS: TestValidateToken_WrongAudience (0.03s)32632026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54724/oidc3264--- PASS: TestScopes_Rules (0.07s)32652026/10/01 09:50:09 http: TLS handshake error from 127.0.0.1:54727: remote error: tls: bad certificate3266--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)32672026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54729/oidc3268--- PASS: TestPins_TopLevelShorthand (0.09s)32692026/10/01 09:50:09 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12332702026/10/01 09:50:09 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54732/oidc32712026/10/01 09:50:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54728/oidc3272--- PASS: TestValidateToken_MultipleProviders (0.10s)3273--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)32742026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54736/oidc3275--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)32762026/10/01 09:50:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54738/oidc3277--- PASS: TestValidateToken_Expired (0.16s)32782026/10/01 09:50:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54740/oidc3279--- PASS: TestValidateToken_NoMatchingProvider (0.18s)3280PASS3281Running hook tests...3282=== RUN TestSendPathsEmpty3283=== PAUSE TestSendPathsEmpty3284=== RUN TestQueueEnqueueAndFetch3285=== PAUSE TestQueueEnqueueAndFetch3286=== RUN TestQueueDeduplication3287=== PAUSE TestQueueDeduplication3288=== RUN TestQueueRemove3289=== PAUSE TestQueueRemove3290=== RUN TestQueueFetchBatchLimit3291=== PAUSE TestQueueFetchBatchLimit3292=== RUN TestQueueRetryMovesToBack3293=== PAUSE TestQueueRetryMovesToBack3294=== RUN TestQueueFetchRemoveLifecycle3295=== PAUSE TestQueueFetchRemoveLifecycle3296=== RUN TestQueueConcurrentWriters3297=== PAUSE TestQueueConcurrentWriters3298=== RUN TestQueueRemoveLargeClosure3299=== PAUSE TestQueueRemoveLargeClosure3300=== RUN TestServerClientIntegration3301=== PAUSE TestServerClientIntegration3302=== RUN TestServerQueueError3303=== PAUSE TestServerQueueError3304=== RUN TestGetListenerSocketActivation3305 server_test.go:210: === RUN TestGetListenerSocketActivation3306 --- PASS: TestGetListenerSocketActivation (0.00s)3307 PASS3308 3309--- PASS: TestGetListenerSocketActivation (0.01s)3310=== RUN TestDrainIsolatesPoisonPath3311=== PAUSE TestDrainIsolatesPoisonPath3312=== RUN TestRunNotBlockedByPoisonHead3313=== PAUSE TestRunNotBlockedByPoisonHead3314=== RUN TestDrainGivesUpWhenServerDown3315=== PAUSE TestDrainGivesUpWhenServerDown3316=== RUN TestFailedPathPrunedByLaterClosure3317=== PAUSE TestFailedPathPrunedByLaterClosure3318=== RUN TestWorkerUploadsAndRemoves3319=== PAUSE TestWorkerUploadsAndRemoves3320=== RUN TestWorkerSkipsGCdPaths3321=== PAUSE TestWorkerSkipsGCdPaths3322=== RUN TestWorkerPrunesClosureDeps3323=== PAUSE TestWorkerPrunesClosureDeps3324=== RUN TestDrainTimeout3325=== PAUSE TestDrainTimeout3326=== CONT TestSendPathsEmpty3327=== CONT TestServerQueueError3328--- PASS: TestSendPathsEmpty (0.00s)3329=== CONT TestServerClientIntegration3330=== CONT TestWorkerUploadsAndRemoves3331=== CONT TestQueueRetryMovesToBack3332=== CONT TestWorkerPrunesClosureDeps3333=== CONT TestQueueConcurrentWriters3334=== CONT TestQueueRemoveLargeClosure3335=== CONT TestDrainGivesUpWhenServerDown3336=== CONT TestFailedPathPrunedByLaterClosure3337=== CONT TestDrainTimeout33382026/10/01 09:50:09 ERROR Failed to queue paths error="permission denied" count=13339--- PASS: TestServerClientIntegration (0.00s)3340=== CONT TestQueueFetchRemoveLifecycle3341--- PASS: TestServerQueueError (0.00s)3342=== CONT TestWorkerSkipsGCdPaths33432026/10/01 09:50:09 INFO Uploading batch count=233442026/10/01 09:50:09 INFO Upload queue status pending=233452026/10/01 09:50:09 INFO Upload queue status pending=233462026/10/01 09:50:09 INFO Uploading batch count=133472026/10/01 09:50:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-79549-3801637548/TestWorkerSkipsGCdPaths3335451402/002/nonexistent33482026/10/01 09:50:09 INFO Upload queue status pending=233492026/10/01 09:50:09 INFO Uploading batch count=233502026/10/01 09:50:09 INFO Uploading batch count=133512026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=133522026/10/01 09:50:09 INFO Uploading batch count=133532026/10/01 09:50:09 INFO Uploading batch count=233542026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=233552026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainGivesUpWhenServerDown2707651888/002/a3356--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3357=== CONT TestQueueRemove33582026/10/01 09:50:09 INFO Uploading batch count=133592026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainGivesUpWhenServerDown2707651888/002/b3360--- PASS: TestQueueRetryMovesToBack (0.01s)3361=== CONT TestQueueFetchBatchLimit33622026/10/01 09:50:09 INFO Uploading batch count=133632026/10/01 09:50:09 INFO Uploading batch count=233642026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=233652026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainGivesUpWhenServerDown2707651888/002/c33662026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainGivesUpWhenServerDown2707651888/002/d33672026/10/01 09:50:09 INFO Uploading batch count=233682026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=233692026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainGivesUpWhenServerDown2707651888/002/e33702026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainGivesUpWhenServerDown2707651888/002/f33712026/10/01 09:50:09 ERROR Drain finished with paths left in queue remaining=103372--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3373=== CONT TestRunNotBlockedByPoisonHead3374--- PASS: TestQueueRemove (0.00s)3375=== CONT TestDrainIsolatesPoisonPath3376--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3377=== CONT TestQueueDeduplication3378--- PASS: TestQueueFetchBatchLimit (0.00s)3379=== CONT TestQueueEnqueueAndFetch33802026/10/01 09:50:09 INFO Upload queue status pending=333812026/10/01 09:50:09 INFO Uploading batch count=133822026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=133832026/10/01 09:50:09 INFO Uploading batch count=433842026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=433852026/10/01 09:50:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-79549-3801637548/TestDrainIsolatesPoisonPath3213775411/002/bbb3386--- PASS: TestQueueDeduplication (0.00s)33872026/10/01 09:50:09 INFO Uploading batch count=133882026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=133892026/10/01 09:50:09 INFO Uploading batch count=133902026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=13391--- PASS: TestQueueEnqueueAndFetch (0.00s)33922026/10/01 09:50:09 INFO Uploading batch count=133932026/10/01 09:50:09 ERROR Upload failed error="upload failed" count=133942026/10/01 09:50:09 ERROR Drain finished with paths left in queue remaining=13395--- PASS: TestDrainIsolatesPoisonPath (0.00s)3396--- PASS: TestWorkerSkipsGCdPaths (0.03s)3397--- PASS: TestWorkerUploadsAndRemoves (0.03s)3398--- PASS: TestWorkerPrunesClosureDeps (0.03s)3399--- PASS: TestQueueRemoveLargeClosure (0.06s)3400--- PASS: TestQueueConcurrentWriters (0.13s)34012026/10/01 09:50:09 ERROR Upload failed error="context deadline exceeded" count=234022026/10/01 09:50:09 ERROR Drain finished with paths left in queue remaining=43403--- PASS: TestDrainTimeout (0.21s)34042026/10/01 09:50:10 INFO Uploading batch count=134052026/10/01 09:50:10 INFO Uploading batch count=134062026/10/01 09:50:10 INFO Uploading batch count=134072026/10/01 09:50:10 ERROR Upload failed error="upload failed" count=134082026/10/01 09:50:10 INFO Uploading batch count=134092026/10/01 09:50:10 ERROR Upload failed error="upload failed" count=134102026/10/01 09:50:10 INFO Uploading batch count=134112026/10/01 09:50:10 ERROR Upload failed error="upload failed" count=134122026/10/01 09:50:10 INFO Uploading batch count=134132026/10/01 09:50:10 ERROR Upload failed error="upload failed" count=134142026/10/01 09:50:10 ERROR Drain finished with paths left in queue remaining=13415--- PASS: TestRunNotBlockedByPoisonHead (1.02s)3416PASS