niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #241
· 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.22s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestSetClientTLS65=== PAUSE TestSetClientTLS66=== RUN TestSetClientTLSDoesNotMutateDefaultTransport67=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport68=== RUN TestSetClientTLSErrors69=== PAUSE TestSetClientTLSErrors70=== RUN TestStaticToken71=== PAUSE TestStaticToken72=== RUN TestFileTokenReadsAndCaches73=== PAUSE TestFileTokenReadsAndCaches74=== RUN TestFileTokenMissing75=== PAUSE TestFileTokenMissing76=== RUN TestFileTokenEmpty77=== PAUSE TestFileTokenEmpty78=== RUN TestScriptTokenNoExpiryRerunsEveryCall79=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall80=== RUN TestScriptTokenCachesUntilRefresh81=== PAUSE TestScriptTokenCachesUntilRefresh82=== RUN TestScriptTokenEmptyToken83=== PAUSE TestScriptTokenEmptyToken84=== RUN TestScriptTokenBadJSON85=== PAUSE TestScriptTokenBadJSON86=== RUN TestScriptTokenScriptFails87=== PAUSE TestScriptTokenScriptFails88=== RUN TestScriptTokenEmptyCommand89=== PAUSE TestScriptTokenEmptyCommand90=== CONT TestDoServerRequestAttachesToken91=== CONT TestStaticToken92--- PASS: TestStaticToken (0.00s)93=== CONT TestShellSplitErrors94=== CONT TestSetClientTLSDoesNotMutateDefaultTransport95=== CONT TestSetClientTLSErrors96=== CONT TestSetClientTLS97=== CONT TestStreamPushReportsEveryPath98=== CONT TestStreamPushIsolatesFailures99=== CONT TestStreamPushBatchesUnderLoad100=== CONT TestStreamPushGivesUpOnDeadServer101--- PASS: TestShellSplitErrors (0.00s)102=== CONT TestEncodeNixBase32WithRealHash103=== CONT TestDoWithRetry_BodyReplayedViaGetBody1042026/09/21 18:37:02 ERROR Upload failed error="connection refused" count=201052026/09/21 18:37:02 ERROR Upload failed error="bad path" count=3106--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1072026/09/21 18:37:02 ERROR Server seems unavailable, giving up on batch untried=17108=== CONT TestResolveStorePath109--- PASS: TestStreamPushReportsEveryPath (0.00s)110=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess111--- PASS: TestStreamPushIsolatesFailures (0.00s)112=== CONT TestRateLimiterFeedback113=== RUN TestRateLimiterFeedback/429_enables_limiter114=== PAUSE TestRateLimiterFeedback/429_enables_limiter115=== RUN TestRateLimiterFeedback/503_enables_limiter1162026/09/21 18:37:02 WARN Rate limiter enabled after throttle name=server-test rate=5117=== PAUSE TestRateLimiterFeedback/503_enables_limiter118=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter119--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)120=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter121=== CONT TestPathInfoCACompatibility122=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter123=== RUN TestPathInfoCACompatibility/null_ca_field124=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter125=== CONT TestParsePathInfoJSONMultiplePaths126=== PAUSE TestPathInfoCACompatibility/null_ca_field127=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths128=== RUN TestPathInfoCACompatibility/old_string_format_-_text129=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths130=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths131=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths132=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text133=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive134=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive135=== RUN TestPathInfoCACompatibility/new_structured_format_-_text136=== CONT TestParsePathInfoJSON137=== RUN TestParsePathInfoJSON/Nix_format138=== PAUSE TestParsePathInfoJSON/Nix_format139=== RUN TestParsePathInfoJSON/Lix_format140=== PAUSE TestParsePathInfoJSON/Lix_format141=== RUN TestParsePathInfoJSON/empty_input142=== PAUSE TestParsePathInfoJSON/empty_input143=== RUN TestParsePathInfoJSON/whitespace_only144=== PAUSE TestParsePathInfoJSON/whitespace_only145=== RUN TestParsePathInfoJSON/invalid_JSON146=== PAUSE TestParsePathInfoJSON/invalid_JSON147=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text148=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method149=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method150=== CONT TestPathInfoHashCompatibility151=== CONT TestGetStorePathHash152=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)153=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon155=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon156=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI157=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI158=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512159=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512160=== CONT TestConvertHashToNix32161=== RUN TestGetStorePathHash/valid_store_path162=== RUN TestConvertHashToNix32/SRI_format_to_Nix32163=== PAUSE TestGetStorePathHash/valid_store_path164=== RUN TestGetStorePathHash/basename_without_hyphen_should_error165=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32166=== RUN TestConvertHashToNix32/already_Nix32_format167=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error168=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error169=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error170=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error171=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error1722026/09/21 18:37:02 WARN Rate limiter enabled after throttle name=server-test rate=5173--- PASS: TestResolveStorePath (0.00s)174=== CONT TestShellSplit1752026/09/21 18:37:02 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:51531176=== RUN TestSetClientTLSErrors/missing_cert_file177--- PASS: TestShellSplit (0.00s)178=== PAUSE TestConvertHashToNix32/already_Nix32_format179=== PAUSE TestSetClientTLSErrors/missing_cert_file180=== RUN TestConvertHashToNix32/invalid_format181=== CONT TestScriptTokenCachesUntilRefresh182=== RUN TestSetClientTLSErrors/missing_key_file183=== PAUSE TestConvertHashToNix32/invalid_format184=== PAUSE TestSetClientTLSErrors/missing_key_file185=== RUN TestSetClientTLSErrors/missing_ca_file186=== PAUSE TestSetClientTLSErrors/missing_ca_file187=== RUN TestSetClientTLSErrors/invalid_ca_file188=== PAUSE TestSetClientTLSErrors/invalid_ca_file189=== CONT TestStreamPushRequestLine190=== CONT TestScriptTokenScriptFails191=== CONT TestScriptTokenEmptyCommand192--- PASS: TestScriptTokenEmptyCommand (0.00s)193=== CONT TestScriptTokenBadJSON1942026/09/21 18:37:02 WARN Rate limiter backed off name=server-test rate=51952026/09/21 18:37:02 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:51531196--- PASS: TestDoServerRequestAttachesToken (0.01s)197=== CONT TestScriptTokenEmptyToken1982026/09/21 18:37:02 ERROR Upload failed error=boom count=1199--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)200=== CONT TestFileTokenEmpty201--- PASS: TestFileTokenEmpty (0.00s)202=== CONT TestScriptTokenNoExpiryRerunsEveryCall203--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)204=== CONT TestFileTokenMissing205--- PASS: TestFileTokenMissing (0.00s)206=== CONT TestUploadMultipart_SupersededByPeer207=== RUN TestUploadMultipart_SupersededByPeer/exists208=== PAUSE TestUploadMultipart_SupersededByPeer/exists209=== RUN TestUploadMultipart_SupersededByPeer/missing210=== PAUSE TestUploadMultipart_SupersededByPeer/missing211=== CONT TestEncodeNixBase32212=== RUN TestEncodeNixBase32/test_string_hash213=== PAUSE TestEncodeNixBase32/test_string_hash214=== RUN TestEncodeNixBase32/empty_input215=== PAUSE TestEncodeNixBase32/empty_input216=== CONT TestDumpPathWriterError217=== RUN TestSetClientTLS/rejects_connection_without_client_cert218=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert219=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA220=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA221=== RUN TestSetClientTLS/preserves_debug_logging_transport222=== PAUSE TestSetClientTLS/preserves_debug_logging_transport223=== CONT TestDumpPathSingleFile224--- PASS: TestScriptTokenScriptFails (0.01s)225=== CONT TestDumpPathMatchesNix226--- PASS: TestScriptTokenBadJSON (0.01s)227=== CONT TestFilterOversizedClosures228=== RUN TestFilterOversizedClosures/no_limit_keeps_everything229=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything230=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped231=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped232=== RUN TestFilterOversizedClosures/all_closures_skipped233=== PAUSE TestFilterOversizedClosures/all_closures_skipped234=== CONT TestPartSizeForNAR235=== RUN TestPartSizeForNAR/zero_stays_at_minimum236=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum237=== RUN TestPartSizeForNAR/small_stays_at_minimum238=== PAUSE TestPartSizeForNAR/small_stays_at_minimum239=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum240=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum241=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts242=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts243=== RUN TestPartSizeForNAR/1_TiB244=== PAUSE TestPartSizeForNAR/1_TiB245=== RUN TestPartSizeForNAR/5_TiB_S3_max_object246=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object247=== RUN TestPartSizeForNAR/capped_at_5_GiB248=== PAUSE TestPartSizeForNAR/capped_at_5_GiB249=== CONT TestFileTokenReadsAndCaches250--- PASS: TestScriptTokenEmptyToken (0.01s)251=== CONT TestCaseHackSuffix252--- PASS: TestFileTokenReadsAndCaches (0.00s)253=== CONT TestUploadMultipart_PartsInParallel254--- PASS: TestStreamPushRequestLine (0.02s)255=== CONT TestRegisterUploadedObjectReusesConnections256--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)257=== CONT TestRateLimiterFeedback/429_enables_limiter2582026/09/21 18:37:02 WARN Rate limiter enabled after throttle name=server-test rate=52592026/09/21 18:37:02 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:516072602026/09/21 18:37:02 WARN Rate limiter backed off name=server-test rate=5261=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter262=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter263=== CONT TestRateLimiterFeedback/503_enables_limiter264--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)265=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths266=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths267--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)268 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)269 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)270=== CONT TestParsePathInfoJSON/Nix_format271=== CONT TestParsePathInfoJSON/invalid_JSON272=== CONT TestParsePathInfoJSON/whitespace_only273=== CONT TestParsePathInfoJSON/empty_input274=== CONT TestParsePathInfoJSON/Lix_format275--- PASS: TestParsePathInfoJSON (0.00s)276 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)277 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)278 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)279 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)280 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)281=== CONT TestPathInfoCACompatibility/null_ca_field282=== CONT TestPathInfoCACompatibilit2026/09/21 18:37:02 WARN Rate limiter enabled after throttle name=server-test rate=52832026/09/21 18:37:02 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:51613284y/new_structured_format_-_nar_method285=== CONT TestPathInfoCACompatibility/new_structured_format_-_text286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== CONT TestPathInfoCACompatibility/old_string_format_-_text288--- PASS: TestPathInfoCACompatibility (0.00s)289 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)290 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)291 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)292 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)293 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)294=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)295=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512296=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI297=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon298--- PASS: TestPathInfoHashCompatibility (0.00s)299 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)300 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)301 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)302 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)303=== CONT TestGetStorePathHash/valid_store_path304=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error3052026/09/21 18:37:02 WARN Rate limiter backed off name=server-test rate=5306=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error307=== CONT TestGetStorePathHash/basename_without_hyphen_should_error308--- PASS: TestGetStorePathHash (0.00s)309 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)310 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)311 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)312 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)313=== CONT TestConvertHashToNix32/SRI_format_to_Nix32314=== CONT TestConvertHashToNix32/invalid_format315=== CONT TestConvertHashToNix32/already_Nix32_format316--- PASS: TestConvertHashToNix32 (0.00s)317 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)318 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)319 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)320=== CONT TestSetClientTLSErrors/missing_cert_file321--- PASS: TestRateLimiterFeedback (0.00s)322 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)323 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)324 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)325 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)326=== CONT TestSetClientTLSErrors/invalid_ca_file327=== CONT TestSetClientTLSErrors/missing_ca_file328=== CONT TestSetClientTLSErrors/missing_key_file329=== CONT TestUploadMultipart_SupersededByPeer/exists330=== CONT TestEncodeNixBase32/test_string_hash331=== CONT TestUploadMultipart_SupersededByPeer/missing332--- PASS: TestSetClientTLSErrors (0.01s)333 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)334 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)336 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)337--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)338=== CONT TestEncodeNixBase32/empty_input339--- PASS: TestEncodeNixBase32 (0.00s)340 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)341 --- PASS: TestEncodeNixBase32/empty_input (0.00s)342=== CONT TestSetClientTLS/rejects_connection_without_client_cert343=== CONT TestSetClientTLS/preserves_debug_logging_transport344--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)345 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)346 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)347=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA348--- PASS: TestDumpPathWriterError (0.05s)349=== CONT TestFilterOversizedClosures/no_limit_keeps_everything350=== CONT TestFilterOversizedClosures/all_closures_skipped3512026/09/21 18:37:02 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=50352=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3532026/09/21 18:37:02 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=2000354--- PASS: TestFilterOversizedClosures (0.00s)355 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)356 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)357 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)358=== CONT TestPartSizeForNAR/zero_stays_at_minimum359=== CONT TestPartSizeForNAR/1_TiB360=== CONT TestPartSizeForNAR/capped_at_5_GiB361=== CONT TestPartSizeForNAR/5_TiB_S3_max_object362=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum363=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts364=== CONT TestPartSizeForNAR/small_stays_at_minimum365--- PASS: TestPartSizeForNAR (0.00s)366 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)367 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)368 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)369 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)370 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)372 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)373--- PASS: TestDumpPathSingleFile (0.05s)374--- PASS: TestCaseHackSuffix (0.05s)3752026/09/21 18:37:02 http: TLS handshake error from 127.0.0.1:51619: remote error: tls: bad certificate376--- PASS: TestSetClientTLS (0.01s)377 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)378 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)379 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)380--- PASS: TestDumpPathMatchesNix (0.07s)381--- PASS: TestStreamPushBatchesUnderLoad (0.10s)382--- PASS: TestUploadMultipart_PartsInParallel (0.62s)383--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)384PASS385Running server tests...386The files belonging to this database system will be owned by user "_nixbld1".387This user must also own the server process.388389The database cluster will be initialized with locale "C".390The default database encoding has accordingly been set to "SQL_ASCII".391The default text search configuration will be set to "english".392393Data page checksums are enabled.394395creating directory /nix/var/nix/builds/nix-25706-3937147719/postgres538869896/data ... ok396creating subdirectories ... ok397selecting dynamic shared memory implementation ... posix398selecting default "max_connections" ... 100399selecting default "shared_buffers" ... 128MB400selecting default time zone ... UTC401creating configuration files ... ok402running bootstrap script ... ok403performing post-bootstrap initialization ... ok404syncing data to disk ... ok405406initdb: warning: enabling "trust" authentication for local connections407initdb: 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.408409Success. You can now start the database server using:410411 pg_ctl -D /nix/var/nix/builds/nix-25706-3937147719/postgres538869896/data -l logfile start4124132026-09-21 18:37:04.758 UTC [25743] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4142026-09-21 18:37:04.758 UTC [25743] LOG: listening on Unix socket "/nix/var/nix/builds/nix-25706-3937147719/postgres538869896/.s.PGSQL.5432"4152026-09-21 18:37:04.760 UTC [25750] LOG: database system was shut down at 2026-09-21 18:37:04 UTC4162026-09-21 18:37:04.761 UTC [25751] FATAL: the database system is starting up417/nix/var/nix/builds/nix-25706-3937147719/postgres538869896:5432 - rejecting connections4182026-09-21 18:37:04.761 UTC [25743] LOG: database system is ready to accept connections419/nix/var/nix/builds/nix-25706-3937147719/postgres538869896:5432 - accepting connections420{"timestamp":"2026-09-21T18:37:04.982957Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"743c7857-01a1-46f8-8b11-372652b81455","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}421=== RUN TestService_AuthMiddleware422=== PAUSE TestService_AuthMiddleware423=== RUN TestService_AuthMiddleware_MTLSProxyHeader424=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader425=== RUN TestService_AuthMiddleware_MTLSBoundSubjects426=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects427=== RUN TestService_ReadAuthMiddleware428=== PAUSE TestService_ReadAuthMiddleware429=== RUN TestService_AuthMiddleware_OIDC430=== PAUSE TestService_AuthMiddleware_OIDC431=== RUN TestService_RequireScope_OIDC432=== PAUSE TestService_RequireScope_OIDC433=== RUN TestService_ReadScope_PublicByDefault434=== PAUSE TestService_ReadScope_PublicByDefault435=== RUN TestCacheConfigHandler436=== PAUSE TestCacheConfigHandler437=== RUN TestCacheStatsHandler438=== PAUSE TestCacheStatsHandler439=== RUN TestClientCADerivations440=== PAUSE TestClientCADerivations441=== RUN TestClientErrorHandling442=== PAUSE TestClientErrorHandling443=== RUN TestClientIntegration444=== PAUSE TestClientIntegration445=== RUN TestClientMultipleUploads446=== PAUSE TestClientMultipleUploads447=== RUN TestClientWithDependencies448=== PAUSE TestClientWithDependencies449=== RUN TestClientSharedPathCommittedMidPush450=== PAUSE TestClientSharedPathCommittedMidPush451=== RUN TestPinProtectsFromGC452=== PAUSE TestPinProtectsFromGC453=== RUN TestResolveDBConnectionString454=== PAUSE TestResolveDBConnectionString455=== RUN TestLeadElectsOneAndHandsOver456=== PAUSE TestLeadElectsOneAndHandsOver457=== RUN TestLeadIncumbentWinsAfterRestart4582026-09-21 18:37:05.189 UTC [25823] ERROR: relation "goose_db_version" does not exist at character 364592026-09-21 18:37:05.189 UTC [25823] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4602026/09/21 18:37:05 OK 20241026095416_initial_model.sql (4.86ms)4612026/09/21 18:37:05 OK 20251210153512_drop_unused_gin_index.sql (645.04µs)4622026/09/21 18:37:05 OK 20251218171726_add_pins.sql (949.54µs)4632026/09/21 18:37:05 OK 20260628120000_add_object_size_and_stats.sql (906.92µs)4642026/09/21 18:37:05 OK 20260905000000_add_claims.sql (979.54µs)4652026/09/21 18:37:05 OK 20260920000000_drop_claims.sql (647µs)4662026/09/21 18:37:05 goose: successfully migrated database to version: 202609200000004672026/09/21 18:37:05 OK 1_commit_pending_closure.sql (1.09ms)4682026/09/21 18:37:05 OK 2_object_stats_trigger.sql (230.46µs)4692026/09/21 18:37:05 goose: up to current file version: 24702026/09/21 18:37:05 INFO lead: acquired remote=192.0.2.1:12344712026/09/21 18:37:05 INFO lead: released remote=192.0.2.1:12344722026/09/21 18:37:05 INFO lead: acquired remote=192.0.2.1:12344732026/09/21 18:37:05 INFO lead: released remote=192.0.2.1:1234474--- PASS: TestLeadIncumbentWinsAfterRestart (0.83s)475=== RUN TestLeadEndsOnShutdown476=== PAUSE TestLeadEndsOnShutdown477=== RUN TestGCAdvisoryLockBlocksConcurrentRun4782026-09-21 18:37:06.010 UTC [25827] ERROR: relation "goose_db_version" does not exist at character 364792026-09-21 18:37:06.010 UTC [25827] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4802026/09/21 18:37:06 OK 20241026095416_initial_model.sql (4.21ms)4812026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (417.92µs)4822026/09/21 18:37:06 OK 20251218171726_add_pins.sql (888.29µs)4832026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (960.75µs)4842026/09/21 18:37:06 OK 20260905000000_add_claims.sql (1.15ms)4852026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (684µs)4862026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000004872026/09/21 18:37:06 OK 1_commit_pending_closure.sql (933.83µs)4882026/09/21 18:37:06 OK 2_object_stats_trigger.sql (232.88µs)4892026/09/21 18:37:06 goose: up to current file version: 2490--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.17s)491=== RUN TestGCBugBareHashReferences492=== PAUSE TestGCBugBareHashReferences493=== RUN TestGCMetrics494=== PAUSE TestGCMetrics495=== RUN TestGCTaskStore_StartNew496=== PAUSE TestGCTaskStore_StartNew497=== RUN TestGCTaskStore_DeduplicateSameParams498=== PAUSE TestGCTaskStore_DeduplicateSameParams499=== RUN TestGCTaskStore_ConflictDifferentParams500=== PAUSE TestGCTaskStore_ConflictDifferentParams501=== RUN TestGCTaskStore_GetEmpty502=== PAUSE TestGCTaskStore_GetEmpty503=== RUN TestGCTaskStore_GetReturnsLatest504=== PAUSE TestGCTaskStore_GetReturnsLatest505=== RUN TestGCTaskStore_CompletedAllowsNewTask506=== PAUSE TestGCTaskStore_CompletedAllowsNewTask507=== RUN TestGCTaskStore_PhaseUpdates508=== PAUSE TestGCTaskStore_PhaseUpdates509=== RUN TestGCTaskStore_Fail510=== PAUSE TestGCTaskStore_Fail511=== RUN TestGracefulShutdownDrainsInflight512=== PAUSE TestGracefulShutdownDrainsInflight513=== RUN TestService_healthCheckHandler514=== PAUSE TestService_healthCheckHandler515=== RUN TestService_readinessHandler516=== PAUSE TestService_readinessHandler517=== RUN TestGenerateLandingPage518=== PAUSE TestGenerateLandingPage519=== RUN TestCacheConfigHandlerMaxNarSize520=== PAUSE TestCacheConfigHandlerMaxNarSize521=== RUN TestCreatePendingClosureRejectsOversizedNAR522=== PAUSE TestCreatePendingClosureRejectsOversizedNAR523=== RUN TestNARDeduplicationMetadataUploadBug524=== PAUSE TestNARDeduplicationMetadataUploadBug525=== RUN TestMetricsInventory526=== PAUSE TestMetricsInventory527=== RUN TestService_NativeMTLS528=== PAUSE TestService_NativeMTLS529=== RUN TestServerTLSConfig530=== PAUSE TestServerTLSConfig531=== RUN TestMultipartCleanup532=== PAUSE TestMultipartCleanup533=== RUN TestObjectStatsTrigger534=== PAUSE TestObjectStatsTrigger535=== RUN TestOrphanedObjectsGC536=== PAUSE TestOrphanedObjectsGC537=== RUN TestOrphanedObjectsGCStressTest538=== PAUSE TestOrphanedObjectsGCStressTest539=== RUN TestResurrectedObjectNotDeleted540=== PAUSE TestResurrectedObjectNotDeleted541=== RUN TestCreatePin_ReservedPins542=== PAUSE TestCreatePin_ReservedPins543=== RUN TestParseSingleRange544=== PAUSE TestParseSingleRange545=== RUN TestIsValidCachePath546=== PAUSE TestIsValidCachePath547=== RUN TestReadProxyNarinfo548=== PAUSE TestReadProxyNarinfo549=== RUN TestReadProxyNarinfoAlreadyDecompressed550=== PAUSE TestReadProxyNarinfoAlreadyDecompressed551=== RUN TestReadProxyNarStreaming552=== PAUSE TestReadProxyNarStreaming553=== RUN TestReadProxy404554=== PAUSE TestReadProxy404555=== RUN TestReadProxyInvalidPath556=== PAUSE TestReadProxyInvalidPath557=== RUN TestReadProxyHead558=== PAUSE TestReadProxyHead559=== RUN TestReadProxyConditionalGet560=== PAUSE TestReadProxyConditionalGet561=== RUN TestReadProxyRootRedirectsToIndexHTML562=== PAUSE TestReadProxyRootRedirectsToIndexHTML563=== RUN TestReadProxyDisabled564=== PAUSE TestReadProxyDisabled565=== RUN TestReadRedirectNar566=== PAUSE TestReadRedirectNar567=== RUN TestReadRedirectKeepsNarinfoProxied568=== PAUSE TestReadRedirectKeepsNarinfoProxied569=== RUN TestReadProxyRangeRequest570=== PAUSE TestReadProxyRangeRequest571=== RUN TestReadRedirectUsesPublicS3URL572=== PAUSE TestReadRedirectUsesPublicS3URL573=== RUN TestRedundantMultipartUpload574=== PAUSE TestRedundantMultipartUpload575=== RUN TestCompleteMultipartUpload_ErrorButObjectExists576=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists577=== RUN TestCompletedNarNotReofferedAcrossClosures578=== PAUSE TestCompletedNarNotReofferedAcrossClosures579=== RUN TestPresignedUploadRegisteredBeforeCommit580=== PAUSE TestPresignedUploadRegisteredBeforeCommit581=== RUN TestService_Rustfstest582=== PAUSE TestService_Rustfstest583=== RUN TestParseSize584=== PAUSE TestParseSize585=== RUN TestSkippedUploadsHandler586=== PAUSE TestSkippedUploadsHandler587=== RUN TestSystemdListenerNotActivated588--- PASS: TestSystemdListenerNotActivated (0.00s)589=== RUN TestWatchdogBeatsWhenHealthy590--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)591=== RUN TestWatchdogSkipsWhenUnhealthy5922026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5932026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5942026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5952026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5962026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5972026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5982026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5992026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6002026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6012026/09/21 18:37:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"602--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)603=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle604=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle605=== RUN TestProxyWriteTimeout606=== PAUSE TestProxyWriteTimeout607=== RUN TestIsValidUploadKey608=== PAUSE TestIsValidUploadKey609=== RUN TestUploadHandlersRejectInvalidKeys610=== PAUSE TestUploadHandlersRejectInvalidKeys611=== RUN TestUploadHandlersRejectOversizedBody612=== PAUSE TestUploadHandlersRejectOversizedBody613=== RUN TestService_cleanupPendingClosuresHandler614=== PAUSE TestService_cleanupPendingClosuresHandler615=== RUN TestService_createPendingClosureHandler616=== PAUSE TestService_createPendingClosureHandler617=== RUN TestService_verifyS3Integrity618=== PAUSE TestService_verifyS3Integrity619=== RUN TestCompleteMultipartUnregistered620=== PAUSE TestCompleteMultipartUnregistered621=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT622=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT623=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle624=== CONT TestSkippedUploadsHandler625=== CONT TestService_createPendingClosureHandler626=== CONT TestCacheConfigHandlerMaxNarSize627=== CONT TestUploadHandlersRejectInvalidKeys628=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info629=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info630=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal631=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal632=== CONT TestUploadHandlersRejectOversizedBody6332026/09/21 18:37:06 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000634--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)635=== CONT TestService_cleanupPendingClosuresHandler636=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT637=== CONT TestCompleteMultipartUnregistered638=== CONT TestService_verifyS3Integrity639=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key640=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key641=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key642=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key643=== CONT TestService_AuthMiddleware644--- PASS: TestSkippedUploadsHandler (0.02s)645=== CONT TestIsValidUploadKey646=== RUN TestIsValidUploadKey/narinfo647=== PAUSE TestIsValidUploadKey/narinfo648=== RUN TestIsValidUploadKey/nar_zst649=== PAUSE TestIsValidUploadKey/nar_zst650=== RUN TestIsValidUploadKey/nar_xz651=== PAUSE TestIsValidUploadKey/nar_xz652=== RUN TestIsValidUploadKey/nar_plain653=== PAUSE TestIsValidUploadKey/nar_plain654=== RUN TestIsValidUploadKey/listing655=== PAUSE TestIsValidUploadKey/listing656=== RUN TestIsValidUploadKey/build_log657=== PAUSE TestIsValidUploadKey/build_log658=== RUN TestIsValidUploadKey/build_log_home-manager_file659=== PAUSE TestIsValidUploadKey/build_log_home-manager_file660=== RUN TestIsValidUploadKey/build_log_plus_in_name661=== PAUSE TestIsValidUploadKey/build_log_plus_in_name662=== RUN TestIsValidUploadKey/build_log_question_mark663=== PAUSE TestIsValidUploadKey/build_log_question_mark664=== RUN TestIsValidUploadKey/build_log_equals665=== PAUSE TestIsValidUploadKey/build_log_equals666=== RUN TestIsValidUploadKey/realisation667=== PAUSE TestIsValidUploadKey/realisation668=== RUN TestIsValidUploadKey/realisation_plus_in_output669=== PAUSE TestIsValidUploadKey/realisation_plus_in_output670=== RUN TestIsValidUploadKey/nix-cache-info671=== PAUSE TestIsValidUploadKey/nix-cache-info672=== RUN TestIsValidUploadKey/index.html673=== PAUSE TestIsValidUploadKey/index.html674=== RUN TestIsValidUploadKey/narinfo_key,_nar_type675=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type676=== RUN TestIsValidUploadKey/nar_key,_narinfo_type677=== CONT TestProxyWriteTimeout678=== RUN TestProxyWriteTimeout/narinfo679=== PAUSE TestProxyWriteTimeout/narinfo680=== RUN TestProxyWriteTimeout/1_GiB_nar681=== PAUSE TestProxyWriteTimeout/1_GiB_nar682=== RUN TestProxyWriteTimeout/10_GiB_nar683=== PAUSE TestProxyWriteTimeout/10_GiB_nar684=== RUN TestProxyWriteTimeout/unknown_size685=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type686=== PAUSE TestProxyWriteTimeout/unknown_size687=== RUN TestIsValidUploadKey/listing_key,_narinfo_type688=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type689=== RUN TestIsValidUploadKey/traversal690=== PAUSE TestIsValidUploadKey/traversal691=== RUN TestIsValidUploadKey/traversal_nar692=== PAUSE TestIsValidUploadKey/traversal_nar693=== RUN TestIsValidUploadKey/absolute694=== PAUSE TestIsValidUploadKey/absolute695=== RUN TestIsValidUploadKey/empty_key696=== PAUSE TestIsValidUploadKey/empty_key697=== CONT TestReadProxy404698=== RUN TestIsValidUploadKey/unknown_type699=== PAUSE TestIsValidUploadKey/unknown_type700=== CONT TestParseSize701--- PASS: TestParseSize (0.00s)702=== CONT TestService_Rustfstest703=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure704=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure705=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart706=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart707=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts708=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts709=== CONT TestPresignedUploadRegisteredBeforeCommit7102026-09-21 18:37:06.639 UTC [25850] ERROR: relation "goose_db_version" does not exist at character 367112026-09-21 18:37:06.639 UTC [25850] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7122026-09-21 18:37:06.640 UTC [25849] ERROR: relation "goose_db_version" does not exist at character 367132026-09-21 18:37:06.640 UTC [25849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7142026-09-21 18:37:06.641 UTC [25851] ERROR: relation "goose_db_version" does not exist at character 367152026-09-21 18:37:06.641 UTC [25851] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7162026-09-21 18:37:06.641 UTC [25852] ERROR: relation "goose_db_version" does not exist at character 367172026-09-21 18:37:06.641 UTC [25852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7182026-09-21 18:37:06.644 UTC [25854] ERROR: relation "goose_db_version" does not exist at character 367192026-09-21 18:37:06.644 UTC [25854] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7202026-09-21 18:37:06.644 UTC [25858] ERROR: relation "goose_db_version" does not exist at character 367212026-09-21 18:37:06.644 UTC [25858] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7222026-09-21 18:37:06.645 UTC [25853] ERROR: relation "goose_db_version" does not exist at character 367232026-09-21 18:37:06.645 UTC [25853] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7242026-09-21 18:37:06.645 UTC [25855] ERROR: relation "goose_db_version" does not exist at character 367252026-09-21 18:37:06.645 UTC [25855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7262026-09-21 18:37:06.645 UTC [25857] ERROR: relation "goose_db_version" does not exist at character 367272026-09-21 18:37:06.645 UTC [25857] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7282026-09-21 18:37:06.646 UTC [25856] ERROR: relation "goose_db_version" does not exist at character 367292026-09-21 18:37:06.646 UTC [25856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7302026/09/21 18:37:06 OK 20241026095416_initial_model.sql (6.85ms)7312026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)7322026/09/21 18:37:06 OK 20241026095416_initial_model.sql (8.24ms)7332026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (659.38µs)7342026/09/21 18:37:06 OK 20241026095416_initial_model.sql (7.98ms)7352026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.95ms)7362026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (670.58µs)7372026/09/21 18:37:06 OK 20241026095416_initial_model.sql (7.92ms)7382026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.97ms)7392026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (869.92µs)7402026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.91ms)7412026/09/21 18:37:06 OK 20251218171726_add_pins.sql (2.21ms)7422026/09/21 18:37:06 OK 20241026095416_initial_model.sql (8.36ms)7432026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.72ms)7442026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)7452026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (781.83µs)7462026/09/21 18:37:06 OK 20241026095416_initial_model.sql (7.95ms)7472026/09/21 18:37:06 OK 20260905000000_add_claims.sql (1.99ms)7482026/09/21 18:37:06 OK 20241026095416_initial_model.sql (7.67ms)7492026/09/21 18:37:06 OK 20241026095416_initial_model.sql (9.13ms)7502026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (2.12ms)7512026/09/21 18:37:06 OK 20241026095416_initial_model.sql (8.18ms)7522026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (902.46µs)7532026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.24ms)7542026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (498.33µs)7552026/09/21 18:37:06 OK 20241026095416_initial_model.sql (9ms)7562026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (836.88µs)7572026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (841.75µs)7582026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.89ms)7592026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (1.8ms)7602026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000007612026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.09ms)7622026/09/21 18:37:06 OK 20260905000000_add_claims.sql (2.2ms)7632026/09/21 18:37:06 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)7642026/09/21 18:37:06 OK 20260905000000_add_claims.sql (1.91ms)7652026/09/21 18:37:06 OK 1_commit_pending_closure.sql (1.24ms)7662026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (1.16ms)7672026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000007682026/09/21 18:37:06 OK 20251218171726_add_pins.sql (2ms)7692026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.64ms)7702026/09/21 18:37:06 OK 20260905000000_add_claims.sql (2.35ms)7712026/09/21 18:37:06 OK 20251218171726_add_pins.sql (2.39ms)7722026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (937.04µs)7732026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000007742026/09/21 18:37:06 OK 2_object_stats_trigger.sql (455.54µs)7752026/09/21 18:37:06 goose: up to current file version: 27762026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.78ms)7772026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.66ms)7782026/09/21 18:37:06 OK 20251218171726_add_pins.sql (1.87ms)7792026/09/21 18:37:06 OK 1_commit_pending_closure.sql (910.21µs)7802026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (1.41ms)7812026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000007822026/09/21 18:37:06 OK 2_object_stats_trigger.sql (617.21µs)7832026/09/21 18:37:06 goose: up to current file version: 27842026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.61ms)7852026/09/21 18:37:06 OK 1_commit_pending_closure.sql (1.5ms)7862026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.16ms)7872026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (1.72ms)7882026/09/21 18:37:06 OK 20260628120000_add_object_size_and_stats.sql (2.03ms)7892026/09/21 18:37:06 OK 2_object_stats_trigger.sql (375.54µs)7902026/09/21 18:37:06 goose: up to current file version: 27912026/09/21 18:37:06 OK 20260905000000_add_claims.sql (1.94ms)7922026/09/21 18:37:06 OK 20260905000000_add_claims.sql (2.11ms)7932026/09/21 18:37:06 OK 1_commit_pending_closure.sql (1.38ms)7942026/09/21 18:37:06 OK 2_object_stats_trigger.sql (250.83µs)7952026/09/21 18:37:06 goose: up to current file version: 27962026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (1.04ms)7972026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000007982026/09/21 18:37:06 OK 20260905000000_add_claims.sql (1.83ms)7992026/09/21 18:37:06 OK 1_commit_pending_closure.sql (732.79µs)8002026/09/21 18:37:06 OK 2_object_stats_trigger.sql (184.71µs)8012026/09/21 18:37:06 goose: up to current file version: 28022026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (6.37ms)8032026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000008042026/09/21 18:37:06 OK 20260905000000_add_claims.sql (7.2ms)8052026/09/21 18:37:06 OK 20260905000000_add_claims.sql (7.16ms)8062026/09/21 18:37:06 OK 20260905000000_add_claims.sql (7.3ms)8072026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (5.87ms)8082026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000008092026/09/21 18:37:06 OK 1_commit_pending_closure.sql (859.79µs)8102026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (722.38µs)8112026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000008122026/09/21 18:37:06 OK 2_object_stats_trigger.sql (217.38µs)8132026/09/21 18:37:06 goose: up to current file version: 28142026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (779.33µs)8152026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000008162026/09/21 18:37:06 OK 20260920000000_drop_claims.sql (903.17µs)8172026/09/21 18:37:06 goose: successfully migrated database to version: 202609200000008182026/09/21 18:37:06 OK 1_commit_pending_closure.sql (840.79µs)8192026/09/21 18:37:06 OK 2_object_stats_trigger.sql (228.13µs)8202026/09/21 18:37:06 goose: up to current file version: 28212026/09/21 18:37:06 OK 1_commit_pending_closure.sql (774.96µs)8222026/09/21 18:37:06 OK 1_commit_pending_closure.sql (643.13µs)8232026/09/21 18:37:06 OK 1_commit_pending_closure.sql (651.79µs)8242026/09/21 18:37:06 OK 2_object_stats_trigger.sql (186.75µs)8252026/09/21 18:37:06 goose: up to current file version: 28262026/09/21 18:37:06 OK 2_object_stats_trigger.sql (185.17µs)8272026/09/21 18:37:06 goose: up to current file version: 28282026/09/21 18:37:06 OK 2_object_stats_trigger.sql (197.13µs)8292026/09/21 18:37:06 goose: up to current file version: 28302026/09/21 18:37:06 INFO Received uploads request method=POST path=/api/pending_closures8312026/09/21 18:37:06 INFO Received uploads request method=POST path=/api/pending_closures8322026/09/21 18:37:06 INFO Received uploads request method=POST path=/api/pending_closures8332026/09/21 18:37:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8342026/09/21 18:37:06 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst835--- PASS: TestCompleteMultipartUnregistered (0.56s)836=== CONT TestCompletedNarNotReofferedAcrossClosures8372026/09/21 18:37:07 INFO Received uploads request method=POST path=/api/pending_closures8382026/09/21 18:37:07 INFO Received uploads request method=POST path=/api/pending_closures8392026/09/21 18:37:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8402026/09/21 18:37:07 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"841--- PASS: TestService_AuthMiddleware (1.14s)842=== CONT TestCompleteMultipartUpload_ErrorButObjectExists8432026/09/21 18:37:07 INFO Received uploads request method=POST path=/api/pending_closures8442026/09/21 18:37:07 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8452026/09/21 18:37:07 INFO Received uploads request method=POST path=/api/pending_closures846--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.35s)847=== CONT TestReadProxyDisabled8482026/09/21 18:37:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8492026-09-21 18:37:07.873 UTC [25865] ERROR: relation "goose_db_version" does not exist at character 368502026-09-21 18:37:07.873 UTC [25865] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8512026/09/21 18:37:07 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=Y2I0M2E2NmQtODhjNS00ODE2LWEzODktNmNiNTA0MDJjY2E4LmJkNmY0YmRmLTBhYTYtNGYxZi04MDRjLTgyNmUxN2U1OWEzNHgxNzkwMDE1ODI2NzMwNTI5MDAw parts=108522026/09/21 18:37:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8532026/09/21 18:37:07 INFO Completed upload id=18542026/09/21 18:37:07 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008552026/09/21 18:37:07 INFO Received uploads request method=POST path=/api/pending_closures8562026/09/21 18:37:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures8572026/09/21 18:37:07 INFO Aborted multipart uploads count=08582026/09/21 18:37:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=08592026/09/21 18:37:07 INFO Vacuumed table table=pending_closures8602026/09/21 18:37:07 INFO Vacuumed table table=pending_objects861--- PASS: TestService_Rustfstest (1.58s)862=== CONT TestReadRedirectUsesPublicS3URL8632026/09/21 18:37:07 INFO Vacuumed table table=multipart_uploads8642026/09/21 18:37:07 INFO Vacuumed table table=closures8652026/09/21 18:37:07 INFO Vacuumed table table=objects8662026/09/21 18:37:07 OK 20241026095416_initial_model.sql (53.01ms)8672026/09/21 18:37:07 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000868--- PASS: TestService_createPendingClosureHandler (1.67s)869=== CONT TestReadProxyRangeRequest8702026/09/21 18:37:07 OK 20251210153512_drop_unused_gin_index.sql (14.7ms)8712026/09/21 18:37:08 OK 20251218171726_add_pins.sql (26.15ms)8722026/09/21 18:37:08 OK 20260628120000_add_object_size_and_stats.sql (28.87ms)8732026/09/21 18:37:08 OK 20260905000000_add_claims.sql (16.61ms)8742026/09/21 18:37:08 OK 20260920000000_drop_claims.sql (36.14ms)8752026/09/21 18:37:08 goose: successfully migrated database to version: 202609200000008762026/09/21 18:37:08 OK 1_commit_pending_closure.sql (1.85ms)8772026/09/21 18:37:08 OK 2_object_stats_trigger.sql (419.17µs)8782026/09/21 18:37:08 goose: up to current file version: 28792026/09/21 18:37:08 INFO Received uploads request method=POST path=/api/pending_closures880--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.83s)881=== CONT TestReadRedirectKeepsNarinfoProxied8822026/09/21 18:37:08 INFO Received cleanup request method=DELETE path=/api/pending_closures8832026/09/21 18:37:08 INFO Aborted multipart uploads count=08842026/09/21 18:37:08 INFO Received uploads request method=POST path=/api/pending_closures8852026/09/21 18:37:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8862026/09/21 18:37:08 INFO Received cleanup request method=DELETE path=/api/pending_closures8872026/09/21 18:37:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=Y2I0M2E2NmQtODhjNS00ODE2LWEzODktNmNiNTA0MDJjY2E4Ljg3N2I5MDQ2LWY4M2QtNDc0OS05NDM4LWUyZjlhNGI3OTNhZXgxNzkwMDE1ODI3MjY3NzcwMDAw parts=108882026/09/21 18:37:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8892026/09/21 18:37:08 INFO Aborted multipart uploads count=18902026/09/21 18:37:08 INFO Completed upload id=18912026/09/21 18:37:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8922026-09-21 18:37:08.416 UTC [25854] ERROR: Closure does not exist: id=18932026-09-21 18:37:08.416 UTC [25854] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE8942026-09-21 18:37:08.416 UTC [25854] STATEMENT: -- name: CommitPendingClosure :exec895 SELECT commit_pending_closure($1::bigint)896 897--- PASS: TestService_cleanupPendingClosuresHandler (2.10s)898=== CONT TestReadRedirectNar8992026/09/21 18:37:08 INFO Received uploads request method=POST path=/api/pending_closures9002026-09-21 18:37:08.419 UTC [25873] ERROR: relation "goose_db_version" does not exist at character 369012026-09-21 18:37:08.419 UTC [25873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9022026/09/21 18:37:08 INFO Received uploads request method=POST path=/api/pending_closures9032026/09/21 18:37:08 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9042026/09/21 18:37:08 WARN Found objects in DB but missing from S3, will re-upload count=1905--- PASS: TestService_verifyS3Integrity (2.10s)906=== CONT TestRedundantMultipartUpload907--- PASS: TestReadProxy404 (2.15s)908=== CONT TestReadProxyRootRedirectsToIndexHTML9092026/09/21 18:37:08 OK 20241026095416_initial_model.sql (72.49ms)9102026/09/21 18:37:08 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)9112026/09/21 18:37:08 OK 20251218171726_add_pins.sql (14.58ms)9122026-09-21 18:37:08.542 UTC [25880] ERROR: relation "goose_db_version" does not exist at character 369132026-09-21 18:37:08.542 UTC [25880] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9142026/09/21 18:37:08 OK 20260628120000_add_object_size_and_stats.sql (12.35ms)9152026/09/21 18:37:08 OK 20260905000000_add_claims.sql (20.41ms)9162026/09/21 18:37:08 OK 20260920000000_drop_claims.sql (9.35ms)9172026/09/21 18:37:08 goose: successfully migrated database to version: 202609200000009182026/09/21 18:37:08 OK 1_commit_pending_closure.sql (2.4ms)9192026/09/21 18:37:08 OK 2_object_stats_trigger.sql (469.13µs)9202026/09/21 18:37:08 goose: up to current file version: 29212026/09/21 18:37:08 INFO Received uploads request method=POST path=/api/pending_closures9222026/09/21 18:37:08 OK 20241026095416_initial_model.sql (73.68ms)9232026/09/21 18:37:08 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)9242026/09/21 18:37:08 OK 20251218171726_add_pins.sql (19.49ms)9252026/09/21 18:37:08 OK 20260628120000_add_object_size_and_stats.sql (30.84ms)9262026/09/21 18:37:08 OK 20260905000000_add_claims.sql (23.26ms)9272026/09/21 18:37:08 OK 20260920000000_drop_claims.sql (9.95ms)9282026/09/21 18:37:08 goose: successfully migrated database to version: 202609200000009292026/09/21 18:37:08 OK 1_commit_pending_closure.sql (2.33ms)9302026/09/21 18:37:08 OK 2_object_stats_trigger.sql (392.54µs)9312026/09/21 18:37:08 goose: up to current file version: 29322026-09-21 18:37:08.776 UTC [25881] ERROR: relation "goose_db_version" does not exist at character 369332026-09-21 18:37:08.776 UTC [25881] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9342026/09/21 18:37:08 INFO Received uploads request method=POST path=/api/pending_closures9352026/09/21 18:37:09 OK 20241026095416_initial_model.sql (232.82ms)9362026/09/21 18:37:09 OK 20251210153512_drop_unused_gin_index.sql (17.34ms)9372026-09-21 18:37:09.086 UTC [25882] ERROR: relation "goose_db_version" does not exist at character 369382026-09-21 18:37:09.086 UTC [25882] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9392026/09/21 18:37:09 OK 20251218171726_add_pins.sql (26.71ms)9402026/09/21 18:37:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9412026/09/21 18:37:09 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Y2I0M2E2NmQtODhjNS00ODE2LWEzODktNmNiNTA0MDJjY2E4LmY0MTNiOTY3LTNlOTItNDRlMi05OGJlLTBlZjlkMmE5MmVkY3gxNzkwMDE1ODI4ODc2MzkyMDAw942--- PASS: TestReadProxyDisabled (1.40s)943=== CONT TestReadProxyConditionalGet9442026/09/21 18:37:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Y2I0M2E2NmQtODhjNS00ODE2LWEzODktNmNiNTA0MDJjY2E4LmY0MTNiOTY3LTNlOTItNDRlMi05OGJlLTBlZjlkMmE5MmVkY3gxNzkwMDE1ODI4ODc2MzkyMDAw parts=1945--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.66s)946=== CONT TestReadProxyHead9472026/09/21 18:37:09 OK 20260628120000_add_object_size_and_stats.sql (34.93ms)9482026/09/21 18:37:09 OK 20260905000000_add_claims.sql (23ms)9492026/09/21 18:37:09 OK 20260920000000_drop_claims.sql (10.5ms)9502026/09/21 18:37:09 goose: successfully migrated database to version: 202609200000009512026/09/21 18:37:09 OK 1_commit_pending_closure.sql (3.07ms)9522026/09/21 18:37:09 OK 2_object_stats_trigger.sql (571.42µs)9532026/09/21 18:37:09 goose: up to current file version: 29542026/09/21 18:37:09 OK 20241026095416_initial_model.sql (38.95ms)9552026/09/21 18:37:09 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)9562026/09/21 18:37:09 OK 20251218171726_add_pins.sql (15.88ms)9572026/09/21 18:37:09 OK 20260628120000_add_object_size_and_stats.sql (36.88ms)9582026/09/21 18:37:09 OK 20260905000000_add_claims.sql (45.01ms)9592026/09/21 18:37:09 OK 20260920000000_drop_claims.sql (13.01ms)9602026/09/21 18:37:09 goose: successfully migrated database to version: 202609200000009612026-09-21 18:37:09.291 UTC [25888] ERROR: relation "goose_db_version" does not exist at character 369622026-09-21 18:37:09.291 UTC [25888] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9632026/09/21 18:37:09 OK 1_commit_pending_closure.sql (2.16ms)9642026/09/21 18:37:09 OK 2_object_stats_trigger.sql (379.08µs)9652026/09/21 18:37:09 goose: up to current file version: 2966--- PASS: TestReadRedirectUsesPublicS3URL (1.47s)967=== CONT TestReadProxyInvalidPath9682026/09/21 18:37:09 OK 20241026095416_initial_model.sql (134.93ms)9692026/09/21 18:37:09 OK 20251210153512_drop_unused_gin_index.sql (13.25ms)9702026/09/21 18:37:09 OK 20251218171726_add_pins.sql (10.08ms)9712026/09/21 18:37:09 OK 20260628120000_add_object_size_and_stats.sql (28.72ms)9722026/09/21 18:37:09 OK 20260905000000_add_claims.sql (73.81ms)973--- PASS: TestReadProxyRangeRequest (1.63s)974=== CONT TestResolveDBConnectionString975=== RUN TestResolveDBConnectionString/flag_wins976=== PAUSE TestResolveDBConnectionString/flag_wins977=== RUN TestResolveDBConnectionString/file_when_flag_empty978=== PAUSE TestResolveDBConnectionString/file_when_flag_empty979=== RUN TestResolveDBConnectionString/missing_file_is_an_error980=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error981=== RUN TestResolveDBConnectionString/PGHOST_allows_empty982=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty983=== RUN TestResolveDBConnectionString/nothing_configured984=== PAUSE TestResolveDBConnectionString/nothing_configured985=== CONT TestGenerateLandingPage9862026/09/21 18:37:09 OK 20260920000000_drop_claims.sql (28.12ms)9872026/09/21 18:37:09 goose: successfully migrated database to version: 20260920000000988--- PASS: TestGenerateLandingPage (0.01s)989=== CONT TestService_readinessHandler9902026/09/21 18:37:09 OK 1_commit_pending_closure.sql (7.54ms)9912026/09/21 18:37:09 OK 2_object_stats_trigger.sql (4.68ms)9922026/09/21 18:37:09 goose: up to current file version: 29932026-09-21 18:37:09.646 UTC [25892] ERROR: relation "goose_db_version" does not exist at character 369942026-09-21 18:37:09.646 UTC [25892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9952026-09-21 18:37:09.670 UTC [25893] ERROR: relation "goose_db_version" does not exist at character 369962026-09-21 18:37:09.670 UTC [25893] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9972026-09-21 18:37:09.678 UTC [25894] ERROR: relation "goose_db_version" does not exist at character 369982026-09-21 18:37:09.678 UTC [25894] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9992026/09/21 18:37:09 OK 20241026095416_initial_model.sql (57.5ms)10002026/09/21 18:37:09 OK 20241026095416_initial_model.sql (71.39ms)10012026/09/21 18:37:09 OK 20251210153512_drop_unused_gin_index.sql (6.38ms)10022026/09/21 18:37:09 OK 20251210153512_drop_unused_gin_index.sql (8.54ms)10032026/09/21 18:37:09 OK 20251218171726_add_pins.sql (28.25ms)10042026/09/21 18:37:09 OK 20251218171726_add_pins.sql (21.56ms)10052026/09/21 18:37:09 OK 20241026095416_initial_model.sql (87.49ms)10062026/09/21 18:37:09 OK 20251210153512_drop_unused_gin_index.sql (7.77ms)10072026/09/21 18:37:09 OK 20260628120000_add_object_size_and_stats.sql (27ms)10082026/09/21 18:37:09 OK 20260628120000_add_object_size_and_stats.sql (25.42ms)10092026/09/21 18:37:09 OK 20251218171726_add_pins.sql (17.93ms)10102026/09/21 18:37:09 OK 20260628120000_add_object_size_and_stats.sql (32.73ms)10112026/09/21 18:37:09 OK 20260905000000_add_claims.sql (40.12ms)10122026/09/21 18:37:09 OK 20260905000000_add_claims.sql (40.49ms)10132026/09/21 18:37:09 OK 20260920000000_drop_claims.sql (2.33ms)10142026/09/21 18:37:09 goose: successfully migrated database to version: 2026092000000010152026/09/21 18:37:09 OK 20260920000000_drop_claims.sql (1.99ms)10162026/09/21 18:37:09 goose: successfully migrated database to version: 2026092000000010172026/09/21 18:37:09 OK 20260905000000_add_claims.sql (2.89ms)10182026/09/21 18:37:09 OK 1_commit_pending_closure.sql (1.87ms)10192026/09/21 18:37:09 OK 1_commit_pending_closure.sql (1.99ms)10202026/09/21 18:37:09 OK 2_object_stats_trigger.sql (627.96µs)10212026/09/21 18:37:09 goose: up to current file version: 210222026/09/21 18:37:09 OK 2_object_stats_trigger.sql (687.42µs)10232026/09/21 18:37:09 goose: up to current file version: 21024--- PASS: TestReadRedirectKeepsNarinfoProxied (1.76s)1025=== CONT TestService_healthCheckHandler10262026/09/21 18:37:09 OK 20260920000000_drop_claims.sql (30.55ms)10272026/09/21 18:37:09 goose: successfully migrated database to version: 2026092000000010282026/09/21 18:37:09 OK 1_commit_pending_closure.sql (37.77ms)10292026/09/21 18:37:09 OK 2_object_stats_trigger.sql (537.58µs)10302026/09/21 18:37:09 goose: up to current file version: 210312026/09/21 18:37:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10322026/09/21 18:37:10 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=Y2I0M2E2NmQtODhjNS00ODE2LWEzODktNmNiNTA0MDJjY2E4LjZmODdlMzNiLWViYjItNDU3My04NTlhLWEzNmMxNzk4NDRjYngxNzkwMDE1ODI4NjcwNjYwMDAw parts=1210332026/09/21 18:37:10 INFO Received uploads request method=POST path=/api/pending_closures1034--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.21s)1035=== CONT TestGracefulShutdownDrainsInflight10362026/09/21 18:37:10 INFO Starting HTTP server address=127.0.0.1:5167410372026/09/21 18:37:10 INFO Shutdown signal received, draining in-flight requests timeout=10s1038--- PASS: TestReadRedirectNar (1.69s)1039=== CONT TestGCTaskStore_Fail1040--- PASS: TestGCTaskStore_Fail (0.00s)1041=== CONT TestGCTaskStore_PhaseUpdates1042--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1043=== CONT TestGCTaskStore_CompletedAllowsNewTask1044--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1045=== CONT TestGCTaskStore_GetReturnsLatest1046--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1047=== CONT TestGCTaskStore_GetEmpty1048--- PASS: TestGCTaskStore_GetEmpty (0.00s)1049=== CONT TestGCTaskStore_ConflictDifferentParams1050--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1051=== CONT TestGCTaskStore_DeduplicateSameParams1052--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1053=== CONT TestGCTaskStore_StartNew1054--- PASS: TestGCTaskStore_StartNew (0.00s)1055=== CONT TestGCMetrics1056--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1057=== CONT TestGCBugBareHashReferences10582026/09/21 18:37:10 INFO Received uploads request method=POST path=/api/pending_closures10592026-09-21 18:37:10.286 UTC [25902] ERROR: relation "goose_db_version" does not exist at character 3610602026-09-21 18:37:10.286 UTC [25902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10612026/09/21 18:37:10 INFO Received uploads request method=POST path=/api/pending_closures10622026-09-21 18:37:10.317 UTC [25903] ERROR: relation "goose_db_version" does not exist at character 3610632026-09-21 18:37:10.317 UTC [25903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10642026/09/21 18:37:10 OK 20241026095416_initial_model.sql (117.74ms)10652026/09/21 18:37:10 OK 20241026095416_initial_model.sql (82.23ms)10662026/09/21 18:37:10 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)1067--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.95s)1068=== CONT TestLeadEndsOnShutdown10692026/09/21 18:37:10 OK 20251210153512_drop_unused_gin_index.sql (8.63ms)10702026/09/21 18:37:10 OK 20251218171726_add_pins.sql (19.66ms)10712026/09/21 18:37:10 OK 20251218171726_add_pins.sql (24.69ms)10722026/09/21 18:37:10 OK 20260628120000_add_object_size_and_stats.sql (22.51ms)10732026/09/21 18:37:10 OK 20260628120000_add_object_size_and_stats.sql (17.07ms)10742026/09/21 18:37:10 OK 20260905000000_add_claims.sql (11.37ms)10752026/09/21 18:37:10 OK 20260905000000_add_claims.sql (3.67ms)10762026/09/21 18:37:10 OK 20260920000000_drop_claims.sql (1.46ms)10772026/09/21 18:37:10 goose: successfully migrated database to version: 2026092000000010782026/09/21 18:37:10 OK 20260920000000_drop_claims.sql (1.32ms)10792026/09/21 18:37:10 goose: successfully migrated database to version: 2026092000000010802026/09/21 18:37:10 OK 1_commit_pending_closure.sql (2.24ms)10812026/09/21 18:37:10 OK 1_commit_pending_closure.sql (2.03ms)10822026/09/21 18:37:10 OK 2_object_stats_trigger.sql (469.71µs)10832026/09/21 18:37:10 goose: up to current file version: 210842026/09/21 18:37:10 OK 2_object_stats_trigger.sql (418.33µs)10852026/09/21 18:37:10 goose: up to current file version: 210862026-09-21 18:37:10.499 UTC [25906] ERROR: relation "goose_db_version" does not exist at character 3610872026-09-21 18:37:10.499 UTC [25906] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10882026/09/21 18:37:10 OK 20241026095416_initial_model.sql (168.14ms)10892026/09/21 18:37:10 OK 20251210153512_drop_unused_gin_index.sql (6.7ms)10902026-09-21 18:37:10.730 UTC [25907] ERROR: relation "goose_db_version" does not exist at character 3610912026-09-21 18:37:10.730 UTC [25907] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10922026/09/21 18:37:10 OK 20251218171726_add_pins.sql (18.79ms)1093--- PASS: TestReadProxyHead (1.64s)1094=== CONT TestLeadElectsOneAndHandsOver10952026/09/21 18:37:10 OK 20260628120000_add_object_size_and_stats.sql (38.62ms)10962026/09/21 18:37:10 OK 20260905000000_add_claims.sql (42.52ms)10972026/09/21 18:37:10 OK 20260920000000_drop_claims.sql (3.71ms)10982026/09/21 18:37:10 goose: successfully migrated database to version: 2026092000000010992026/09/21 18:37:10 OK 1_commit_pending_closure.sql (2.29ms)11002026/09/21 18:37:10 OK 2_object_stats_trigger.sql (390.29µs)11012026/09/21 18:37:10 goose: up to current file version: 211022026/09/21 18:37:10 OK 20241026095416_initial_model.sql (101.15ms)11032026/09/21 18:37:10 OK 20251210153512_drop_unused_gin_index.sql (13.57ms)11042026/09/21 18:37:10 OK 20251218171726_add_pins.sql (9.71ms)11052026/09/21 18:37:10 OK 20260628120000_add_object_size_and_stats.sql (26.1ms)1106--- PASS: TestReadProxyConditionalGet (1.84s)1107=== CONT TestOrphanedObjectsGCStressTest11082026/09/21 18:37:10 OK 20260905000000_add_claims.sql (45.15ms)11092026/09/21 18:37:10 OK 20260920000000_drop_claims.sql (20.08ms)11102026/09/21 18:37:10 goose: successfully migrated database to version: 2026092000000011112026/09/21 18:37:11 OK 1_commit_pending_closure.sql (1.61ms)11122026/09/21 18:37:11 OK 2_object_stats_trigger.sql (406.83µs)11132026/09/21 18:37:11 goose: up to current file version: 21114--- PASS: TestReadProxyInvalidPath (1.77s)1115=== CONT TestReadProxyNarStreaming11162026-09-21 18:37:11.290 UTC [25914] ERROR: relation "goose_db_version" does not exist at character 3611172026-09-21 18:37:11.290 UTC [25914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11182026/09/21 18:37:11 WARN readiness check failed error="closed pool"1119--- PASS: TestService_readinessHandler (1.76s)1120=== CONT TestReadProxyNarinfoAlreadyDecompressed11212026/09/21 18:37:11 OK 20241026095416_initial_model.sql (88.12ms)11222026/09/21 18:37:11 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)11232026/09/21 18:37:11 OK 20251218171726_add_pins.sql (1.82ms)11242026-09-21 18:37:11.436 UTC [25917] ERROR: relation "goose_db_version" does not exist at character 3611252026-09-21 18:37:11.436 UTC [25917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11262026-09-21 18:37:11.442 UTC [25918] ERROR: relation "goose_db_version" does not exist at character 3611272026-09-21 18:37:11.442 UTC [25918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11282026/09/21 18:37:11 OK 20260628120000_add_object_size_and_stats.sql (15.11ms)11292026/09/21 18:37:11 OK 20260905000000_add_claims.sql (55.01ms)11302026/09/21 18:37:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11312026/09/21 18:37:11 OK 20260920000000_drop_claims.sql (3.38ms)11322026/09/21 18:37:11 goose: successfully migrated database to version: 2026092000000011332026/09/21 18:37:11 OK 1_commit_pending_closure.sql (2.28ms)11342026/09/21 18:37:11 OK 2_object_stats_trigger.sql (671.71µs)11352026/09/21 18:37:11 goose: up to current file version: 211362026/09/21 18:37:11 OK 20241026095416_initial_model.sql (47.52ms)11372026/09/21 18:37:11 OK 20251210153512_drop_unused_gin_index.sql (29.07ms)11382026/09/21 18:37:11 WARN Rate limiter enabled after throttle name=s3-test rate=511392026/09/21 18:37:11 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1140=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1141 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101142 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001143--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.24s)1144=== CONT TestReadProxyNarinfo11452026/09/21 18:37:11 OK 20251218171726_add_pins.sql (13.5ms)11462026/09/21 18:37:11 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=Y2I0M2E2NmQtODhjNS00ODE2LWEzODktNmNiNTA0MDJjY2E4LjJmM2VkM2FmLWJjOTQtNDRiNy04ZDBiLWFjNDgwZmE4MzM1ZngxNzkwMDE1ODMwMjYxODEzMDAw parts=121147--- PASS: TestRedundantMultipartUpload (3.14s)1148=== CONT TestIsValidCachePath1149=== RUN TestIsValidCachePath/narinfo1150=== PAUSE TestIsValidCachePath/narinfo1151=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1152=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1153=== RUN TestIsValidCachePath/nar_zst1154=== PAUSE TestIsValidCachePath/nar_zst1155=== RUN TestIsValidCachePath/nar_xz1156=== PAUSE TestIsValidCachePath/nar_xz1157=== RUN TestIsValidCachePath/nar_bz21158=== PAUSE TestIsValidCachePath/nar_bz21159=== RUN TestIsValidCachePath/nar_uncompressed1160=== PAUSE TestIsValidCachePath/nar_uncompressed1161=== RUN TestIsValidCachePath/ls1162=== PAUSE TestIsValidCachePath/ls1163=== RUN TestIsValidCachePath/log1164=== PAUSE TestIsValidCachePath/log1165=== RUN TestIsValidCachePath/realisation1166=== PAUSE TestIsValidCachePath/realisation1167=== RUN TestIsValidCachePath/nix-cache-info1168=== PAUSE TestIsValidCachePath/nix-cache-info1169=== RUN TestIsValidCachePath/index.html1170=== PAUSE TestIsValidCachePath/index.html1171=== RUN TestIsValidCachePath/traversal_parent1172=== PAUSE TestIsValidCachePath/traversal_parent1173=== RUN TestIsValidCachePath/traversal_in_middle1174=== PAUSE TestIsValidCachePath/traversal_in_middle1175=== RUN TestIsValidCachePath/invalid_char_e1176=== PAUSE TestIsValidCachePath/invalid_char_e1177=== RUN TestIsValidCachePath/invalid_char_u1178=== PAUSE TestIsValidCachePath/invalid_char_u1179=== RUN TestIsValidCachePath/random_path1180=== PAUSE TestIsValidCachePath/random_path1181=== RUN TestIsValidCachePath/empty1182=== PAUSE TestIsValidCachePath/empty1183=== RUN TestIsValidCachePath/leading_slash1184=== PAUSE TestIsValidCachePath/leading_slash1185=== RUN TestIsValidCachePath/wrong_extension1186=== PAUSE TestIsValidCachePath/wrong_extension1187=== RUN TestIsValidCachePath/short_hash1188=== PAUSE TestIsValidCachePath/short_hash1189=== CONT TestParseSingleRange1190=== RUN TestParseSingleRange/none1191=== PAUSE TestParseSingleRange/none1192=== RUN TestParseSingleRange/unknown_unit1193=== PAUSE TestParseSingleRange/unknown_unit1194=== RUN TestParseSingleRange/multi-range_ignored1195=== PAUSE TestParseSingleRange/multi-range_ignored1196=== RUN TestParseSingleRange/malformed_no_dash1197=== PAUSE TestParseSingleRange/malformed_no_dash1198=== RUN TestParseSingleRange/malformed_both_empty1199=== PAUSE TestParseSingleRange/malformed_both_empty1200=== RUN TestParseSingleRange/malformed_end_before_start1201=== PAUSE TestParseSingleRange/malformed_end_before_start1202=== RUN TestParseSingleRange/closed1203=== PAUSE TestParseSingleRange/closed1204=== RUN TestParseSingleRange/open-ended1205=== PAUSE TestParseSingleRange/open-ended1206=== RUN TestParseSingleRange/end_clamped_to_size1207=== PAUSE TestParseSingleRange/end_clamped_to_size1208=== RUN TestParseSingleRange/suffix1209=== PAUSE TestParseSingleRange/suffix1210=== RUN TestParseSingleRange/suffix_exceeds_size1211=== PAUSE TestParseSingleRange/suffix_exceeds_size1212=== RUN TestParseSingleRange/single_byte1213=== PAUSE TestParseSingleRange/single_byte1214=== RUN TestParseSingleRange/start_past_EOF1215=== PAUSE TestParseSingleRange/start_past_EOF1216=== RUN TestParseSingleRange/start_far_past_EOF1217=== PAUSE TestParseSingleRange/start_far_past_EOF1218=== CONT TestCreatePin_ReservedPins12192026/09/21 18:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51698/oidc12202026/09/21 18:37:11 OK 20260628120000_add_object_size_and_stats.sql (17.21ms)12212026/09/21 18:37:11 OK 20241026095416_initial_model.sql (70.03ms)12222026/09/21 18:37:11 OK 20251210153512_drop_unused_gin_index.sql (7.56ms)12232026/09/21 18:37:11 OK 20251218171726_add_pins.sql (14.23ms)12242026/09/21 18:37:11 OK 20260905000000_add_claims.sql (28.94ms)12252026/09/21 18:37:11 OK 20260920000000_drop_claims.sql (3.98ms)12262026/09/21 18:37:11 goose: successfully migrated database to version: 2026092000000012272026/09/21 18:37:11 OK 20260628120000_add_object_size_and_stats.sql (10.96ms)12282026/09/21 18:37:11 OK 1_commit_pending_closure.sql (1.41ms)12292026/09/21 18:37:11 OK 2_object_stats_trigger.sql (306.17µs)12302026/09/21 18:37:11 goose: up to current file version: 212312026-09-21 18:37:11.624 UTC [25923] ERROR: relation "goose_db_version" does not exist at character 3612322026-09-21 18:37:11.624 UTC [25923] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12332026/09/21 18:37:11 OK 20260905000000_add_claims.sql (28.26ms)12342026/09/21 18:37:11 OK 20260920000000_drop_claims.sql (24.31ms)12352026/09/21 18:37:11 goose: successfully migrated database to version: 2026092000000012362026/09/21 18:37:11 OK 1_commit_pending_closure.sql (1.47ms)12372026/09/21 18:37:11 OK 2_object_stats_trigger.sql (352.96µs)12382026/09/21 18:37:11 goose: up to current file version: 21239--- PASS: TestService_healthCheckHandler (1.79s)1240=== CONT TestResurrectedObjectNotDeleted12412026/09/21 18:37:11 OK 20241026095416_initial_model.sql (57.91ms)12422026/09/21 18:37:11 OK 20251210153512_drop_unused_gin_index.sql (6.4ms)12432026/09/21 18:37:11 OK 20251218171726_add_pins.sql (6.96ms)12442026/09/21 18:37:11 OK 20260628120000_add_object_size_and_stats.sql (30.42ms)12452026/09/21 18:37:11 OK 20260905000000_add_claims.sql (16.59ms)12462026/09/21 18:37:11 OK 20260920000000_drop_claims.sql (16.34ms)12472026/09/21 18:37:11 goose: successfully migrated database to version: 2026092000000012482026/09/21 18:37:11 OK 1_commit_pending_closure.sql (3.28ms)12492026/09/21 18:37:11 OK 2_object_stats_trigger.sql (484.5µs)12502026/09/21 18:37:11 goose: up to current file version: 212512026/09/21 18:37:11 INFO Aborted multipart uploads count=012522026/09/21 18:37:11 WARN Force mode enabled - objects will be deleted immediately without grace period12532026/09/21 18:37:11 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012542026/09/21 18:37:11 INFO Vacuumed table table=pending_closures12552026/09/21 18:37:11 INFO Vacuumed table table=pending_objects12562026/09/21 18:37:11 INFO Vacuumed table table=multipart_uploads12572026/09/21 18:37:11 INFO Vacuumed table table=closures12582026/09/21 18:37:11 INFO Vacuumed table table=objects1259--- PASS: TestGCMetrics (1.77s)1260=== CONT TestServerTLSConfig1261=== RUN TestServerTLSConfig/no_client_CA1262=== PAUSE TestServerTLSConfig/no_client_CA1263=== RUN TestServerTLSConfig/missing_CA_file1264=== PAUSE TestServerTLSConfig/missing_CA_file1265=== RUN TestServerTLSConfig/not_a_PEM_file1266=== PAUSE TestServerTLSConfig/not_a_PEM_file1267=== CONT TestOrphanedObjectsGC12682026-09-21 18:37:11.915 UTC [25929] ERROR: relation "goose_db_version" does not exist at character 3612692026-09-21 18:37:11.915 UTC [25929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12702026/09/21 18:37:12 OK 20241026095416_initial_model.sql (88.97ms)12712026/09/21 18:37:12 OK 20251210153512_drop_unused_gin_index.sql (22.76ms)12722026-09-21 18:37:12.057 UTC [25930] ERROR: relation "goose_db_version" does not exist at character 3612732026-09-21 18:37:12.057 UTC [25930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12742026/09/21 18:37:12 OK 20251218171726_add_pins.sql (18.52ms)12752026/09/21 18:37:12 OK 20260628120000_add_object_size_and_stats.sql (12.82ms)12762026/09/21 18:37:12 OK 20260905000000_add_claims.sql (23.36ms)12772026/09/21 18:37:12 OK 20260920000000_drop_claims.sql (10.09ms)12782026/09/21 18:37:12 goose: successfully migrated database to version: 2026092000000012792026/09/21 18:37:12 OK 1_commit_pending_closure.sql (3.1ms)12802026/09/21 18:37:12 OK 2_object_stats_trigger.sql (513.5µs)12812026/09/21 18:37:12 goose: up to current file version: 212822026/09/21 18:37:12 OK 20241026095416_initial_model.sql (57.84ms)12832026/09/21 18:37:12 OK 20251210153512_drop_unused_gin_index.sql (8.41ms)12842026/09/21 18:37:12 OK 20251218171726_add_pins.sql (25.96ms)12852026/09/21 18:37:12 OK 20260628120000_add_object_size_and_stats.sql (35.18ms)12862026/09/21 18:37:12 INFO lead: acquired remote=192.0.2.1:123412872026/09/21 18:37:12 INFO lead: released remote=192.0.2.1:12341288--- PASS: TestLeadEndsOnShutdown (1.81s)1289=== CONT TestObjectStatsTrigger12902026/09/21 18:37:12 OK 20260905000000_add_claims.sql (68.74ms)1291--- PASS: TestGCBugBareHashReferences (2.12s)1292=== CONT TestMultipartCleanup12932026/09/21 18:37:12 OK 20260920000000_drop_claims.sql (52.57ms)12942026/09/21 18:37:12 goose: successfully migrated database to version: 2026092000000012952026/09/21 18:37:12 OK 1_commit_pending_closure.sql (1.91ms)12962026/09/21 18:37:12 OK 2_object_stats_trigger.sql (409µs)12972026/09/21 18:37:12 goose: up to current file version: 212982026-09-21 18:37:12.373 UTC [25935] ERROR: relation "goose_db_version" does not exist at character 3612992026-09-21 18:37:12.373 UTC [25935] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13002026/09/21 18:37:12 INFO lead: acquired remote=192.0.2.1:123413012026/09/21 18:37:12 OK 20241026095416_initial_model.sql (184.1ms)13022026/09/21 18:37:12 OK 20251210153512_drop_unused_gin_index.sql (4.26ms)13032026-09-21 18:37:12.647 UTC [25937] ERROR: relation "goose_db_version" does not exist at character 3613042026-09-21 18:37:12.647 UTC [25937] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13052026/09/21 18:37:12 OK 20251218171726_add_pins.sql (22.6ms)13062026/09/21 18:37:12 OK 20260628120000_add_object_size_and_stats.sql (23.05ms)13072026/09/21 18:37:12 INFO lead: released remote=192.0.2.1:123413082026/09/21 18:37:12 INFO lead: acquired remote=192.0.2.1:123413092026/09/21 18:37:12 INFO lead: released remote=192.0.2.1:12341310--- PASS: TestLeadElectsOneAndHandsOver (1.98s)1311=== CONT TestService_ReadScope_PublicByDefault13122026/09/21 18:37:12 OK 20260905000000_add_claims.sql (99.49ms)13132026/09/21 18:37:12 OK 20260920000000_drop_claims.sql (32.7ms)13142026/09/21 18:37:12 goose: successfully migrated database to version: 2026092000000013152026/09/21 18:37:12 OK 1_commit_pending_closure.sql (3.28ms)13162026/09/21 18:37:12 OK 2_object_stats_trigger.sql (615µs)13172026/09/21 18:37:12 goose: up to current file version: 213182026/09/21 18:37:12 OK 20241026095416_initial_model.sql (210.36ms)13192026/09/21 18:37:12 OK 20251210153512_drop_unused_gin_index.sql (14.06ms)13202026/09/21 18:37:12 OK 20251218171726_add_pins.sql (32.32ms)13212026-09-21 18:37:12.943 UTC [25941] ERROR: relation "goose_db_version" does not exist at character 3613222026-09-21 18:37:12.943 UTC [25941] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13232026/09/21 18:37:12 OK 20260628120000_add_object_size_and_stats.sql (36.72ms)13242026-09-21 18:37:12.985 UTC [25942] ERROR: relation "goose_db_version" does not exist at character 3613252026-09-21 18:37:12.985 UTC [25942] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13262026/09/21 18:37:13 OK 20260905000000_add_claims.sql (72.01ms)13272026/09/21 18:37:13 OK 20260920000000_drop_claims.sql (22.04ms)13282026/09/21 18:37:13 goose: successfully migrated database to version: 2026092000000013292026/09/21 18:37:13 OK 1_commit_pending_closure.sql (4.76ms)13302026/09/21 18:37:13 OK 2_object_stats_trigger.sql (791.58µs)13312026/09/21 18:37:13 goose: up to current file version: 21332--- PASS: TestReadProxyNarStreaming (2.02s)1333=== CONT TestService_RequireScope_OIDC13342026/09/21 18:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51709/oidc13352026/09/21 18:37:13 OK 20241026095416_initial_model.sql (178.7ms)13362026/09/21 18:37:13 OK 20251210153512_drop_unused_gin_index.sql (10.35ms)13372026/09/21 18:37:13 OK 20251218171726_add_pins.sql (23.34ms)13382026/09/21 18:37:13 OK 20260628120000_add_object_size_and_stats.sql (39.84ms)13392026/09/21 18:37:13 OK 20241026095416_initial_model.sql (221.22ms)13402026/09/21 18:37:13 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)13412026/09/21 18:37:13 OK 20251218171726_add_pins.sql (16.38ms)13422026/09/21 18:37:13 OK 20260905000000_add_claims.sql (30.97ms)13432026-09-21 18:37:13.312 UTC [25945] ERROR: relation "goose_db_version" does not exist at character 3613442026-09-21 18:37:13.312 UTC [25945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13452026/09/21 18:37:13 OK 20260628120000_add_object_size_and_stats.sql (32.09ms)13462026/09/21 18:37:13 OK 20260920000000_drop_claims.sql (39.41ms)13472026/09/21 18:37:13 goose: successfully migrated database to version: 2026092000000013482026/09/21 18:37:13 OK 1_commit_pending_closure.sql (3.95ms)13492026/09/21 18:37:13 OK 2_object_stats_trigger.sql (696.96µs)13502026/09/21 18:37:13 goose: up to current file version: 213512026/09/21 18:37:13 OK 20260905000000_add_claims.sql (96.98ms)13522026/09/21 18:37:13 OK 20260920000000_drop_claims.sql (16.21ms)13532026/09/21 18:37:13 goose: successfully migrated database to version: 2026092000000013542026/09/21 18:37:13 OK 1_commit_pending_closure.sql (6.69ms)13552026/09/21 18:37:13 OK 2_object_stats_trigger.sql (2.95ms)13562026/09/21 18:37:13 goose: up to current file version: 21357--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.06s)1358=== CONT TestService_AuthMiddleware_OIDC13592026/09/21 18:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51714/oidc13602026/09/21 18:37:13 OK 20241026095416_initial_model.sql (82.73ms)13612026-09-21 18:37:13.483 UTC [25947] ERROR: relation "goose_db_version" does not exist at character 3613622026-09-21 18:37:13.483 UTC [25947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13632026/09/21 18:37:13 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)13642026/09/21 18:37:13 OK 20251218171726_add_pins.sql (24.73ms)13652026/09/21 18:37:13 OK 20260628120000_add_object_size_and_stats.sql (27.62ms)13662026/09/21 18:37:13 OK 20260905000000_add_claims.sql (49.96ms)13672026/09/21 18:37:13 OK 20260920000000_drop_claims.sql (44.73ms)13682026/09/21 18:37:13 goose: successfully migrated database to version: 2026092000000013692026/09/21 18:37:13 OK 1_commit_pending_closure.sql (3.76ms)13702026/09/21 18:37:13 OK 2_object_stats_trigger.sql (999.21µs)13712026/09/21 18:37:13 goose: up to current file version: 213722026/09/21 18:37:13 OK 20241026095416_initial_model.sql (193.19ms)1373--- PASS: TestReadProxyNarinfo (2.18s)1374=== CONT TestService_ReadAuthMiddleware13752026/09/21 18:37:13 OK 20251210153512_drop_unused_gin_index.sql (14.45ms)13762026/09/21 18:37:13 OK 20251218171726_add_pins.sql (21.14ms)13772026/09/21 18:37:13 OK 20260628120000_add_object_size_and_stats.sql (34.27ms)13782026/09/21 18:37:13 OK 20260905000000_add_claims.sql (78.12ms)13792026/09/21 18:37:13 OK 20260920000000_drop_claims.sql (39.08ms)13802026/09/21 18:37:13 goose: successfully migrated database to version: 2026092000000013812026/09/21 18:37:13 OK 1_commit_pending_closure.sql (5.17ms)13822026/09/21 18:37:13 OK 2_object_stats_trigger.sql (2ms)13832026/09/21 18:37:13 goose: up to current file version: 213842026/09/21 18:37:13 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13852026/09/21 18:37:13 WARN Refused reserved pin name=worker-x86_64-linux13862026/09/21 18:37:13 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13872026/09/21 18:37:13 INFO Received create pin request method=POST path=/api/pins/my-app13882026/09/21 18:37:13 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1389--- PASS: TestCreatePin_ReservedPins (2.44s)1390=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13912026-09-21 18:37:14.302 UTC [25953] ERROR: relation "goose_db_version" does not exist at character 3613922026-09-21 18:37:14.302 UTC [25953] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13932026-09-21 18:37:14.380 UTC [25954] ERROR: relation "goose_db_version" does not exist at character 3613942026-09-21 18:37:14.380 UTC [25954] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1395--- PASS: TestResurrectedObjectNotDeleted (2.71s)1396=== CONT TestService_AuthMiddleware_MTLSProxyHeader13972026/09/21 18:37:14 OK 20241026095416_initial_model.sql (131.8ms)13982026/09/21 18:37:14 OK 20251210153512_drop_unused_gin_index.sql (7.5ms)13992026-09-21 18:37:14.527 UTC [25963] ERROR: relation "goose_db_version" does not exist at character 3614002026-09-21 18:37:14.527 UTC [25963] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14012026/09/21 18:37:14 OK 20251218171726_add_pins.sql (12.74ms)14022026/09/21 18:37:14 OK 20241026095416_initial_model.sql (129.96ms)14032026/09/21 18:37:14 OK 20251210153512_drop_unused_gin_index.sql (8.32ms)14042026/09/21 18:37:14 OK 20260628120000_add_object_size_and_stats.sql (32.72ms)14052026/09/21 18:37:14 OK 20251218171726_add_pins.sql (28.57ms)14062026/09/21 18:37:14 OK 20260905000000_add_claims.sql (35.83ms)14072026/09/21 18:37:14 OK 20260628120000_add_object_size_and_stats.sql (24.08ms)14082026/09/21 18:37:14 OK 20260920000000_drop_claims.sql (19.47ms)14092026/09/21 18:37:14 goose: successfully migrated database to version: 2026092000000014102026/09/21 18:37:14 OK 1_commit_pending_closure.sql (3.53ms)14112026/09/21 18:37:14 OK 2_object_stats_trigger.sql (748.38µs)14122026/09/21 18:37:14 goose: up to current file version: 214132026/09/21 18:37:14 OK 20260905000000_add_claims.sql (47.77ms)14142026/09/21 18:37:14 OK 20260920000000_drop_claims.sql (31.48ms)14152026/09/21 18:37:14 goose: successfully migrated database to version: 2026092000000014162026/09/21 18:37:14 OK 1_commit_pending_closure.sql (3.61ms)14172026/09/21 18:37:14 OK 2_object_stats_trigger.sql (679.83µs)14182026/09/21 18:37:14 goose: up to current file version: 214192026/09/21 18:37:14 OK 20241026095416_initial_model.sql (132.9ms)14202026/09/21 18:37:14 OK 20251210153512_drop_unused_gin_index.sql (8.9ms)14212026/09/21 18:37:14 OK 20251218171726_add_pins.sql (17.35ms)14222026/09/21 18:37:14 OK 20260628120000_add_object_size_and_stats.sql (27.16ms)14232026/09/21 18:37:14 OK 20260905000000_add_claims.sql (69.31ms)14242026/09/21 18:37:14 OK 20260920000000_drop_claims.sql (35.09ms)14252026/09/21 18:37:14 goose: successfully migrated database to version: 2026092000000014262026/09/21 18:37:14 OK 1_commit_pending_closure.sql (4.72ms)14272026/09/21 18:37:14 OK 2_object_stats_trigger.sql (1.02ms)14282026/09/21 18:37:14 goose: up to current file version: 214292026/09/21 18:37:14 INFO Received uploads request method=POST path=/api/pending_closures14302026-09-21 18:37:14.955 UTC [25964] ERROR: relation "goose_db_version" does not exist at character 3614312026-09-21 18:37:14.955 UTC [25964] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14322026/09/21 18:37:15 INFO Received cleanup request method=DELETE path=/api/pending_closures14332026/09/21 18:37:15 INFO Aborted multipart uploads count=11434--- PASS: TestMultipartCleanup (2.81s)1435=== CONT TestClientMultipleUploads14362026/09/21 18:37:15 OK 20241026095416_initial_model.sql (248.21ms)1437=== NAME TestOrphanedObjectsGC1438 orphaned_objects_gc_test.go:290: GC Test Summary:1439 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1440 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1441 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1442 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1443 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1444--- PASS: TestOrphanedObjectsGC (3.41s)1445=== CONT TestMetricsInventory14462026/09/21 18:37:15 OK 20251210153512_drop_unused_gin_index.sql (14.92ms)14472026/09/21 18:37:15 OK 20251218171726_add_pins.sql (33.02ms)1448--- PASS: TestObjectStatsTrigger (3.09s)1449=== CONT TestService_NativeMTLS14502026/09/21 18:37:15 OK 20260628120000_add_object_size_and_stats.sql (28ms)14512026-09-21 18:37:15.372 UTC [25968] ERROR: relation "goose_db_version" does not exist at character 3614522026-09-21 18:37:15.372 UTC [25968] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14532026/09/21 18:37:15 OK 20260905000000_add_claims.sql (52.82ms)14542026/09/21 18:37:15 OK 20260920000000_drop_claims.sql (39.03ms)14552026/09/21 18:37:15 goose: successfully migrated database to version: 2026092000000014562026/09/21 18:37:15 OK 1_commit_pending_closure.sql (3.1ms)14572026/09/21 18:37:15 OK 2_object_stats_trigger.sql (602.08µs)14582026/09/21 18:37:15 goose: up to current file version: 21459--- PASS: TestService_ReadScope_PublicByDefault (2.75s)1460=== CONT TestPinProtectsFromGC14612026/09/21 18:37:15 OK 20241026095416_initial_model.sql (156.74ms)14622026/09/21 18:37:15 OK 20251210153512_drop_unused_gin_index.sql (14.22ms)14632026-09-21 18:37:15.603 UTC [25974] ERROR: relation "goose_db_version" does not exist at character 3614642026-09-21 18:37:15.603 UTC [25974] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14652026/09/21 18:37:15 OK 20251218171726_add_pins.sql (48.39ms)14662026/09/21 18:37:15 OK 20260628120000_add_object_size_and_stats.sql (28.59ms)14672026/09/21 18:37:15 OK 20260905000000_add_claims.sql (63.65ms)14682026/09/21 18:37:15 OK 20260920000000_drop_claims.sql (41.47ms)14692026/09/21 18:37:15 goose: successfully migrated database to version: 2026092000000014702026/09/21 18:37:15 OK 1_commit_pending_closure.sql (4.57ms)14712026/09/21 18:37:15 OK 2_object_stats_trigger.sql (2.38ms)14722026/09/21 18:37:15 goose: up to current file version: 21473=== RUN TestService_RequireScope_OIDC/builder_may_write1474=== PAUSE TestService_RequireScope_OIDC/builder_may_write1475=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1476=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1477=== RUN TestService_RequireScope_OIDC/ops_may_admin1478=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1479=== RUN TestService_RequireScope_OIDC/ops_may_not_write1480=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1481=== RUN TestService_RequireScope_OIDC/reader_may_not_write1482=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1483=== RUN TestService_RequireScope_OIDC/static_token_may_admin1484=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1485=== RUN TestService_RequireScope_OIDC/static_token_may_write1486=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1487=== RUN TestService_RequireScope_OIDC/reader_may_read1488=== PAUSE TestService_RequireScope_OIDC/reader_may_read1489=== RUN TestService_RequireScope_OIDC/writer_implies_read1490=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1491=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1492=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1493=== CONT TestClientSharedPathCommittedMidPush14942026/09/21 18:37:15 OK 20241026095416_initial_model.sql (139.47ms)14952026/09/21 18:37:15 OK 20251210153512_drop_unused_gin_index.sql (12.75ms)14962026/09/21 18:37:15 OK 20251218171726_add_pins.sql (35.79ms)14972026/09/21 18:37:15 OK 20260628120000_add_object_size_and_stats.sql (36.11ms)14982026/09/21 18:37:15 OK 20260905000000_add_claims.sql (45.76ms)14992026-09-21 18:37:15.948 UTC [25977] ERROR: relation "goose_db_version" does not exist at character 3615002026-09-21 18:37:15.948 UTC [25977] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15012026/09/21 18:37:15 OK 20260920000000_drop_claims.sql (11.18ms)15022026/09/21 18:37:15 goose: successfully migrated database to version: 2026092000000015032026/09/21 18:37:15 OK 1_commit_pending_closure.sql (2.74ms)15042026/09/21 18:37:15 OK 2_object_stats_trigger.sql (513.63µs)15052026/09/21 18:37:15 goose: up to current file version: 21506=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1507=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1508=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1509=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1510=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1511=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1512=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1513=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1514=== CONT TestClientWithDependencies15152026/09/21 18:37:16 OK 20241026095416_initial_model.sql (67.69ms)15162026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (9.82ms)15172026-09-21 18:37:16.060 UTC [25979] ERROR: relation "goose_db_version" does not exist at character 3615182026-09-21 18:37:16.060 UTC [25979] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15192026/09/21 18:37:16 OK 20251218171726_add_pins.sql (6.76ms)15202026/09/21 18:37:16 OK 20260628120000_add_object_size_and_stats.sql (14.56ms)15212026/09/21 18:37:16 OK 20260905000000_add_claims.sql (33.38ms)15222026/09/21 18:37:16 OK 20260920000000_drop_claims.sql (27.3ms)15232026/09/21 18:37:16 goose: successfully migrated database to version: 2026092000000015242026/09/21 18:37:16 OK 1_commit_pending_closure.sql (2.98ms)15252026/09/21 18:37:16 OK 2_object_stats_trigger.sql (547.5µs)15262026/09/21 18:37:16 goose: up to current file version: 215272026/09/21 18:37:16 OK 20241026095416_initial_model.sql (85.54ms)15282026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (7.05ms)15292026/09/21 18:37:16 OK 20251218171726_add_pins.sql (18.56ms)1530--- PASS: TestService_ReadAuthMiddleware (2.49s)1531=== CONT TestClientErrorHandling1532=== RUN TestClientErrorHandling/InvalidStorePath1533=== PAUSE TestClientErrorHandling/InvalidStorePath1534=== RUN TestClientErrorHandling/InvalidAuthToken1535=== PAUSE TestClientErrorHandling/InvalidAuthToken1536=== RUN TestClientErrorHandling/ServerNotAvailable1537=== PAUSE TestClientErrorHandling/ServerNotAvailable1538=== CONT TestClientIntegration15392026/09/21 18:37:16 OK 20260628120000_add_object_size_and_stats.sql (31.33ms)15402026/09/21 18:37:16 OK 20260905000000_add_claims.sql (6.13ms)15412026/09/21 18:37:16 OK 20260920000000_drop_claims.sql (15.75ms)15422026/09/21 18:37:16 goose: successfully migrated database to version: 2026092000000015432026/09/21 18:37:16 OK 1_commit_pending_closure.sql (2.49ms)15442026/09/21 18:37:16 OK 2_object_stats_trigger.sql (464.92µs)15452026/09/21 18:37:16 goose: up to current file version: 215462026/09/21 18:37:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15472026/09/21 18:37:16 WARN mTLS auth: bound subjects configured but subject DN unavailable15482026/09/21 18:37:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1549--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.41s)1550=== CONT TestNARDeduplicationMetadataUploadBug15512026-09-21 18:37:16.501 UTC [25988] ERROR: relation "goose_db_version" does not exist at character 3615522026-09-21 18:37:16.501 UTC [25988] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1553--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.21s)1554=== CONT TestCreatePendingClosureRejectsOversizedNAR15552026/09/21 18:37:16 INFO Received uploads request method=POST path=/api/pending_closures15562026-09-21 18:37:16.621 UTC [25989] ERROR: relation "goose_db_version" does not exist at character 3615572026-09-21 18:37:16.621 UTC [25989] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1558--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1559=== CONT TestClientCADerivations15602026/09/21 18:37:16 OK 20241026095416_initial_model.sql (76.59ms)15612026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)15622026-09-21 18:37:16.634 UTC [25991] ERROR: relation "goose_db_version" does not exist at character 3615632026-09-21 18:37:16.634 UTC [25991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15642026-09-21 18:37:16.635 UTC [25992] ERROR: relation "goose_db_version" does not exist at character 3615652026-09-21 18:37:16.635 UTC [25992] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15662026/09/21 18:37:16 OK 20251218171726_add_pins.sql (5.5ms)15672026/09/21 18:37:16 OK 20260628120000_add_object_size_and_stats.sql (5.81ms)15682026/09/21 18:37:16 OK 20260905000000_add_claims.sql (4.85ms)15692026/09/21 18:37:16 OK 20260920000000_drop_claims.sql (1.91ms)15702026/09/21 18:37:16 goose: successfully migrated database to version: 2026092000000015712026/09/21 18:37:16 OK 1_commit_pending_closure.sql (1.97ms)15722026/09/21 18:37:16 OK 2_object_stats_trigger.sql (559.46µs)15732026/09/21 18:37:16 goose: up to current file version: 215742026/09/21 18:37:16 OK 20241026095416_initial_model.sql (27.61ms)15752026/09/21 18:37:16 OK 20241026095416_initial_model.sql (21.54ms)15762026/09/21 18:37:16 OK 20241026095416_initial_model.sql (28.1ms)15772026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (9.57ms)15782026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (9.68ms)15792026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (8.48ms)15802026/09/21 18:37:16 OK 20251218171726_add_pins.sql (19.48ms)15812026/09/21 18:37:16 OK 20251218171726_add_pins.sql (12.55ms)15822026/09/21 18:37:16 OK 20251218171726_add_pins.sql (20.06ms)15832026/09/21 18:37:16 OK 20260628120000_add_object_size_and_stats.sql (14.39ms)15842026/09/21 18:37:16 OK 20260628120000_add_object_size_and_stats.sql (20.28ms)15852026/09/21 18:37:16 OK 20260628120000_add_object_size_and_stats.sql (21.56ms)15862026/09/21 18:37:16 OK 20260905000000_add_claims.sql (32.75ms)15872026/09/21 18:37:16 OK 20260905000000_add_claims.sql (26.5ms)15882026/09/21 18:37:16 OK 20260905000000_add_claims.sql (27.32ms)15892026/09/21 18:37:16 OK 20260920000000_drop_claims.sql (4.95ms)15902026/09/21 18:37:16 goose: successfully migrated database to version: 2026092000000015912026/09/21 18:37:16 OK 20260920000000_drop_claims.sql (4.61ms)15922026/09/21 18:37:16 goose: successfully migrated database to version: 2026092000000015932026/09/21 18:37:16 OK 1_commit_pending_closure.sql (1.83ms)15942026/09/21 18:37:16 OK 1_commit_pending_closure.sql (1.75ms)15952026/09/21 18:37:16 OK 2_object_stats_trigger.sql (413.29µs)15962026/09/21 18:37:16 goose: up to current file version: 215972026/09/21 18:37:16 OK 2_object_stats_trigger.sql (440.75µs)15982026/09/21 18:37:16 goose: up to current file version: 215992026/09/21 18:37:16 OK 20260920000000_drop_claims.sql (11.94ms)16002026/09/21 18:37:16 goose: successfully migrated database to version: 2026092000000016012026/09/21 18:37:16 OK 1_commit_pending_closure.sql (1.86ms)16022026/09/21 18:37:16 OK 2_object_stats_trigger.sql (422.96µs)16032026/09/21 18:37:16 goose: up to current file version: 216042026-09-21 18:37:16.882 UTC [25994] ERROR: relation "goose_db_version" does not exist at character 3616052026-09-21 18:37:16.882 UTC [25994] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16062026/09/21 18:37:16 OK 20241026095416_initial_model.sql (77.25ms)16072026/09/21 18:37:16 OK 20251210153512_drop_unused_gin_index.sql (6.65ms)1608=== NAME TestClientMultipleUploads1609 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-25706-3937147719/TestClientMultipleUploads4101475090/001/store/dxa4wcgj5sl1zk6rcx51cgbziz7d8379-test-file-0.txt16102026/09/21 18:37:17 OK 20251218171726_add_pins.sql (21.34ms)16112026/09/21 18:37:17 OK 20260628120000_add_object_size_and_stats.sql (14.69ms)16122026-09-21 18:37:17.038 UTC [25998] ERROR: relation "goose_db_version" does not exist at character 3616132026-09-21 18:37:17.038 UTC [25998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16142026/09/21 18:37:17 OK 20260905000000_add_claims.sql (32.79ms)1615 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-25706-3937147719/TestClientMultipleUploads4101475090/001/store/x14x6z5pp87nw21xc2gcarsb35xps1bi-test-file-1.txt16162026/09/21 18:37:17 OK 20260920000000_drop_claims.sql (2.34ms)16172026/09/21 18:37:17 goose: successfully migrated database to version: 2026092000000016182026/09/21 18:37:17 OK 1_commit_pending_closure.sql (1.36ms)16192026/09/21 18:37:17 OK 2_object_stats_trigger.sql (313.29µs)16202026/09/21 18:37:17 goose: up to current file version: 216212026-09-21 18:37:17.077 UTC [26001] ERROR: relation "goose_db_version" does not exist at character 3616222026-09-21 18:37:17.077 UTC [26001] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16232026/09/21 18:37:17 OK 20241026095416_initial_model.sql (47.35ms)1624 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-25706-3937147719/TestClientMultipleUploads4101475090/001/store/2qqwx5b1hcnyiifq68l6xxldc7655n0s-test-file-2.txt16252026/09/21 18:37:17 OK 20251210153512_drop_unused_gin_index.sql (8ms)16262026/09/21 18:37:17 OK 20251218171726_add_pins.sql (1.56ms)16272026/09/21 18:37:17 OK 20260628120000_add_object_size_and_stats.sql (22.77ms)16282026/09/21 18:37:17 OK 20260905000000_add_claims.sql (15.52ms)16292026/09/21 18:37:17 OK 20241026095416_initial_model.sql (67.75ms)16302026/09/21 18:37:17 OK 20260920000000_drop_claims.sql (2.47ms)16312026/09/21 18:37:17 goose: successfully migrated database to version: 2026092000000016322026/09/21 18:37:17 OK 1_commit_pending_closure.sql (847.92µs)16332026/09/21 18:37:17 OK 2_object_stats_trigger.sql (201.58µs)16342026/09/21 18:37:17 goose: up to current file version: 216352026/09/21 18:37:17 OK 20251210153512_drop_unused_gin_index.sql (9.31ms)16362026/09/21 18:37:17 OK 20251218171726_add_pins.sql (12.99ms)16372026/09/21 18:37:17 OK 20260628120000_add_object_size_and_stats.sql (15.43ms)16382026/09/21 18:37:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1639=== NAME TestPinProtectsFromGC1640 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-25706-3937147719/TestPinProtectsFromGC358889863/001/store/wndbw9ki2dz5ly9gi6d64baq8zrd9pb8-pinned-file.txt1641 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-25706-3937147719/TestPinProtectsFromGC358889863/001/store/dh2fsbc450jdhh8f5l2d0i0x2r3n16y5-unpinned-file.txt16422026/09/21 18:37:17 OK 20260905000000_add_claims.sql (20.79ms)16432026/09/21 18:37:17 OK 20260920000000_drop_claims.sql (15.09ms)16442026/09/21 18:37:17 goose: successfully migrated database to version: 2026092000000016452026/09/21 18:37:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16462026/09/21 18:37:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1647--- PASS: TestService_NativeMTLS (1.90s)1648=== CONT TestCacheStatsHandler16492026/09/21 18:37:17 OK 1_commit_pending_closure.sql (3.51ms)16502026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures16512026/09/21 18:37:17 OK 2_object_stats_trigger.sql (827.67µs)16522026/09/21 18:37:17 goose: up to current file version: 216532026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures16542026-09-21 18:37:17.245 UTC [26016] ERROR: relation "goose_db_version" does not exist at character 3616552026-09-21 18:37:17.245 UTC [26016] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16562026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures16572026/09/21 18:37:17 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16582026/09/21 18:37:17 INFO Uploading 2qqwx5b1hcnyiifq68l6xxldc7655n0s-test-file-2.txt (160B)16592026/09/21 18:37:17 INFO Uploading x14x6z5pp87nw21xc2gcarsb35xps1bi-test-file-1.txt (160B)16602026/09/21 18:37:17 INFO Uploading dxa4wcgj5sl1zk6rcx51cgbziz7d8379-test-file-0.txt (160B)16612026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16622026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16632026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16642026/09/21 18:37:17 WARN Failed to register uploaded object key=x14x6z5pp87nw21xc2gcarsb35xps1bi.ls error="server returned 404: 404 page not found\n"16652026/09/21 18:37:17 WARN Failed to register uploaded object key=2qqwx5b1hcnyiifq68l6xxldc7655n0s.ls error="server returned 404: 404 page not found\n"16662026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign16672026/09/21 18:37:17 WARN Failed to register uploaded object key=dxa4wcgj5sl1zk6rcx51cgbziz7d8379.ls error="server returned 404: 404 page not found\n"16682026/09/21 18:37:17 INFO Signed narinfos id=3 count=116692026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16702026/09/21 18:37:17 INFO Signed narinfos id=1 count=116712026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16722026/09/21 18:37:17 INFO Signed narinfos id=2 count=116732026/09/21 18:37:17 INFO Uploading 3 narinfos16742026/09/21 18:37:17 WARN Failed to register uploaded object key=2qqwx5b1hcnyiifq68l6xxldc7655n0s.narinfo error="server returned 404: 404 page not found\n"16752026/09/21 18:37:17 WARN Failed to register uploaded object key=dxa4wcgj5sl1zk6rcx51cgbziz7d8379.narinfo error="server returned 404: 404 page not found\n"16762026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16772026/09/21 18:37:17 WARN Failed to register uploaded object key=x14x6z5pp87nw21xc2gcarsb35xps1bi.narinfo error="server returned 404: 404 page not found\n"16782026/09/21 18:37:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1679=== NAME TestOrphanedObjectsGCStressTest1680 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains16812026/09/21 18:37:17 INFO Completed upload id=116822026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16832026/09/21 18:37:17 INFO Completed upload id=216842026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete16852026/09/21 18:37:17 INFO Completed upload id=316862026/09/21 18:37:17 INFO Upload complete. (138ms)1687=== NAME TestClientMultipleUploads1688 client_integration_test.go:369: Uploaded 3 paths in 179.613708ms16892026-09-21 18:37:17.301 UTC [26021] ERROR: relation "goose_db_version" does not exist at character 3616902026-09-21 18:37:17.301 UTC [26021] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16912026/09/21 18:37:17 OK 20241026095416_initial_model.sql (25ms)16922026/09/21 18:37:17 OK 20251210153512_drop_unused_gin_index.sql (957.21µs)16932026/09/21 18:37:17 OK 20251218171726_add_pins.sql (11.76ms)1694--- PASS: TestClientMultipleUploads (2.22s)1695=== CONT TestCacheConfigHandler1696=== RUN TestCacheConfigHandler/full_config,_no_issuer1697=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1698=== RUN TestCacheConfigHandler/no_cache_url_configured1699=== PAUSE TestCacheConfigHandler/no_cache_url_configured1700=== RUN TestCacheConfigHandler/no_signing_keys1701=== PAUSE TestCacheConfigHandler/no_signing_keys1702=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1703=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1704=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17052026/09/21 18:37:17 INFO Received uploads request method=POST path=/1706=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17072026/09/21 18:37:17 INFO Received request for more parts method=POST path=/1708=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17092026/09/21 18:37:17 INFO Received complete multipart upload request method=POST path=/1710=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17112026/09/21 18:37:17 INFO Received uploads request method=POST path=/1712--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1713 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1714 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1715 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1716 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1717=== CONT TestProxyWriteTimeout/narinfo1718=== CONT TestProxyWriteTimeout/unknown_size1719=== CONT TestProxyWriteTimeout/10_GiB_nar1720=== CONT TestProxyWriteTimeout/1_GiB_nar1721--- PASS: TestProxyWriteTimeout (0.00s)1722 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1723 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1724 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1725 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1726=== CONT TestIsValidUploadKey/narinfo1727=== CONT TestIsValidUploadKey/realisation_plus_in_output1728=== CONT TestIsValidUploadKey/unknown_type1729=== CONT TestIsValidUploadKey/empty_key1730=== CONT TestIsValidUploadKey/absolute1731=== CONT TestIsValidUploadKey/traversal_nar1732=== CONT TestIsValidUploadKey/traversal1733=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1734=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1735=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1736=== CONT TestIsValidUploadKey/index.html1737=== CONT TestIsValidUploadKey/nix-cache-info1738=== CONT TestIsValidUploadKey/build_log_home-manager_file1739=== CONT TestIsValidUploadKey/realisation1740=== CONT TestIsValidUploadKey/build_log_equals1741=== CONT TestIsValidUploadKey/build_log_question_mark1742=== CONT TestIsValidUploadKey/build_log_plus_in_name1743=== CONT TestIsValidUploadKey/nar_plain1744=== CONT TestIsValidUploadKey/build_log1745=== CONT TestIsValidUploadKey/listing1746=== CONT TestIsValidUploadKey/nar_xz1747=== CONT TestIsValidUploadKey/nar_zst1748--- PASS: TestIsValidUploadKey (0.02s)1749 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1750 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1751 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1752 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1753 --- PASS: TestIsValidUploadKey/absolute (0.00s)1754 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1755 --- PASS: TestIsValidUploadKey/traversal (0.00s)1756 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1757 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1758 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1759 --- PASS: TestIsValidUploadKey/index.html (0.00s)1760 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1761 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1762 --- PASS: TestIsValidUploadKey/realisation (0.00s)1763 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1764 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1765 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1766 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log (0.00s)1768 --- PASS: TestIsValidUploadKey/listing (0.00s)1769 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1770 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1771=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17722026/09/21 18:37:17 INFO Received uploads request method=POST path=/1773=== NAME TestOrphanedObjectsGCStressTest1774 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion17752026/09/21 18:37:17 OK 20260628120000_add_object_size_and_stats.sql (3ms)17762026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures17772026/09/21 18:37:17 OK 20260905000000_add_claims.sql (18.84ms)17782026/09/21 18:37:17 OK 20260920000000_drop_claims.sql (7.94ms)17792026/09/21 18:37:17 goose: successfully migrated database to version: 2026092000000017802026/09/21 18:37:17 OK 1_commit_pending_closure.sql (991.04µs)17812026/09/21 18:37:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17822026/09/21 18:37:17 INFO Uploading wndbw9ki2dz5ly9gi6d64baq8zrd9pb8-pinned-file.txt (128B)17832026/09/21 18:37:17 OK 2_object_stats_trigger.sql (471.63µs)17842026/09/21 18:37:17 goose: up to current file version: 217852026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17862026/09/21 18:37:17 OK 20241026095416_initial_model.sql (48.82ms)17872026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17882026/09/21 18:37:17 INFO Signed narinfos id=1 count=117892026/09/21 18:37:17 WARN Failed to register uploaded object key=wndbw9ki2dz5ly9gi6d64baq8zrd9pb8.ls error="server returned 404: 404 page not found\n"17902026/09/21 18:37:17 INFO Uploading 1 narinfos17912026/09/21 18:37:17 OK 20251210153512_drop_unused_gin_index.sql (7.07ms)17922026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17932026/09/21 18:37:17 WARN Failed to register uploaded object key=wndbw9ki2dz5ly9gi6d64baq8zrd9pb8.narinfo error="server returned 404: 404 page not found\n"17942026/09/21 18:37:17 OK 20251218171726_add_pins.sql (1.63ms)17952026/09/21 18:37:17 INFO Completed upload id=117962026/09/21 18:37:17 INFO Upload complete. (140ms)17972026/09/21 18:37:17 OK 20260628120000_add_object_size_and_stats.sql (19.42ms)17982026/09/21 18:37:17 OK 20260905000000_add_claims.sql (5.21ms)17992026/09/21 18:37:17 OK 20260920000000_drop_claims.sql (1.07ms)18002026/09/21 18:37:17 goose: successfully migrated database to version: 2026092000000018012026/09/21 18:37:17 OK 1_commit_pending_closure.sql (1.42ms)18022026/09/21 18:37:17 OK 2_object_stats_trigger.sql (338.21µs)18032026/09/21 18:37:17 goose: up to current file version: 21804--- PASS: TestMetricsInventory (2.11s)1805=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18062026/09/21 18:37:17 INFO Received request for more parts method=POST path=/1807=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18082026/09/21 18:37:17 INFO Received complete multipart upload request method=POST path=/1809=== CONT TestResolveDBConnectionString/flag_wins1810=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1811=== CONT TestResolveDBConnectionString/nothing_configured1812=== CONT TestResolveDBConnectionString/missing_file_is_an_error1813=== CONT TestResolveDBConnectionString/file_when_flag_empty1814=== CONT TestIsValidCachePath/narinfo1815=== CONT TestIsValidCachePath/index.html1816=== CONT TestIsValidCachePath/short_hash1817=== CONT TestIsValidCachePath/wrong_extension1818=== CONT TestIsValidCachePath/leading_slash1819=== CONT TestIsValidCachePath/empty1820=== CONT TestIsValidCachePath/random_path1821=== CONT TestIsValidCachePath/invalid_char_u1822=== CONT TestIsValidCachePath/invalid_char_e1823=== CONT TestIsValidCachePath/traversal_in_middle1824=== CONT TestIsValidCachePath/traversal_parent1825=== CONT TestIsValidCachePath/nar_uncompressed1826=== CONT TestIsValidCachePath/nix-cache-info1827=== CONT TestIsValidCachePath/realisation1828=== CONT TestIsValidCachePath/log1829=== CONT TestIsValidCachePath/ls1830=== CONT TestIsValidCachePath/nar_zst1831=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1832=== CONT TestIsValidCachePath/nar_bz21833=== CONT TestIsValidCachePath/nar_xz1834--- PASS: TestIsValidCachePath (0.00s)1835 --- PASS: TestIsValidCachePath/narinfo (0.00s)1836 --- PASS: TestIsValidCachePath/index.html (0.00s)1837 --- PASS: TestIsValidCachePath/short_hash (0.00s)1838 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1839 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1840 --- PASS: TestIsValidCachePath/empty (0.00s)1841 --- PASS: TestIsValidCachePath/random_path (0.00s)1842 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1843 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1844 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1845 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1846 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1847 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1848 --- PASS: TestIsValidCachePath/realisation (0.00s)1849 --- PASS: TestIsValidCachePath/log (0.00s)1850 --- PASS: TestIsValidCachePath/ls (0.00s)1851 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1852 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1853 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1854 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1855=== CONT TestParseSingleRange/none1856=== CONT TestParseSingleRange/open-ended1857=== CONT TestParseSingleRange/start_far_past_EOF1858=== CONT TestParseSingleRange/start_past_EOF1859=== CONT TestParseSingleRange/single_byte1860=== CONT TestParseSingleRange/suffix_exceeds_size1861=== CONT TestParseSingleRange/suffix1862=== CONT TestParseSingleRange/end_clamped_to_size1863=== CONT TestParseSingleRange/malformed_both_empty1864=== CONT TestParseSingleRange/closed1865=== CONT TestParseSingleRange/malformed_end_before_start1866=== CONT TestParseSingleRange/multi-range_ignored1867=== CONT TestParseSingleRange/malformed_no_dash1868=== CONT TestParseSingleRange/unknown_unit1869--- PASS: TestParseSingleRange (0.00s)1870 --- PASS: TestParseSingleRange/none (0.00s)1871 --- PASS: TestParseSingleRange/open-ended (0.00s)1872 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1873 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1874 --- PASS: TestParseSingleRange/single_byte (0.00s)1875 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1876 --- PASS: TestParseSingleRange/suffix (0.00s)1877 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1878 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1879 --- PASS: TestParseSingleRange/closed (0.00s)1880 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1881 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1882 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1883 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1884=== CONT TestServerTLSConfig/no_client_CA1885=== CONT TestServerTLSConfig/not_a_PEM_file1886--- PASS: TestResolveDBConnectionString (0.01s)1887 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1888 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1889 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1890 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1891 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1892=== CONT TestServerTLSConfig/missing_CA_file1893--- PASS: TestServerTLSConfig (0.00s)1894 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1895 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1896 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1897=== CONT TestService_RequireScope_OIDC/builder_may_write1898=== CONT TestService_RequireScope_OIDC/static_token_may_admin1899=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1900=== CONT TestService_RequireScope_OIDC/writer_implies_read1901=== CONT TestService_RequireScope_OIDC/reader_may_read1902=== CONT TestService_RequireScope_OIDC/static_token_may_write1903=== CONT TestService_RequireScope_OIDC/ops_may_not_write1904=== CONT TestService_RequireScope_OIDC/reader_may_not_write1905=== CONT TestService_RequireScope_OIDC/ops_may_admin1906=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1907=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1908=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19092026/09/21 18:37:17 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]1910=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1911=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19122026/09/21 18:37:17 WARN Authentication failed token_preview=eyJhbGciOi...Cfr0vGxgXA token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1913=== CONT TestClientErrorHandling/InvalidStorePath1914--- PASS: TestService_RequireScope_OIDC (2.63s)1915 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1916 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1917 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1918 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1919 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1920 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1921 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1922 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1923 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1924 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1925--- PASS: TestService_AuthMiddleware_OIDC (2.58s)1926 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1927 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1928 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1929 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)19302026/09/21 18:37:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19312026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures19322026/09/21 18:37:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19332026/09/21 18:37:17 INFO Uploading dh2fsbc450jdhh8f5l2d0i0x2r3n16y5-unpinned-file.txt (128B)19342026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"19352026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign19362026/09/21 18:37:17 INFO Signed narinfos id=2 count=119372026/09/21 18:37:17 INFO Uploading 1 narinfos19382026/09/21 18:37:17 WARN Failed to register uploaded object key=dh2fsbc450jdhh8f5l2d0i0x2r3n16y5.ls error="server returned 404: 404 page not found\n"19392026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19402026/09/21 18:37:17 WARN Failed to register uploaded object key=dh2fsbc450jdhh8f5l2d0i0x2r3n16y5.narinfo error="server returned 404: 404 page not found\n"19412026/09/21 18:37:17 INFO Completed upload id=219422026/09/21 18:37:17 INFO Upload complete. (126ms)19432026/09/21 18:37:17 INFO Received create pin request method=POST path=/api/pins/myapp1944=== CONT TestClientErrorHandling/ServerNotAvailable1945--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1946 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1947 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1948 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)19492026/09/21 18:37:17 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-25706-3937147719/TestPinProtectsFromGC358889863/001/store/wndbw9ki2dz5ly9gi6d64baq8zrd9pb8-pinned-file.txt narinfo_key=wndbw9ki2dz5ly9gi6d64baq8zrd9pb8.narinfo19502026/09/21 18:37:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures19512026/09/21 18:37:17 INFO Garbage collection started19522026/09/21 18:37:17 INFO Aborted multipart uploads count=019532026/09/21 18:37:17 WARN Force mode enabled - objects will be deleted immediately without grace period19542026-09-21 18:37:17.711 UTC [26044] ERROR: relation "goose_db_version" does not exist at character 3619552026-09-21 18:37:17.711 UTC [26044] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19562026/09/21 18:37:17 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19572026/09/21 18:37:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19582026/09/21 18:37:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=019592026/09/21 18:37:17 OK 20241026095416_initial_model.sql (60.67ms)19602026/09/21 18:37:17 INFO Vacuumed table table=pending_closures19612026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures19622026/09/21 18:37:17 OK 20251210153512_drop_unused_gin_index.sql (7.28ms)19632026/09/21 18:37:17 OK 20251218171726_add_pins.sql (13.26ms)19642026/09/21 18:37:17 INFO Vacuumed table table=pending_objects19652026/09/21 18:37:17 INFO Vacuumed table table=multipart_uploads19662026/09/21 18:37:17 INFO Vacuumed table table=closures19672026/09/21 18:37:17 INFO Vacuumed table table=objects19682026/09/21 18:37:17 OK 20260628120000_add_object_size_and_stats.sql (12.06ms)19692026/09/21 18:37:17 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.628748ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19702026/09/21 18:37:17 OK 20260905000000_add_claims.sql (1.7ms)19712026/09/21 18:37:17 OK 20260920000000_drop_claims.sql (12.17ms)19722026/09/21 18:37:17 goose: successfully migrated database to version: 2026092000000019732026/09/21 18:37:17 OK 1_commit_pending_closure.sql (1.04ms)19742026/09/21 18:37:17 OK 2_object_stats_trigger.sql (284.92µs)19752026/09/21 18:37:17 goose: up to current file version: 219762026/09/21 18:37:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1977=== NAME TestClientIntegration1978 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-25706-3937147719/TestClientIntegration838743436/002/store/xxfg28qjc5a4ix77hj6v0mvr8f5z8zk1-test-file.txt19792026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures19802026/09/21 18:37:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19812026/09/21 18:37:17 INFO Uploading x3m10qc361bczpf42ifgqrskl885wigi-shared-dep (136B)19822026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19832026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign19842026/09/21 18:37:17 WARN Failed to register uploaded object key=x3m10qc361bczpf42ifgqrskl885wigi.ls error="server returned 404: 404 page not found\n"19852026/09/21 18:37:17 INFO Signed narinfos id=2 count=119862026/09/21 18:37:17 INFO Uploading 1 narinfos19872026-09-21 18:37:17.943 UTC [26065] ERROR: relation "goose_db_version" does not exist at character 3619882026-09-21 18:37:17.943 UTC [26065] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1989=== NAME TestClientWithDependencies1990 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-25706-3937147719/TestClientWithDependencies6896097/001/store/wviqvzjxjz3pn578x98whrp6kmiyxp9j-test-script19912026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19922026/09/21 18:37:17 WARN Failed to register uploaded object key=x3m10qc361bczpf42ifgqrskl885wigi.narinfo error="server returned 404: 404 page not found\n"19932026/09/21 18:37:17 INFO Completed upload id=219942026/09/21 18:37:17 INFO Upload complete. (119ms)19952026/09/21 18:37:17 INFO Received uploads request method=POST path=/api/pending_closures19962026/09/21 18:37:17 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)19972026/09/21 18:37:17 INFO Uploading x3m10qc361bczpf42ifgqrskl885wigi-shared-dep (136B)19982026/09/21 18:37:17 INFO Uploading kjp5fi052nm3v563z5q928asli5hyz41-top (256B)19992026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/057ha2vmj9v395m65s14jvkmxlhkk3ps9zpf5vnv3ib5idy2rycr.nar.zst error="server returned 404: 404 page not found\n"20002026/09/21 18:37:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20012026/09/21 18:37:17 WARN Failed to register uploaded object key=kjp5fi052nm3v563z5q928asli5hyz41.ls error="server returned 404: 404 page not found\n"20022026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20032026/09/21 18:37:17 WARN Failed to register uploaded object key=x3m10qc361bczpf42ifgqrskl885wigi.ls error="server returned 404: 404 page not found\n"20042026/09/21 18:37:17 INFO Signed narinfos id=1 count=120052026/09/21 18:37:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign20062026/09/21 18:37:17 INFO Signed narinfos id=3 count=120072026/09/21 18:37:17 INFO Uploading 2 narinfos20082026/09/21 18:37:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"2009 client_integration_test.go:615: Found 1 dependencies (including self)20102026/09/21 18:37:17 WARN Failed to register uploaded object key=kjp5fi052nm3v563z5q928asli5hyz41.narinfo error="server returned 404: 404 page not found\n"20112026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20122026/09/21 18:37:17 WARN Failed to register uploaded object key=x3m10qc361bczpf42ifgqrskl885wigi.narinfo error="server returned 404: 404 page not found\n"20132026/09/21 18:37:17 OK 20241026095416_initial_model.sql (29.5ms)20142026/09/21 18:37:17 INFO Completed upload id=120152026/09/21 18:37:17 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete20162026/09/21 18:37:17 INFO Completed upload id=320172026/09/21 18:37:17 INFO Upload complete. (296ms)2018=== NAME TestClientSharedPathCommittedMidPush2019 client_integration_test.go:680: Retrieved narinfo from S3:2020 StorePath: /nix/var/nix/builds/nix-25706-3937147719/TestClientSharedPathCommittedMidPush3899726299/001/store/x3m10qc361bczpf42ifgqrskl885wigi-shared-dep2021 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2022 Compression: zstd2023 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822024 NarSize: 1362025 References: 2026 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n20272026/09/21 18:37:17 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)2028 client_integration_test.go:680: Retrieved narinfo from S3:2029 StorePath: /nix/var/nix/builds/nix-25706-3937147719/TestClientSharedPathCommittedMidPush3899726299/001/store/kjp5fi052nm3v563z5q928asli5hyz41-top2030 URL: nar/057ha2vmj9v395m65s14jvkmxlhkk3ps9zpf5vnv3ib5idy2rycr.nar.zst2031 Compression: zstd2032 NarHash: sha256:057ha2vmj9v395m65s14jvkmxlhkk3ps9zpf5vnv3ib5idy2rycr2033 NarSize: 2562034 References: /nix/var/nix/builds/nix-25706-3937147719/TestClientSharedPathCommittedMidPush3899726299/001/store/x3m10qc361bczpf42ifgqrskl885wigi-shared-dep2035 CA: text:sha256:1ls5kjzra96mxydbqjybz9r5zf9imkkjrgz67k6m653vyjbyjwvy20362026/09/21 18:37:18 OK 20251218171726_add_pins.sql (10.6ms)20372026/09/21 18:37:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=427.192661ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2038--- PASS: TestClientSharedPathCommittedMidPush (2.20s)2039=== CONT TestClientErrorHandling/InvalidAuthToken20402026/09/21 18:37:18 OK 20260628120000_add_object_size_and_stats.sql (11.99ms)20412026/09/21 18:37:18 OK 20260905000000_add_claims.sql (2.12ms)20422026/09/21 18:37:18 INFO Received uploads request method=POST path=/api/pending_closures20432026/09/21 18:37:18 OK 20260920000000_drop_claims.sql (9.9ms)20442026/09/21 18:37:18 goose: successfully migrated database to version: 2026092000000020452026/09/21 18:37:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20462026/09/21 18:37:18 INFO Uploading xxfg28qjc5a4ix77hj6v0mvr8f5z8zk1-test-file.txt (152B)20472026/09/21 18:37:18 OK 1_commit_pending_closure.sql (891.67µs)20482026/09/21 18:37:18 OK 2_object_stats_trigger.sql (220.79µs)20492026/09/21 18:37:18 goose: up to current file version: 220502026/09/21 18:37:18 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20512026/09/21 18:37:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20522026/09/21 18:37:18 WARN Failed to register uploaded object key=xxfg28qjc5a4ix77hj6v0mvr8f5z8zk1.ls error="server returned 404: 404 page not found\n"20532026/09/21 18:37:18 INFO Signed narinfos id=1 count=120542026/09/21 18:37:18 INFO Uploading 1 narinfos20552026/09/21 18:37:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20562026/09/21 18:37:18 WARN Failed to register uploaded object key=xxfg28qjc5a4ix77hj6v0mvr8f5z8zk1.narinfo error="server returned 404: 404 page not found\n"2057=== NAME TestNARDeduplicationMetadataUploadBug2058 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-25706-3937147719/TestNARDeduplicationMetadataUploadBug1403768186/001/store/7z0lycxhx5vq8pm3rxxzm59d88cyny0c-file1.txt20592026/09/21 18:37:18 INFO Completed upload id=120602026/09/21 18:37:18 INFO Upload complete. (118ms)20612026/09/21 18:37:18 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"20622026/09/21 18:37:18 INFO Received uploads request method=POST path=/api/pending_closures20632026/09/21 18:37:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20642026/09/21 18:37:18 INFO Uploading wviqvzjxjz3pn578x98whrp6kmiyxp9j-test-script (136B)20652026/09/21 18:37:18 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"20662026/09/21 18:37:18 WARN Failed to register uploaded object key=log/8sv8ly8qa134lh04f7s4sadiky7ax2wq-test-script.drv error="server returned 404: 404 page not found\n"20672026/09/21 18:37:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20682026/09/21 18:37:18 WARN Failed to register uploaded object key=wviqvzjxjz3pn578x98whrp6kmiyxp9j.ls error="server returned 404: 404 page not found\n"20692026/09/21 18:37:18 INFO Signed narinfos id=1 count=120702026/09/21 18:37:18 INFO Uploading 1 narinfos20712026/09/21 18:37:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20722026/09/21 18:37:18 WARN Failed to register uploaded object key=wviqvzjxjz3pn578x98whrp6kmiyxp9j.narinfo error="server returned 404: 404 page not found\n"20732026/09/21 18:37:18 INFO All 1 paths already cached2074=== NAME TestClientIntegration2075 client_integration_test.go:312: Retrieved narinfo from S3:2076 StorePath: /nix/var/nix/builds/nix-25706-3937147719/TestClientIntegration838743436/002/store/xxfg28qjc5a4ix77hj6v0mvr8f5z8zk1-test-file.txt2077 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2078 Compression: zstd2079 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12080 NarSize: 1522081 References: 2082 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12083 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2084 client_integration_test.go:313: Decompressed .ls content (64 bytes):2085 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2086 client_integration_test.go:316: Testing garbage collection...20872026/09/21 18:37:18 INFO Completed upload id=120882026/09/21 18:37:18 INFO Upload complete. (77ms)2089=== NAME TestClientWithDependencies2090 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-25706-3937147719/TestClientWithDependencies6896097/001/store) requires matching store prefix2091--- PASS: TestClientWithDependencies (2.08s)2092=== CONT TestCacheConfigHandler/full_config,_no_issuer2093=== CONT TestCacheConfigHandler/no_signing_keys2094=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2095=== CONT TestCacheConfigHandler/no_cache_url_configured2096--- PASS: TestCacheConfigHandler (0.00s)2097 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2098 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2099 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2100 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)21012026/09/21 18:37:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures21022026/09/21 18:37:18 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21032026/09/21 18:37:18 INFO Garbage collection started21042026/09/21 18:37:18 INFO Aborted multipart uploads count=021052026/09/21 18:37:18 WARN Force mode enabled - objects will be deleted immediately without grace period21062026/09/21 18:37:18 INFO Received uploads request method=POST path=/api/pending_closures21072026/09/21 18:37:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21082026/09/21 18:37:18 INFO Uploading 7z0lycxhx5vq8pm3rxxzm59d88cyny0c-file1.txt (160B)21092026/09/21 18:37:18 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"21102026/09/21 18:37:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21112026/09/21 18:37:18 INFO Signed narinfos id=1 count=121122026/09/21 18:37:18 WARN Failed to register uploaded object key=7z0lycxhx5vq8pm3rxxzm59d88cyny0c.ls error="server returned 404: 404 page not found\n"21132026/09/21 18:37:18 INFO Uploading 1 narinfos21142026/09/21 18:37:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21152026/09/21 18:37:18 WARN Failed to register uploaded object key=7z0lycxhx5vq8pm3rxxzm59d88cyny0c.narinfo error="server returned 404: 404 page not found\n"21162026/09/21 18:37:18 INFO Completed upload id=121172026/09/21 18:37:18 INFO Upload complete. (141ms)2118=== NAME TestNARDeduplicationMetadataUploadBug2119 metadata_upload_test.go:54: Retrieved narinfo from S3:2120 StorePath: /nix/var/nix/builds/nix-25706-3937147719/TestNARDeduplicationMetadataUploadBug1403768186/001/store/7z0lycxhx5vq8pm3rxxzm59d88cyny0c-file1.txt2121 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2122 Compression: zstd2123 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2124 NarSize: 1602125 References: 2126 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2127 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2128 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2129 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2130--- PASS: TestCacheStatsHandler (1.02s)2131=== NAME TestNARDeduplicationMetadataUploadBug2132 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-25706-3937147719/TestNARDeduplicationMetadataUploadBug1403768186/001/store/b3hq83ljm0gc1zw93bz7rd2yb5hjxhl9-file2.txt21332026/09/21 18:37:18 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=021342026/09/21 18:37:18 INFO Vacuumed table table=pending_closures21352026/09/21 18:37:18 INFO Vacuumed table table=pending_objects21362026/09/21 18:37:18 INFO Vacuumed table table=multipart_uploads21372026/09/21 18:37:18 INFO Vacuumed table table=closures2138=== NAME TestClientCADerivations2139 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-25706-3937147719/TestClientCADerivations2439011747/001/store/glr99wynzwskvmlwdp7yqbryixbmf19a-ca-test21402026/09/21 18:37:18 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21412026/09/21 18:37:18 INFO Vacuumed table table=objects21422026-09-21 18:37:18.391 UTC [26106] ERROR: relation "goose_db_version" does not exist at character 3621432026-09-21 18:37:18.391 UTC [26106] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21442026/09/21 18:37:18 OK 20241026095416_initial_model.sql (3.92ms)21452026/09/21 18:37:18 OK 20251210153512_drop_unused_gin_index.sql (447.33µs)21462026/09/21 18:37:18 OK 20251218171726_add_pins.sql (844µs)21472026/09/21 18:37:18 OK 20260628120000_add_object_size_and_stats.sql (1ms)21482026/09/21 18:37:18 OK 20260905000000_add_claims.sql (1.13ms)2149=== NAME TestOrphanedObjectsGCStressTest2150 orphaned_objects_gc_test.go:509: Stress test completed successfully:2151 orphaned_objects_gc_test.go:510: - Active objects preserved: 202152 orphaned_objects_gc_test.go:511: - Objects deleted: 2102153 orphaned_objects_gc_test.go:512: - Total GC'd: 2102154--- PASS: TestOrphanedObjectsGCStressTest (7.43s)21552026/09/21 18:37:18 OK 20260920000000_drop_claims.sql (714.33µs)21562026/09/21 18:37:18 goose: successfully migrated database to version: 2026092000000021572026/09/21 18:37:18 OK 1_commit_pending_closure.sql (820.5µs)21582026/09/21 18:37:18 OK 2_object_stats_trigger.sql (480.54µs)21592026/09/21 18:37:18 goose: up to current file version: 221602026/09/21 18:37:18 INFO Received uploads request method=POST path=/api/pending_closures21612026/09/21 18:37:18 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2162=== NAME TestClientCADerivations2163 client_ca_test.go:139: Found 1 dependencies (including self)21642026/09/21 18:37:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign21652026/09/21 18:37:18 INFO Signed narinfos id=2 count=121662026/09/21 18:37:18 WARN Failed to register uploaded object key=b3hq83ljm0gc1zw93bz7rd2yb5hjxhl9.ls error="server returned 404: 404 page not found\n"21672026/09/21 18:37:18 INFO Uploading 1 narinfos21682026/09/21 18:37:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=788.245027ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21692026/09/21 18:37:18 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21702026/09/21 18:37:18 WARN Failed to register uploaded object key=b3hq83ljm0gc1zw93bz7rd2yb5hjxhl9.narinfo error="server returned 404: 404 page not found\n"21712026/09/21 18:37:18 INFO Completed upload id=221722026/09/21 18:37:18 INFO Upload complete. (126ms)2173=== NAME TestNARDeduplicationMetadataUploadBug2174 metadata_upload_test.go:76: Retrieved narinfo from S3:2175 StorePath: /nix/var/nix/builds/nix-25706-3937147719/TestNARDeduplicationMetadataUploadBug1403768186/001/store/b3hq83ljm0gc1zw93bz7rd2yb5hjxhl9-file2.txt2176 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2177 Compression: zstd2178 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2179 NarSize: 1602180 References: 2181 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2182 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2183 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2184 {"version":1,"root":{"type":"regular","size":44}}2185--- PASS: TestNARDeduplicationMetadataUploadBug (2.04s)21862026/09/21 18:37:18 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21872026/09/21 18:37:18 INFO Received uploads request method=POST path=/api/pending_closures21882026/09/21 18:37:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21892026/09/21 18:37:18 INFO Uploading glr99wynzwskvmlwdp7yqbryixbmf19a-ca-test (144B)21902026/09/21 18:37:18 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21912026/09/21 18:37:18 WARN Failed to register uploaded object key=log/3xphss8my6ajn8cp92yk016b63cdfr7c-ca-test.drv error="server returned 404: 404 page not found\n"21922026/09/21 18:37:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21932026/09/21 18:37:18 WARN Failed to register uploaded object key=glr99wynzwskvmlwdp7yqbryixbmf19a.ls error="server returned 404: 404 page not found\n"21942026/09/21 18:37:18 INFO Signed narinfos id=1 count=121952026/09/21 18:37:18 INFO Uploading 1 narinfos21962026/09/21 18:37:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21972026/09/21 18:37:18 WARN Failed to register uploaded object key=glr99wynzwskvmlwdp7yqbryixbmf19a.narinfo error="server returned 404: 404 page not found\n"21982026/09/21 18:37:18 INFO Completed upload id=121992026/09/21 18:37:18 INFO Upload complete. (72ms)2200=== NAME TestClientCADerivations2201 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-25706-3937147719/TestClientCADerivations2439011747/001/store/glr99wynzwskvmlwdp7yqbryixbmf19a-ca-test2202 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2203 Compression: zstd2204 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2205 NarSize: 1442206 References: 2207 Deriver: /nix/var/nix/builds/nix-25706-3937147719/TestClientCADerivations2439011747/001/store/3xphss8my6ajn8cp92yk016b63cdfr7c-ca-test.drv2208 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2209 client_ca_test.go:185: Checking for realisation files in S3...2210 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2211 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2212 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket54?endpoint=http://localhost:51624®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-25706-3937147719/TestClientCADerivations2439011747/001/store'2213 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12214--- PASS: TestClientCADerivations (1.96s)22152026/09/21 18:37:18 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22162026/09/21 18:37:18 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22172026/09/21 18:37:18 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22182026/09/21 18:37:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.740640818s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22192026/09/21 18:37:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02220=== NAME TestPinProtectsFromGC2221 client_integration_test.go:794: Pin successfully protected closure from garbage collection2222--- PASS: TestPinProtectsFromGC (4.11s)22232026/09/21 18:37:20 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02224=== NAME TestClientIntegration2225 client_integration_test.go:323: Objects in database after GC:2226 client_integration_test.go:323: Successfully deleted all objects with GC --force2227--- PASS: TestClientIntegration (3.92s)22282026/09/21 18:37:21 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/09/21 18:37:21 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.461273ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22302026/09/21 18:37:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=433.924751ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22312026/09/21 18:37:21 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=870.634757ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/09/21 18:37:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.682030568s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22332026/09/21 18:37:24 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 127.0.0.1:19999: connect: connection refused"22342026/09/21 18:37:24 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22352026/09/21 18:37:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.697742ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22362026/09/21 18:37:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=434.621429ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/09/21 18:37:25 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=730.872072ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22382026/09/21 18:37:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.704577912s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2239--- PASS: TestClientErrorHandling (0.00s)2240 --- PASS: TestClientErrorHandling/InvalidStorePath (0.97s)2241 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.64s)2242 --- PASS: TestClientErrorHandling/ServerNotAvailable (10.03s)2243PASS22442026-09-21 18:37:27.713 UTC [25743] LOG: received smart shutdown request22452026-09-21 18:37:27.714 UTC [25743] LOG: background worker "logical replication launcher" (PID 25754) exited with exit code 122462026-09-21 18:37:27.722 UTC [25748] LOG: shutting down22472026-09-21 18:37:27.722 UTC [25748] LOG: checkpoint starting: shutdown immediate22482026-09-21 18:37:28.827 UTC [25748] LOG: checkpoint complete: wrote 13092 buffers (79.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=0.759 s, sync=0.320 s, total=1.106 s; sync files=19072, longest=0.001 s, average=0.001 s; distance=264769 kB, estimate=264769 kB; lsn=0/11A1D740, redo lsn=0/11A1D74022492026-09-21 18:37:28.832 UTC [25743] LOG: database system is shut down2250Running OIDC tests...2251=== RUN TestAudienceForIssuer2252=== PAUSE TestAudienceForIssuer2253=== RUN TestGlobMatch2254=== PAUSE TestGlobMatch2255=== RUN TestValidateToken_ValidToken2256=== PAUSE TestValidateToken_ValidToken2257=== RUN TestValidateToken_WrongAudience2258=== PAUSE TestValidateToken_WrongAudience2259=== RUN TestValidateToken_Expired2260=== PAUSE TestValidateToken_Expired2261=== RUN TestValidateToken_BoundClaimsMismatch2262=== PAUSE TestValidateToken_BoundClaimsMismatch2263=== RUN TestValidateToken_BoundSubjectMismatch2264=== PAUSE TestValidateToken_BoundSubjectMismatch2265=== RUN TestValidateToken_MultipleProviders2266=== PAUSE TestValidateToken_MultipleProviders2267=== RUN TestValidateToken_NoMatchingProvider2268=== PAUSE TestValidateToken_NoMatchingProvider2269=== RUN TestValidateToken_KubernetesServiceAccount2270=== PAUSE TestValidateToken_KubernetesServiceAccount2271=== RUN TestNewValidator_KubernetesRequiresCA2272=== PAUSE TestNewValidator_KubernetesRequiresCA2273=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2274=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2275=== RUN TestPins_ReservedForMatchingRule2276=== PAUSE TestPins_ReservedForMatchingRule2277=== RUN TestPins_TopLevelShorthand2278=== PAUSE TestPins_TopLevelShorthand2279=== RUN TestPins_ConfigValidation2280=== PAUSE TestPins_ConfigValidation2281=== RUN TestScopes_LegacyProviderDefaultsToWrite2282=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2283=== RUN TestScopes_Rules2284=== PAUSE TestScopes_Rules2285=== RUN TestScopes_ConfigValidation2286=== PAUSE TestScopes_ConfigValidation2287=== CONT TestAudienceForIssuer2288--- PASS: TestAudienceForIssuer (0.00s)2289=== CONT TestValidateToken_KubernetesServiceAccount2290=== CONT TestValidateToken_NoMatchingProvider2291=== CONT TestValidateToken_MultipleProviders2292=== CONT TestValidateToken_BoundSubjectMismatch2293=== CONT TestValidateToken_BoundClaimsMismatch2294=== CONT TestValidateToken_Expired2295=== CONT TestValidateToken_WrongAudience2296=== CONT TestValidateToken_ValidToken2297=== CONT TestGlobMatch2298=== RUN TestGlobMatch/foo_foo2299=== PAUSE TestGlobMatch/foo_foo2300=== RUN TestGlobMatch/foo_bar2301=== CONT TestPins_ConfigValidation2302=== PAUSE TestGlobMatch/foo_bar2303=== RUN TestGlobMatch/*_2304=== PAUSE TestGlobMatch/*_2305=== RUN TestGlobMatch/*_anything2306=== PAUSE TestGlobMatch/*_anything2307=== RUN TestGlobMatch/foo*_foo2308=== PAUSE TestGlobMatch/foo*_foo2309=== RUN TestGlobMatch/foo*_foobar2310=== PAUSE TestGlobMatch/foo*_foobar2311=== RUN TestGlobMatch/foo*_bar2312=== PAUSE TestGlobMatch/foo*_bar2313=== RUN TestGlobMatch/*bar_bar2314=== PAUSE TestGlobMatch/*bar_bar2315=== RUN TestGlobMatch/*bar_foobar2316=== PAUSE TestGlobMatch/*bar_foobar2317=== RUN TestGlobMatch/*bar_foo2318=== PAUSE TestGlobMatch/*bar_foo2319=== RUN TestGlobMatch/foo*bar_foobar2320=== PAUSE TestGlobMatch/foo*bar_foobar2321=== RUN TestGlobMatch/foo*bar_foo123bar2322=== PAUSE TestGlobMatch/foo*bar_foo123bar2323=== RUN TestGlobMatch/foo*bar_foobarbaz2324=== PAUSE TestGlobMatch/foo*bar_foobarbaz2325=== RUN TestGlobMatch/*/*_foo/bar2326=== PAUSE TestGlobMatch/*/*_foo/bar2327=== RUN TestGlobMatch/*/*_foo2328=== PAUSE TestGlobMatch/*/*_foo2329=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2330=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2331=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02332=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02333=== RUN TestGlobMatch/refs/*/main_refs/heads/main2334=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2335=== RUN TestGlobMatch/fo?_foo2336=== PAUSE TestGlobMatch/fo?_foo2337=== RUN TestGlobMatch/fo?_fo2338=== PAUSE TestGlobMatch/fo?_fo2339=== RUN TestGlobMatch/fo?_fooo2340=== PAUSE TestGlobMatch/fo?_fooo2341=== RUN TestGlobMatch/?oo_foo2342=== PAUSE TestGlobMatch/?oo_foo2343=== RUN TestGlobMatch/?oo_boo2344=== PAUSE TestGlobMatch/?oo_boo2345=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2346=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2347=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2348=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2349=== CONT TestPins_ReservedForMatchingRule23502026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51832/oidc23512026/09/21 18:37:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51835/oidc23522026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51836/oidc23532026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51841/oidc2354--- PASS: TestPins_ConfigValidation (0.00s)2355=== CONT TestPins_TopLevelShorthand23562026/09/21 18:37:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51837/oidc23572026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51833/oidc23582026/09/21 18:37:29 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:51838/oidc23592026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51834/oidc23602026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51850/oidc23612026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51852/oidc2362--- PASS: TestValidateToken_WrongAudience (0.01s)2363=== CONT TestScopes_Rules2364--- PASS: TestValidateToken_Expired (0.01s)2365=== CONT TestScopes_ConfigValidation23662026/09/21 18:37:29 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:518392367--- PASS: TestValidateToken_ValidToken (0.01s)2368=== CONT TestScopes_LegacyProviderDefaultsToWrite2369--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2370=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2371--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2372=== CONT TestNewValidator_KubernetesRequiresCA2373--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2374=== CONT TestGlobMatch/foo_foo2375=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2376=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2377=== CONT TestGlobMatch/?oo_boo2378=== CONT TestGlobMatch/?oo_foo2379=== CONT TestGlobMatch/fo?_fooo2380=== CONT TestGlobMatch/fo?_fo2381=== CONT TestGlobMatch/fo?_foo2382=== CONT TestGlobMatch/refs/*/main_refs/heads/main2383=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02384=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2385=== CONT TestGlobMatch/*/*_foo2386=== CONT TestGlobMatch/*/*_foo/bar2387=== CONT TestGlobMatch/foo*bar_foobarbaz2388=== CONT TestGlobMatch/foo*bar_foo123bar2389=== CONT TestGlobMatch/foo*bar_foobar2390=== CONT TestGlobMatch/*bar_foo2391=== CONT TestGlobMatch/*bar_foobar2392=== CONT TestGlobMatch/*bar_bar2393--- PASS: TestPins_TopLevelShorthand (0.01s)2394=== CONT TestGlobMatch/foo*_bar2395=== CONT TestGlobMatch/foo*_foo2396=== CONT TestGlobMatch/*_anything2397--- PASS: TestValidateToken_MultipleProviders (0.01s)2398=== CONT TestGlobMatch/*_2399=== CONT TestGlobMatch/foo_bar2400=== CONT TestGlobMatch/foo*_foobar2401--- PASS: TestGlobMatch (0.00s)2402 --- PASS: TestGlobMatch/foo_foo (0.00s)2403 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2404 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2405 --- PASS: TestGlobMatch/?oo_boo (0.00s)2406 --- PASS: TestGlobMatch/?oo_foo (0.00s)2407 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2408 --- PASS: TestGlobMatch/fo?_fo (0.00s)2409 --- PASS: TestGlobMatch/fo?_foo (0.00s)2410 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2411 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2412 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2413 --- PASS: TestGlobMatch/*/*_foo (0.00s)2414 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2415 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2416 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2417 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2418 --- PASS: TestGlobMatch/*bar_foo (0.00s)2419 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2420 --- PASS: TestGlobMatch/*bar_bar (0.00s)2421 --- PASS: TestGlobMatch/foo*_bar (0.00s)2422 --- PASS: TestGlobMatch/foo*_foo (0.00s)2423 --- PASS: TestGlobMatch/*_anything (0.00s)2424 --- PASS: TestGlobMatch/*_ (0.00s)2425 --- PASS: TestGlobMatch/foo_bar (0.00s)2426 --- PASS: TestGlobMatch/foo*_foobar (0.00s)24272026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51855/oidc24282026/09/21 18:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51856/oidc2429--- PASS: TestScopes_ConfigValidation (0.00s)2430--- PASS: TestPins_ReservedForMatchingRule (0.01s)24312026/09/21 18:37:29 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232432--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2433--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)2434--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)24352026/09/21 18:37:29 http: TLS handshake error from 127.0.0.1:51860: read tcp 127.0.0.1:51858->127.0.0.1:51860: use of closed network connection2436--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2437--- PASS: TestScopes_Rules (0.01s)2438PASS2439Running hook tests...2440=== RUN TestSendPathsEmpty2441=== PAUSE TestSendPathsEmpty2442=== RUN TestQueueEnqueueAndFetch2443=== PAUSE TestQueueEnqueueAndFetch2444=== RUN TestQueueDeduplication2445=== PAUSE TestQueueDeduplication2446=== RUN TestQueueRemove2447=== PAUSE TestQueueRemove2448=== RUN TestQueueFetchBatchLimit2449=== PAUSE TestQueueFetchBatchLimit2450=== RUN TestQueueRetryMovesToBack2451=== PAUSE TestQueueRetryMovesToBack2452=== RUN TestQueueFetchRemoveLifecycle2453=== PAUSE TestQueueFetchRemoveLifecycle2454=== RUN TestQueueConcurrentWriters2455=== PAUSE TestQueueConcurrentWriters2456=== RUN TestQueueRemoveLargeClosure2457=== PAUSE TestQueueRemoveLargeClosure2458=== RUN TestServerClientIntegration2459=== PAUSE TestServerClientIntegration2460=== RUN TestServerQueueError2461=== PAUSE TestServerQueueError2462=== RUN TestGetListenerSocketActivation2463 server_test.go:210: === RUN TestGetListenerSocketActivation2464 --- PASS: TestGetListenerSocketActivation (0.00s)2465 PASS2466 2467--- PASS: TestGetListenerSocketActivation (0.01s)2468=== RUN TestDrainIsolatesPoisonPath2469=== PAUSE TestDrainIsolatesPoisonPath2470=== RUN TestRunNotBlockedByPoisonHead2471=== PAUSE TestRunNotBlockedByPoisonHead2472=== RUN TestDrainGivesUpWhenServerDown2473=== PAUSE TestDrainGivesUpWhenServerDown2474=== RUN TestFailedPathPrunedByLaterClosure2475=== PAUSE TestFailedPathPrunedByLaterClosure2476=== RUN TestWorkerUploadsAndRemoves2477=== PAUSE TestWorkerUploadsAndRemoves2478=== RUN TestWorkerSkipsGCdPaths2479=== PAUSE TestWorkerSkipsGCdPaths2480=== RUN TestWorkerPrunesClosureDeps2481=== PAUSE TestWorkerPrunesClosureDeps2482=== RUN TestDrainTimeout2483=== PAUSE TestDrainTimeout2484=== CONT TestSendPathsEmpty2485=== CONT TestServerQueueError2486--- PASS: TestSendPathsEmpty (0.00s)2487=== CONT TestServerClientIntegration2488=== CONT TestWorkerUploadsAndRemoves2489=== CONT TestQueueRetryMovesToBack2490=== CONT TestQueueRemove2491=== CONT TestWorkerPrunesClosureDeps2492=== CONT TestWorkerSkipsGCdPaths2493=== CONT TestQueueFetchBatchLimit2494=== CONT TestDrainTimeout2495=== CONT TestQueueDeduplication24962026/09/21 18:37:30 ERROR Failed to queue paths error="permission denied" count=12497--- PASS: TestServerQueueError (0.00s)2498=== CONT TestQueueEnqueueAndFetch2499--- PASS: TestServerClientIntegration (0.00s)2500=== CONT TestFailedPathPrunedByLaterClosure25012026/09/21 18:37:30 INFO Upload queue status pending=22502--- PASS: TestQueueFetchBatchLimit (0.01s)2503=== CONT TestDrainGivesUpWhenServerDown25042026/09/21 18:37:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-25706-3937147719/TestWorkerSkipsGCdPaths403467326/002/nonexistent2505--- PASS: TestQueueEnqueueAndFetch (0.01s)2506=== CONT TestRunNotBlockedByPoisonHead25072026/09/21 18:37:30 INFO Uploading batch count=125082026/09/21 18:37:30 INFO Uploading batch count=225092026/09/21 18:37:30 INFO Upload queue status pending=225102026/09/21 18:37:30 INFO Upload queue status pending=22511--- PASS: TestQueueDeduplication (0.01s)2512=== CONT TestDrainIsolatesPoisonPath25132026/09/21 18:37:30 INFO Uploading batch count=125142026/09/21 18:37:30 INFO Uploading batch count=125152026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=125162026/09/21 18:37:30 INFO Uploading batch count=225172026/09/21 18:37:30 INFO Uploading batch count=12518--- PASS: TestQueueRetryMovesToBack (0.01s)2519=== CONT TestQueueRemoveLargeClosure25202026/09/21 18:37:30 INFO Uploading batch count=12521--- PASS: TestQueueRemove (0.01s)2522=== CONT TestQueueConcurrentWriters2523--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2524=== CONT TestQueueFetchRemoveLifecycle25252026/09/21 18:37:30 INFO Uploading batch count=225262026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=225272026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainGivesUpWhenServerDown2146243659/002/a25282026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainGivesUpWhenServerDown2146243659/002/b25292026/09/21 18:37:30 INFO Uploading batch count=425302026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=425312026/09/21 18:37:30 INFO Uploading batch count=225322026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=225332026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainGivesUpWhenServerDown2146243659/002/c25342026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainIsolatesPoisonPath2693943937/002/bbb25352026/09/21 18:37:30 INFO Upload queue status pending=325362026/09/21 18:37:30 INFO Uploading batch count=125372026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=125382026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainGivesUpWhenServerDown2146243659/002/d25392026/09/21 18:37:30 INFO Uploading batch count=125402026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=125412026/09/21 18:37:30 INFO Uploading batch count=225422026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=225432026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainGivesUpWhenServerDown2146243659/002/e25442026/09/21 18:37:30 INFO Uploading batch count=125452026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=125462026/09/21 18:37:30 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25706-3937147719/TestDrainGivesUpWhenServerDown2146243659/002/f2547--- PASS: TestQueueFetchRemoveLifecycle (0.00s)25482026/09/21 18:37:30 INFO Uploading batch count=125492026/09/21 18:37:30 ERROR Upload failed error="upload failed" count=125502026/09/21 18:37:30 ERROR Drain finished with paths left in queue remaining=1025512026/09/21 18:37:30 ERROR Drain finished with paths left in queue remaining=12552--- PASS: TestDrainIsolatesPoisonPath (0.01s)2553--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2554--- PASS: TestWorkerSkipsGCdPaths (0.03s)2555--- PASS: TestWorkerUploadsAndRemoves (0.03s)2556--- PASS: TestWorkerPrunesClosureDeps (0.03s)2557--- PASS: TestQueueRemoveLargeClosure (0.05s)2558--- PASS: TestQueueConcurrentWriters (0.15s)25592026/09/21 18:37:30 ERROR Upload failed error="context deadline exceeded" count=225602026/09/21 18:37:30 ERROR Drain finished with paths left in queue remaining=42561--- PASS: TestDrainTimeout (0.21s)25622026/09/21 18:37:31 INFO Uploading batch count=125632026/09/21 18:37:31 INFO Uploading batch count=125642026/09/21 18:37:31 INFO Uploading batch count=125652026/09/21 18:37:31 ERROR Upload failed error="upload failed" count=125662026/09/21 18:37:31 INFO Uploading batch count=125672026/09/21 18:37:31 ERROR Upload failed error="upload failed" count=125682026/09/21 18:37:31 INFO Uploading batch count=125692026/09/21 18:37:31 ERROR Upload failed error="upload failed" count=125702026/09/21 18:37:31 INFO Uploading batch count=125712026/09/21 18:37:31 ERROR Upload failed error="upload failed" count=125722026/09/21 18:37:31 ERROR Drain finished with paths left in queue remaining=12573--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2574PASS