niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #207
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathCaseHackMatchesNix13--- PASS: TestDumpPathCaseHackMatchesNix (0.17s)14=== RUN TestDumpPathCaseHackCollision15--- PASS: TestDumpPathCaseHackCollision (0.00s)16=== RUN TestDumpPathMatchesNix17=== PAUSE TestDumpPathMatchesNix18=== RUN TestDumpPathSingleFile19=== PAUSE TestDumpPathSingleFile20=== RUN TestDumpPathWriterError21=== PAUSE TestDumpPathWriterError22=== RUN TestEncodeNixBase3223=== PAUSE TestEncodeNixBase3224=== RUN TestEncodeNixBase32WithRealHash25=== PAUSE TestEncodeNixBase32WithRealHash26=== RUN TestConvertHashToNix3227=== PAUSE TestConvertHashToNix3228=== RUN TestGetStorePathHash29=== PAUSE TestGetStorePathHash30=== RUN TestPathInfoHashCompatibility31=== PAUSE TestPathInfoHashCompatibility32=== RUN TestParsePathInfoJSON33=== PAUSE TestParsePathInfoJSON34=== RUN TestParsePathInfoJSONMultiplePaths35=== PAUSE TestParsePathInfoJSONMultiplePaths36=== RUN TestPathInfoCACompatibility37=== PAUSE TestPathInfoCACompatibility38=== RUN TestRateLimiterFeedback39=== PAUSE TestRateLimiterFeedback40=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess41=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== RUN TestResolveStorePath43=== PAUSE TestResolveStorePath44=== RUN TestDoWithRetry_BodyReplayedViaGetBody45=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody46=== RUN TestShellSplit47=== PAUSE TestShellSplit48=== RUN TestShellSplitErrors49=== PAUSE TestShellSplitErrors50=== RUN TestStreamPushReportsEveryPath51=== PAUSE TestStreamPushReportsEveryPath52=== RUN TestStreamPushBatchesUnderLoad53=== PAUSE TestStreamPushBatchesUnderLoad54=== RUN TestStreamPushIsolatesFailures55=== PAUSE TestStreamPushIsolatesFailures56=== RUN TestStreamPushGivesUpOnDeadServer57=== PAUSE TestStreamPushGivesUpOnDeadServer58=== RUN TestSetClientTLS59=== PAUSE TestSetClientTLS60=== RUN TestSetClientTLSDoesNotMutateDefaultTransport61=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport62=== RUN TestSetClientTLSErrors63=== PAUSE TestSetClientTLSErrors64=== RUN TestStaticToken65=== PAUSE TestStaticToken66=== RUN TestFileTokenReadsAndCaches67=== PAUSE TestFileTokenReadsAndCaches68=== RUN TestFileTokenMissing69=== PAUSE TestFileTokenMissing70=== RUN TestFileTokenEmpty71=== PAUSE TestFileTokenEmpty72=== RUN TestScriptTokenNoExpiryRerunsEveryCall73=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall74=== RUN TestScriptTokenCachesUntilRefresh75=== PAUSE TestScriptTokenCachesUntilRefresh76=== RUN TestScriptTokenEmptyToken77=== PAUSE TestScriptTokenEmptyToken78=== RUN TestScriptTokenBadJSON79=== PAUSE TestScriptTokenBadJSON80=== RUN TestScriptTokenScriptFails81=== PAUSE TestScriptTokenScriptFails82=== RUN TestScriptTokenEmptyCommand83=== PAUSE TestScriptTokenEmptyCommand84=== CONT TestDoServerRequestAttachesToken85=== CONT TestShellSplit86=== CONT TestConvertHashToNix3287--- PASS: TestShellSplit (0.00s)88=== CONT TestFileTokenEmpty89=== RUN TestConvertHashToNix32/SRI_format_to_Nix3290=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3291=== RUN TestConvertHashToNix32/already_Nix32_format92=== PAUSE TestConvertHashToNix32/already_Nix32_format93=== RUN TestConvertHashToNix32/invalid_format94=== PAUSE TestConvertHashToNix32/invalid_format95=== CONT TestFileTokenReadsAndCaches96=== CONT TestFileTokenMissing97=== CONT TestScriptTokenEmptyCommand98--- PASS: TestScriptTokenEmptyCommand (0.00s)99=== CONT TestPathInfoCACompatibility100=== RUN TestPathInfoCACompatibility/null_ca_field101=== PAUSE TestPathInfoCACompatibility/null_ca_field102=== RUN TestPathInfoCACompatibility/old_string_format_-_text103=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text104=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive105=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive106=== RUN TestPathInfoCACompatibility/new_structured_format_-_text107=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text108=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method109=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method110=== CONT TestDoWithRetry_BodyReplayedViaGetBody111=== CONT TestScriptTokenScriptFails112--- PASS: TestFileTokenReadsAndCaches (0.00s)113=== CONT TestResolveStorePath114=== CONT TestScriptTokenBadJSON115--- PASS: TestFileTokenMissing (0.00s)116=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess117=== CONT TestScriptTokenEmptyToken118=== CONT TestScriptTokenCachesUntilRefresh119=== CONT TestScriptTokenNoExpiryRerunsEveryCall120--- PASS: TestFileTokenEmpty (0.00s)121=== CONT TestRateLimiterFeedback1222026/09/15 08:31:32 WARN Rate limiter enabled after throttle name=server-test rate=5123=== RUN TestRateLimiterFeedback/429_enables_limiter124=== PAUSE TestRateLimiterFeedback/429_enables_limiter125=== RUN TestRateLimiterFeedback/503_enables_limiter126=== PAUSE TestRateLimiterFeedback/503_enables_limiter127=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter128=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter129=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter130=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter131=== CONT TestEncodeNixBase32132=== RUN TestEncodeNixBase32/test_string_hash133=== PAUSE TestEncodeNixBase32/test_string_hash134=== RUN TestEncodeNixBase32/empty_input135=== PAUSE TestEncodeNixBase32/empty_input136=== CONT TestEncodeNixBase32WithRealHash137--- PASS: TestEncodeNixBase32WithRealHash (0.00s)138=== CONT TestPartSizeForNAR139=== RUN TestPartSizeForNAR/zero_stays_at_minimum140=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum141=== RUN TestPartSizeForNAR/small_stays_at_minimum142=== PAUSE TestPartSizeForNAR/small_stays_at_minimum143--- PASS: TestResolveStorePath (0.00s)144=== CONT TestUploadMultipart_SupersededByPeer145=== RUN TestUploadMultipart_SupersededByPeer/exists146=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum147=== PAUSE TestUploadMultipart_SupersededByPeer/exists148=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum1492026/09/15 08:31:32 WARN Rate limiter enabled after throttle name=server-test rate=5150=== RUN TestUploadMultipart_SupersededByPeer/missing1512026/09/15 08:31:32 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57153152=== PAUSE TestUploadMultipart_SupersededByPeer/missing153=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts154=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts155=== CONT TestFilterOversizedClosures156=== RUN TestPartSizeForNAR/1_TiB157=== PAUSE TestPartSizeForNAR/1_TiB158=== RUN TestPartSizeForNAR/5_TiB_S3_max_object159=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object160=== RUN TestPartSizeForNAR/capped_at_5_GiB161=== PAUSE TestPartSizeForNAR/capped_at_5_GiB162=== CONT TestParsePathInfoJSON163=== RUN TestParsePathInfoJSON/Nix_format164=== PAUSE TestParsePathInfoJSON/Nix_format165=== RUN TestParsePathInfoJSON/Lix_format166=== PAUSE TestParsePathInfoJSON/Lix_format167=== RUN TestParsePathInfoJSON/empty_input168=== PAUSE TestParsePathInfoJSON/empty_input169=== RUN TestParsePathInfoJSON/whitespace_only170=== PAUSE TestParsePathInfoJSON/whitespace_only171=== RUN TestFilterOversizedClosures/no_limit_keeps_everything172=== RUN TestParsePathInfoJSON/invalid_JSON173=== PAUSE TestParsePathInfoJSON/invalid_JSON174=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything175=== CONT TestParsePathInfoJSONMultiplePaths176--- PASS: TestDoServerRequestAttachesToken (0.00s)177=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths178=== CONT TestPathInfoHashCompatibility179=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)180=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths181=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths182=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths183=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped184=== CONT TestGetStorePathHash185=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)186=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped187=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon188=== RUN TestGetStorePathHash/valid_store_path189=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon190=== RUN TestFilterOversizedClosures/all_closures_skipped191=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI192=== PAUSE TestGetStorePathHash/valid_store_path193=== PAUSE TestFilterOversizedClosures/all_closures_skipped194=== RUN TestGetStorePathHash/basename_without_hyphen_should_error195--- PASS: TestScriptTokenScriptFails (0.01s)196=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error197=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error198=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error199=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error200=== CONT TestDumpPathWriterError201=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error202=== CONT TestCaseHackSuffix203=== CONT TestStreamPushGivesUpOnDeadServer2042026/09/15 08:31:32 WARN Rate limiter backed off name=server-test rate=52052026/09/15 08:31:32 ERROR Upload failed error="connection refused" count=202062026/09/15 08:31:32 ERROR Server seems unavailable, giving up on batch untried=172072026/09/15 08:31:32 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57153208=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI209=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512210=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512211=== CONT TestStaticToken212--- PASS: TestStaticToken (0.00s)213=== CONT TestSetClientTLSErrors214--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)215=== CONT TestSetClientTLSDoesNotMutateDefaultTransport216--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)217=== CONT TestSetClientTLS218--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)219=== CONT TestStreamPushBatchesUnderLoad220=== RUN TestSetClientTLSErrors/missing_cert_file221=== PAUSE TestSetClientTLSErrors/missing_cert_file222=== RUN TestSetClientTLSErrors/missing_key_file223=== PAUSE TestSetClientTLSErrors/missing_key_file224=== RUN TestSetClientTLSErrors/missing_ca_file225=== PAUSE TestSetClientTLSErrors/missing_ca_file226=== RUN TestSetClientTLSErrors/invalid_ca_file227=== PAUSE TestSetClientTLSErrors/invalid_ca_file228=== CONT TestStreamPushIsolatesFailures2292026/09/15 08:31:32 ERROR Upload failed error="bad path" count=3230--- PASS: TestStreamPushIsolatesFailures (0.00s)231=== CONT TestDumpPathSingleFile232=== RUN TestSetClientTLS/rejects_connection_without_client_cert233=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert234=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA235=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA236=== RUN TestSetClientTLS/preserves_debug_logging_transport237=== PAUSE TestSetClientTLS/preserves_debug_logging_transport238=== CONT TestStreamPushReportsEveryPath239--- PASS: TestStreamPushReportsEveryPath (0.00s)240=== CONT TestShellSplitErrors241--- PASS: TestShellSplitErrors (0.00s)242=== CONT TestDumpPathMatchesNix243--- PASS: TestScriptTokenBadJSON (0.01s)244=== CONT TestConvertHashToNix32/invalid_format245=== CONT TestConvertHashToNix32/already_Nix32_format246=== CONT TestPathInfoCACompatibility/null_ca_field247=== CONT TestPathInfoCACompatibility/new_structured_format_-_text248--- PASS: TestScriptTokenEmptyToken (0.01s)249=== CONT TestConvertHashToNix32/SRI_format_to_Nix32250--- PASS: TestConvertHashToNix32 (0.00s)251 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)252 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)253 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)254=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method255=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive256=== CONT TestPathInfoCACompatibility/old_string_format_-_text257=== CONT TestRateLimiterFeedback/429_enables_limiter258=== CONT TestEncodeNixBase32/test_string_hash259--- PASS: TestPathInfoCACompatibility (0.00s)260 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)261 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)262 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)263 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)264 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)265=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2662026/09/15 08:31:32 WARN Rate limiter enabled after throttle name=server-test rate=5267=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2682026/09/15 08:31:32 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:571592692026/09/15 08:31:32 WARN Rate limiter backed off name=server-test rate=5270=== CONT TestRateLimiterFeedback/503_enables_limiter271=== CONT TestEncodeNixBase32/empty_input272--- PASS: TestEncodeNixBase32 (0.00s)273 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)274 --- PASS: TestEncodeNixBase32/empty_input (0.00s)275=== CONT TestUploadMultipart_SupersededByPeer/exists2762026/09/15 08:31:32 WARN Rate limiter enabled after throttle name=server-test rate=52772026/09/15 08:31:32 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:571652782026/09/15 08:31:32 WARN Rate limiter backed off name=server-test rate=5279--- PASS: TestRateLimiterFeedback (0.00s)280 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)281 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)282 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)283 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)284=== CONT TestUploadMultipart_SupersededByPeer/missing285=== CONT TestPartSizeForNAR/zero_stays_at_minimum286=== CONT TestPartSizeForNAR/1_TiB287=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts288=== CONT TestPartSizeForNAR/small_stays_at_minimum289=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum290=== CONT TestPartSizeForNAR/5_TiB_S3_max_object291=== CONT TestParsePathInfoJSON/Nix_format292=== CONT TestPartSizeForNAR/capped_at_5_GiB293=== CONT TestParsePathInfoJSON/whitespace_only294=== CONT TestParsePathInfoJSON/invalid_JSON295=== CONT TestParsePathInfoJSON/empty_input296=== CONT TestParsePathInfoJSON/Lix_format297=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths298=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths299=== CONT TestFilterOversizedClosures/no_limit_keeps_everything300=== CONT TestGetStorePathHash/valid_store_path301=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error302=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped303=== CONT TestFilterOversizedClosures/all_closures_skipped3042026/09/15 0--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)305 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)306 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)307--- PASS: TestPartSizeForNAR (0.00s)308 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)309 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)310 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)311 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)312 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)313 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)314 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)315--- PASS: TestParsePathInfoJSON (0.00s)316 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)317 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)318 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)319 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)320 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)321--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)8:31:32 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=2000322323 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)324 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)325=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error326=== CONT TestGetStorePathHash/basename_without_hyphen_should_error3272026/09/15 08:31:32 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=50328--- PASS: TestGetStorePathHash (0.00s)329 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)330 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)331 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)332 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)333--- PASS: TestFilterOversizedClosures (0.00s)334 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)335 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)336 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)337=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI338=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512339=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon340=== CONT TestSetClientTLSErrors/missing_cert_file341=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)342=== CONT TestSetClientTLSErrors/invalid_ca_file343--- PASS: TestPathInfoHashCompatibility (0.00s)344 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)345 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)346 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)347 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)348=== CONT TestSetClientTLSErrors/missing_ca_file349=== CONT TestSetClientTLSErrors/missing_key_file350=== CONT TestSetClientTLS/rejects_connection_without_client_cert351=== CONT TestSetClientTLS/preserves_debug_logging_transport352--- PASS: TestSetClientTLSErrors (0.00s)353 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)354 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)355 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)356 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)357=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA358--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)359--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)3602026/09/15 08:31:32 http: TLS handshake error from 127.0.0.1:57171: read tcp 127.0.0.1:57158->127.0.0.1:57171: use of closed network connection361--- PASS: TestSetClientTLS (0.00s)362 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)363 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)364 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)365--- PASS: TestDumpPathWriterError (0.04s)366--- PASS: TestDumpPathSingleFile (0.04s)367--- PASS: TestCaseHackSuffix (0.04s)368--- PASS: TestDumpPathMatchesNix (0.06s)369--- PASS: TestStreamPushBatchesUnderLoad (0.10s)370--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)371PASS372Running server tests...373The files belonging to this database system will be owned by user "_nixbld1".374This user must also own the server process.375376The database cluster will be initialized with locale "C".377The default database encoding has accordingly been set to "SQL_ASCII".378The default text search configuration will be set to "english".379380Data page checksums are enabled.381382creating directory /nix/var/nix/builds/nix-58445-3431720553/postgres1788701579/data ... ok383creating subdirectories ... ok384selecting dynamic shared memory implementation ... posix385selecting default "max_connections" ... 100386selecting default "shared_buffers" ... 128MB387selecting default time zone ... UTC388creating configuration files ... ok389running bootstrap script ... ok390performing post-bootstrap initialization ... ok391syncing data to disk ... ok392393initdb: warning: enabling "trust" authentication for local connections394initdb: 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.395396Success. You can now start the database server using:397398 pg_ctl -D /nix/var/nix/builds/nix-58445-3431720553/postgres1788701579/data -l logfile start399400/nix/var/nix/builds/nix-58445-3431720553/postgres1788701579:5432 - no response4012026-09-15 08:31:34.628 UTC [58512] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4022026-09-15 08:31:34.628 UTC [58512] LOG: listening on Unix socket "/nix/var/nix/builds/nix-58445-3431720553/postgres1788701579/.s.PGSQL.5432"4032026-09-15 08:31:34.630 UTC [58519] LOG: database system was shut down at 2026-09-15 08:31:34 UTC4042026-09-15 08:31:34.631 UTC [58512] LOG: database system is ready to accept connections405/nix/var/nix/builds/nix-58445-3431720553/postgres1788701579:5432 - accepting connections406=== RUN TestService_AuthMiddleware407=== PAUSE TestService_AuthMiddleware408=== RUN TestService_AuthMiddleware_MTLSProxyHeader409=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader410=== RUN TestService_AuthMiddleware_MTLSBoundSubjects411=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects412=== RUN TestService_ReadAuthMiddleware413=== PAUSE TestService_ReadAuthMiddleware414=== RUN TestService_AuthMiddleware_OIDC415=== PAUSE TestService_AuthMiddleware_OIDC416=== RUN TestService_RequireScope_OIDC417=== PAUSE TestService_RequireScope_OIDC418=== RUN TestService_ReadScope_PublicByDefault419=== PAUSE TestService_ReadScope_PublicByDefault420=== RUN TestCacheConfigHandler421=== PAUSE TestCacheConfigHandler422=== RUN TestCacheStatsHandler423=== PAUSE TestCacheStatsHandler424=== RUN TestClientCADerivations425=== PAUSE TestClientCADerivations426=== RUN TestClientErrorHandling427=== PAUSE TestClientErrorHandling428=== RUN TestClientIntegration429=== PAUSE TestClientIntegration430=== RUN TestClientMultipleUploads431=== PAUSE TestClientMultipleUploads432=== RUN TestClientWithDependencies433=== PAUSE TestClientWithDependencies434=== RUN TestPinProtectsFromGC435=== PAUSE TestPinProtectsFromGC436=== RUN TestResolveDBConnectionString437=== PAUSE TestResolveDBConnectionString438=== RUN TestGCAdvisoryLockBlocksConcurrentRun4392026-09-15 08:31:34.949 UTC [58540] ERROR: relation "goose_db_version" does not exist at character 364402026-09-15 08:31:34.949 UTC [58540] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4412026/09/15 08:31:34 OK 20241026095416_initial_model.sql (44.11ms)4422026/09/15 08:31:34 OK 20251210153512_drop_unused_gin_index.sql (759.33µs)4432026/09/15 08:31:34 OK 20251218171726_add_pins.sql (811.04µs)4442026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (931.04µs)4452026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200004462026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.32ms)4472026/09/15 08:31:35 OK 2_object_stats_trigger.sql (214.92µs)4482026/09/15 08:31:35 goose: up to current file version: 2449--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.43s)450=== RUN TestGCBugBareHashReferences451=== PAUSE TestGCBugBareHashReferences452=== RUN TestGCMetrics453=== PAUSE TestGCMetrics454=== RUN TestGCTaskStore_StartNew455=== PAUSE TestGCTaskStore_StartNew456=== RUN TestGCTaskStore_DeduplicateSameParams457=== PAUSE TestGCTaskStore_DeduplicateSameParams458=== RUN TestGCTaskStore_ConflictDifferentParams459=== PAUSE TestGCTaskStore_ConflictDifferentParams460=== RUN TestGCTaskStore_GetEmpty461=== PAUSE TestGCTaskStore_GetEmpty462=== RUN TestGCTaskStore_GetReturnsLatest463=== PAUSE TestGCTaskStore_GetReturnsLatest464=== RUN TestGCTaskStore_CompletedAllowsNewTask465=== PAUSE TestGCTaskStore_CompletedAllowsNewTask466=== RUN TestGCTaskStore_PhaseUpdates467=== PAUSE TestGCTaskStore_PhaseUpdates468=== RUN TestGCTaskStore_Fail469=== PAUSE TestGCTaskStore_Fail470=== RUN TestGracefulShutdownDrainsInflight471=== PAUSE TestGracefulShutdownDrainsInflight472=== RUN TestService_healthCheckHandler473=== PAUSE TestService_healthCheckHandler474=== RUN TestService_readinessHandler475=== PAUSE TestService_readinessHandler476=== RUN TestGenerateLandingPage477=== PAUSE TestGenerateLandingPage478=== RUN TestCacheConfigHandlerMaxNarSize479=== PAUSE TestCacheConfigHandlerMaxNarSize480=== RUN TestCreatePendingClosureRejectsOversizedNAR481=== PAUSE TestCreatePendingClosureRejectsOversizedNAR482=== RUN TestNARDeduplicationMetadataUploadBug483=== PAUSE TestNARDeduplicationMetadataUploadBug484=== RUN TestMetricsInventory485=== PAUSE TestMetricsInventory486=== RUN TestService_NativeMTLS487=== PAUSE TestService_NativeMTLS488=== RUN TestServerTLSConfig489=== PAUSE TestServerTLSConfig490=== RUN TestMultipartCleanup491=== PAUSE TestMultipartCleanup492=== RUN TestObjectStatsTrigger493=== PAUSE TestObjectStatsTrigger494=== RUN TestOrphanedObjectsGC495=== PAUSE TestOrphanedObjectsGC496=== RUN TestOrphanedObjectsGCStressTest497=== PAUSE TestOrphanedObjectsGCStressTest498=== RUN TestResurrectedObjectNotDeleted499=== PAUSE TestResurrectedObjectNotDeleted500=== RUN TestParseSingleRange501=== PAUSE TestParseSingleRange502=== RUN TestIsValidCachePath503=== PAUSE TestIsValidCachePath504=== RUN TestReadProxyNarinfo505=== PAUSE TestReadProxyNarinfo506=== RUN TestReadProxyNarinfoAlreadyDecompressed507=== PAUSE TestReadProxyNarinfoAlreadyDecompressed508=== RUN TestReadProxyNarStreaming509=== PAUSE TestReadProxyNarStreaming510=== RUN TestReadProxy404511=== PAUSE TestReadProxy404512=== RUN TestReadProxyInvalidPath513=== PAUSE TestReadProxyInvalidPath514=== RUN TestReadProxyHead515=== PAUSE TestReadProxyHead516=== RUN TestReadProxyConditionalGet517=== PAUSE TestReadProxyConditionalGet518=== RUN TestReadProxyRootRedirectsToIndexHTML519=== PAUSE TestReadProxyRootRedirectsToIndexHTML520=== RUN TestReadProxyDisabled521=== PAUSE TestReadProxyDisabled522=== RUN TestReadRedirectNar523=== PAUSE TestReadRedirectNar524=== RUN TestReadRedirectKeepsNarinfoProxied525=== PAUSE TestReadRedirectKeepsNarinfoProxied526=== RUN TestReadProxyRangeRequest527=== PAUSE TestReadProxyRangeRequest528=== RUN TestReadRedirectUsesPublicS3URL529=== PAUSE TestReadRedirectUsesPublicS3URL530=== RUN TestRedundantMultipartUpload531=== PAUSE TestRedundantMultipartUpload532=== RUN TestCompleteMultipartUpload_ErrorButObjectExists533=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists534=== RUN TestCompletedNarNotReofferedAcrossClosures535=== PAUSE TestCompletedNarNotReofferedAcrossClosures536=== RUN TestPresignedUploadRegisteredBeforeCommit537=== PAUSE TestPresignedUploadRegisteredBeforeCommit538=== RUN TestService_Rustfstest539=== PAUSE TestService_Rustfstest540=== RUN TestParseSize541=== PAUSE TestParseSize542=== RUN TestSkippedUploadsHandler543=== PAUSE TestSkippedUploadsHandler544=== RUN TestSystemdListenerNotActivated545--- PASS: TestSystemdListenerNotActivated (0.00s)546=== RUN TestWatchdogBeatsWhenHealthy547--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)548=== RUN TestWatchdogSkipsWhenUnhealthy5492026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5502026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5512026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5522026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5532026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5542026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5552026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5562026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5572026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5582026/09/15 08:31:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"559--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)560=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle561=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle562=== RUN TestProxyWriteTimeout563=== PAUSE TestProxyWriteTimeout564=== RUN TestIsValidUploadKey565=== PAUSE TestIsValidUploadKey566=== RUN TestUploadHandlersRejectInvalidKeys567=== PAUSE TestUploadHandlersRejectInvalidKeys568=== RUN TestUploadHandlersRejectOversizedBody569=== PAUSE TestUploadHandlersRejectOversizedBody570=== RUN TestService_cleanupPendingClosuresHandler571=== PAUSE TestService_cleanupPendingClosuresHandler572=== RUN TestService_createPendingClosureHandler573=== PAUSE TestService_createPendingClosureHandler574=== RUN TestService_verifyS3Integrity575=== PAUSE TestService_verifyS3Integrity576=== RUN TestCompleteMultipartUnregistered577=== PAUSE TestCompleteMultipartUnregistered578=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT579=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT580=== CONT TestRedundantMultipartUpload581=== CONT TestService_AuthMiddleware582=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT583=== CONT TestService_readinessHandler584=== CONT TestParseSize585--- PASS: TestParseSize (0.00s)586=== CONT TestProxyWriteTimeout587=== RUN TestProxyWriteTimeout/narinfo588=== PAUSE TestProxyWriteTimeout/narinfo589=== RUN TestProxyWriteTimeout/1_GiB_nar590=== PAUSE TestProxyWriteTimeout/1_GiB_nar591=== RUN TestProxyWriteTimeout/10_GiB_nar592=== PAUSE TestProxyWriteTimeout/10_GiB_nar593=== RUN TestProxyWriteTimeout/unknown_size594=== PAUSE TestProxyWriteTimeout/unknown_size595=== CONT TestProxyWriteTimeout/narinfo596=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle597=== CONT TestIsValidUploadKey598=== CONT TestReadRedirectUsesPublicS3URL599=== RUN TestIsValidUploadKey/narinfo600=== PAUSE TestIsValidUploadKey/narinfo601=== RUN TestIsValidUploadKey/nar_zst602=== PAUSE TestIsValidUploadKey/nar_zst603=== RUN TestIsValidUploadKey/nar_xz604=== CONT TestCompleteMultipartUnregistered605=== PAUSE TestIsValidUploadKey/nar_xz606=== RUN TestIsValidUploadKey/nar_plain607=== PAUSE TestIsValidUploadKey/nar_plain608=== RUN TestIsValidUploadKey/listing609=== PAUSE TestIsValidUploadKey/listing610=== RUN TestIsValidUploadKey/build_log611=== PAUSE TestIsValidUploadKey/build_log612=== RUN TestIsValidUploadKey/build_log_home-manager_file613=== PAUSE TestIsValidUploadKey/build_log_home-manager_file614=== RUN TestIsValidUploadKey/build_log_plus_in_name615=== PAUSE TestIsValidUploadKey/build_log_plus_in_name616=== RUN TestIsValidUploadKey/build_log_question_mark617=== CONT TestService_verifyS3Integrity618=== PAUSE TestIsValidUploadKey/build_log_question_mark619=== RUN TestIsValidUploadKey/build_log_equals620=== PAUSE TestIsValidUploadKey/build_log_equals621=== RUN TestIsValidUploadKey/realisation622=== PAUSE TestIsValidUploadKey/realisation623=== RUN TestIsValidUploadKey/realisation_plus_in_output624=== PAUSE TestIsValidUploadKey/realisation_plus_in_output625=== CONT TestService_createPendingClosureHandler626=== RUN TestIsValidUploadKey/nix-cache-info627=== PAUSE TestIsValidUploadKey/nix-cache-info628=== RUN TestIsValidUploadKey/index.html629=== PAUSE TestIsValidUploadKey/index.html630=== RUN TestIsValidUploadKey/narinfo_key,_nar_type631=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type632=== RUN TestIsValidUploadKey/nar_key,_narinfo_type633=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type634=== RUN TestIsValidUploadKey/listing_key,_narinfo_type635=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type636=== RUN TestIsValidUploadKey/traversal637=== PAUSE TestIsValidUploadKey/traversal638=== RUN TestIsValidUploadKey/traversal_nar639=== PAUSE TestIsValidUploadKey/traversal_nar640=== RUN TestIsValidUploadKey/absolute641=== PAUSE TestIsValidUploadKey/absolute642=== RUN TestIsValidUploadKey/empty_key643=== PAUSE TestIsValidUploadKey/empty_key644=== RUN TestIsValidUploadKey/unknown_type645=== PAUSE TestIsValidUploadKey/unknown_type646=== CONT TestService_cleanupPendingClosuresHandler6472026-09-15 08:31:35.875 UTC [58635] ERROR: relation "goose_db_version" does not exist at character 366482026-09-15 08:31:35.875 UTC [58635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6492026/09/15 08:31:35 OK 20241026095416_initial_model.sql (2.9ms)6502026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (546.83µs)6512026/09/15 08:31:35 OK 20251218171726_add_pins.sql (677.42µs)6522026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (782.58µs)6532026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200006542026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.31ms)6552026/09/15 08:31:35 OK 2_object_stats_trigger.sql (371.71µs)6562026/09/15 08:31:35 goose: up to current file version: 26572026-09-15 08:31:35.901 UTC [58636] ERROR: relation "goose_db_version" does not exist at character 366582026-09-15 08:31:35.901 UTC [58636] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6592026-09-15 08:31:35.905 UTC [58639] ERROR: relation "goose_db_version" does not exist at character 366602026-09-15 08:31:35.905 UTC [58639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6612026-09-15 08:31:35.905 UTC [58637] ERROR: relation "goose_db_version" does not exist at character 366622026-09-15 08:31:35.905 UTC [58637] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6632026-09-15 08:31:35.905 UTC [58638] ERROR: relation "goose_db_version" does not exist at character 366642026-09-15 08:31:35.905 UTC [58638] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6652026-09-15 08:31:35.905 UTC [58640] ERROR: relation "goose_db_version" does not exist at character 366662026-09-15 08:31:35.905 UTC [58640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6672026-09-15 08:31:35.906 UTC [58641] ERROR: relation "goose_db_version" does not exist at character 366682026-09-15 08:31:35.906 UTC [58641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6692026-09-15 08:31:35.907 UTC [58642] ERROR: relation "goose_db_version" does not exist at character 366702026-09-15 08:31:35.907 UTC [58642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6712026-09-15 08:31:35.908 UTC [58644] ERROR: relation "goose_db_version" does not exist at character 366722026-09-15 08:31:35.908 UTC [58644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6732026-09-15 08:31:35.909 UTC [58643] ERROR: relation "goose_db_version" does not exist at character 366742026-09-15 08:31:35.909 UTC [58643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6752026/09/15 08:31:35 OK 20241026095416_initial_model.sql (7.1ms)6762026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)6772026/09/15 08:31:35 OK 20241026095416_initial_model.sql (6.35ms)6782026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.78ms)6792026/09/15 08:31:35 OK 20241026095416_initial_model.sql (7.48ms)6802026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (749µs)6812026/09/15 08:31:35 OK 20241026095416_initial_model.sql (6.02ms)6822026/09/15 08:31:35 OK 20241026095416_initial_model.sql (7.02ms)6832026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (949.63µs)6842026/09/15 08:31:35 OK 20241026095416_initial_model.sql (7.98ms)6852026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (885.08µs)6862026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)6872026/09/15 08:31:35 OK 20241026095416_initial_model.sql (6.96ms)6882026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)6892026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200006902026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.69ms)6912026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (871.29µs)6922026/09/15 08:31:35 OK 20241026095416_initial_model.sql (8.26ms)6932026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.49ms)6942026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (828.13µs)6952026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.15ms)6962026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (895.38µs)6972026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.37ms)6982026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.62ms)6992026/09/15 08:31:35 OK 20241026095416_initial_model.sql (7.8ms)7002026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.36ms)7012026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007022026/09/15 08:31:35 OK 2_object_stats_trigger.sql (671.33µs)7032026/09/15 08:31:35 goose: up to current file version: 27042026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.76ms)7052026/09/15 08:31:35 OK 20251218171726_add_pins.sql (992.29µs)7062026/09/15 08:31:35 OK 20251210153512_drop_unused_gin_index.sql (505.79µs)7072026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (2.43ms)7082026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007092026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.71ms)7102026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007112026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.91ms)7122026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.08ms)7132026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007142026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.52ms)7152026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (2.04ms)7162026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007172026/09/15 08:31:35 OK 1_commit_pending_closure.sql (958.33µs)7182026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.17ms)7192026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.67ms)7202026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007212026/09/15 08:31:35 OK 2_object_stats_trigger.sql (284.79µs)7222026/09/15 08:31:35 goose: up to current file version: 27232026/09/15 08:31:35 OK 2_object_stats_trigger.sql (273.96µs)7242026/09/15 08:31:35 goose: up to current file version: 27252026/09/15 08:31:35 OK 20251218171726_add_pins.sql (1.51ms)7262026/09/15 08:31:35 OK 2_object_stats_trigger.sql (366.46µs)7272026/09/15 08:31:35 goose: up to current file version: 27282026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.55ms)7292026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007302026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.1ms)7312026/09/15 08:31:35 OK 1_commit_pending_closure.sql (940.67µs)7322026/09/15 08:31:35 OK 1_commit_pending_closure.sql (1.23ms)7332026/09/15 08:31:35 OK 2_object_stats_trigger.sql (314.67µs)7342026/09/15 08:31:35 goose: up to current file version: 27352026/09/15 08:31:35 OK 2_object_stats_trigger.sql (255.13µs)7362026/09/15 08:31:35 goose: up to current file version: 27372026/09/15 08:31:35 OK 20260628120000_add_object_size_and_stats.sql (1.06ms)7382026/09/15 08:31:35 goose: successfully migrated database to version: 202606281200007392026/09/15 08:31:35 OK 2_object_stats_trigger.sql (288.21µs)7402026/09/15 08:31:35 goose: up to current file version: 27412026/09/15 08:31:35 OK 1_commit_pending_closure.sql (986.42µs)7422026/09/15 08:31:35 OK 2_object_stats_trigger.sql (168.54µs)7432026/09/15 08:31:35 goose: up to current file version: 27442026/09/15 08:31:35 OK 1_commit_pending_closure.sql (657.17µs)7452026/09/15 08:31:35 OK 2_object_stats_trigger.sql (166.04µs)7462026/09/15 08:31:35 goose: up to current file version: 2747--- PASS: TestReadRedirectUsesPublicS3URL (0.58s)748=== CONT TestUploadHandlersRejectOversizedBody749=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure750=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure751=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart752=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart753=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts754=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts755=== CONT TestUploadHandlersRejectInvalidKeys756=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info757=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info758=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal759=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal760=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key761=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key762=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key763=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key764=== CONT TestPresignedUploadRegisteredBeforeCommit7652026/09/15 08:31:36 INFO Received uploads request method=POST path=/api/pending_closures7662026/09/15 08:31:36 INFO Received uploads request method=POST path=/api/pending_closures7672026/09/15 08:31:36 INFO Received uploads request method=POST path=/api/pending_closures7682026/09/15 08:31:36 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"769--- PASS: TestService_AuthMiddleware (0.83s)770=== CONT TestService_Rustfstest7712026/09/15 08:31:36 INFO Received uploads request method=POST path=/api/pending_closures7722026/09/15 08:31:36 WARN readiness check failed error="closed pool"773--- PASS: TestService_readinessHandler (1.20s)774=== CONT TestProxyWriteTimeout/unknown_size775=== CONT TestSkippedUploadsHandler7762026/09/15 08:31:36 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000777--- PASS: TestSkippedUploadsHandler (0.00s)778=== CONT TestProxyWriteTimeout/10_GiB_nar779=== CONT TestIsValidCachePath780=== RUN TestIsValidCachePath/narinfo781=== PAUSE TestIsValidCachePath/narinfo782=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars783=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars784=== RUN TestIsValidCachePath/nar_zst785=== PAUSE TestIsValidCachePath/nar_zst786=== RUN TestIsValidCachePath/nar_xz787=== PAUSE TestIsValidCachePath/nar_xz788=== RUN TestIsValidCachePath/nar_bz2789=== PAUSE TestIsValidCachePath/nar_bz2790=== RUN TestIsValidCachePath/nar_uncompressed791=== PAUSE TestIsValidCachePath/nar_uncompressed792=== RUN TestIsValidCachePath/ls793=== PAUSE TestIsValidCachePath/ls794=== RUN TestIsValidCachePath/log795=== PAUSE TestIsValidCachePath/log796=== RUN TestIsValidCachePath/realisation797=== PAUSE TestIsValidCachePath/realisation798=== RUN TestIsValidCachePath/nix-cache-info799=== PAUSE TestIsValidCachePath/nix-cache-info800=== RUN TestIsValidCachePath/index.html801=== PAUSE TestIsValidCachePath/index.html802=== RUN TestIsValidCachePath/traversal_parent803=== PAUSE TestIsValidCachePath/traversal_parent804=== RUN TestIsValidCachePath/traversal_in_middle805=== PAUSE TestIsValidCachePath/traversal_in_middle806=== RUN TestIsValidCachePath/invalid_char_e807=== PAUSE TestIsValidCachePath/invalid_char_e808=== RUN TestIsValidCachePath/invalid_char_u809=== PAUSE TestIsValidCachePath/invalid_char_u810=== RUN TestIsValidCachePath/random_path811=== PAUSE TestIsValidCachePath/random_path812=== RUN TestIsValidCachePath/empty813=== PAUSE TestIsValidCachePath/empty814=== RUN TestIsValidCachePath/leading_slash815=== PAUSE TestIsValidCachePath/leading_slash816=== RUN TestIsValidCachePath/wrong_extension817=== PAUSE TestIsValidCachePath/wrong_extension818=== RUN TestIsValidCachePath/short_hash819=== PAUSE TestIsValidCachePath/short_hash820=== CONT TestReadProxyRangeRequest8212026-09-15 08:31:36.762 UTC [58658] ERROR: relation "goose_db_version" does not exist at character 368222026-09-15 08:31:36.762 UTC [58658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8232026/09/15 08:31:36 OK 20241026095416_initial_model.sql (71.84ms)8242026/09/15 08:31:36 OK 20251210153512_drop_unused_gin_index.sql (19.36ms)8252026/09/15 08:31:36 OK 20251218171726_add_pins.sql (21.18ms)8262026/09/15 08:31:36 OK 20260628120000_add_object_size_and_stats.sql (26.02ms)8272026/09/15 08:31:36 goose: successfully migrated database to version: 202606281200008282026-09-15 08:31:36.935 UTC [58659] ERROR: relation "goose_db_version" does not exist at character 368292026-09-15 08:31:36.935 UTC [58659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8302026/09/15 08:31:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8312026/09/15 08:31:36 OK 1_commit_pending_closure.sql (7.53ms)8322026/09/15 08:31:36 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst833--- PASS: TestCompleteMultipartUnregistered (1.44s)834=== CONT TestReadRedirectKeepsNarinfoProxied8352026/09/15 08:31:36 OK 2_object_stats_trigger.sql (618µs)8362026/09/15 08:31:36 goose: up to current file version: 28372026/09/15 08:31:37 OK 20241026095416_initial_model.sql (122.04ms)8382026/09/15 08:31:37 OK 20251210153512_drop_unused_gin_index.sql (9.12ms)8392026/09/15 08:31:37 OK 20251218171726_add_pins.sql (17.49ms)8402026/09/15 08:31:37 OK 20260628120000_add_object_size_and_stats.sql (14.69ms)8412026/09/15 08:31:37 goose: successfully migrated database to version: 202606281200008422026/09/15 08:31:37 OK 1_commit_pending_closure.sql (6.95ms)8432026/09/15 08:31:37 OK 2_object_stats_trigger.sql (211.29µs)8442026/09/15 08:31:37 goose: up to current file version: 28452026/09/15 08:31:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8462026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8472026/09/15 08:31:37 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZGRkYzBkZWEtZjZjMS00ZjQ2LTk1ZGEtNzFmZjkzMzNkNzhjLjdiNGM5OWVjLTg0MWEtNDM1YS1iMzhhLTZjMGY1NDZiMzE2OXgxNzg5NDYxMDk2MTgxMDk0MDAw parts=108482026/09/15 08:31:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8492026/09/15 08:31:37 INFO Completed upload id=18502026/09/15 08:31:37 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008512026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8522026/09/15 08:31:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures8532026/09/15 08:31:37 INFO Aborted multipart uploads count=08542026/09/15 08:31:37 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=08552026/09/15 08:31:37 INFO Vacuumed table table=pending_closures856--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.72s)857=== CONT TestReadRedirectNar8582026/09/15 08:31:37 INFO Vacuumed table table=pending_objects8592026/09/15 08:31:37 INFO Vacuumed table table=multipart_uploads8602026/09/15 08:31:37 INFO Vacuumed table table=closures8612026/09/15 08:31:37 INFO Vacuumed table table=objects8622026/09/15 08:31:37 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000863--- PASS: TestService_createPendingClosureHandler (1.74s)864=== CONT TestReadProxyDisabled8652026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8662026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8672026-09-15 08:31:37.426 UTC [58669] ERROR: relation "goose_db_version" does not exist at character 368682026-09-15 08:31:37.426 UTC [58669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8692026/09/15 08:31:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8702026/09/15 08:31:37 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZGRkYzBkZWEtZjZjMS00ZjQ2LTk1ZGEtNzFmZjkzMzNkNzhjLmVlMWY5ZDZiLTlmZGYtNDllNS1hY2JmLWY1ZTQ4OTQxNjYwN3gxNzg5NDYxMDk2NDk4NzQ4MDAw parts=108712026/09/15 08:31:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8722026/09/15 08:31:37 INFO Completed upload id=18732026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8742026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8752026/09/15 08:31:37 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8762026/09/15 08:31:37 WARN Found objects in DB but missing from S3, will re-upload count=1877--- PASS: TestService_verifyS3Integrity (2.02s)878=== CONT TestReadProxyRootRedirectsToIndexHTML8792026/09/15 08:31:37 OK 20241026095416_initial_model.sql (96.97ms)8802026/09/15 08:31:37 OK 20251210153512_drop_unused_gin_index.sql (13.27ms)8812026/09/15 08:31:37 OK 20251218171726_add_pins.sql (9.49ms)8822026/09/15 08:31:37 INFO Received cleanup request method=DELETE path=/api/pending_closures8832026/09/15 08:31:37 INFO Aborted multipart uploads count=08842026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures8852026/09/15 08:31:37 OK 20260628120000_add_object_size_and_stats.sql (42.02ms)8862026/09/15 08:31:37 goose: successfully migrated database to version: 202606281200008872026/09/15 08:31:37 OK 1_commit_pending_closure.sql (1.14ms)8882026/09/15 08:31:37 OK 2_object_stats_trigger.sql (224.5µs)8892026/09/15 08:31:37 goose: up to current file version: 28902026-09-15 08:31:37.656 UTC [58672] ERROR: relation "goose_db_version" does not exist at character 368912026-09-15 08:31:37.656 UTC [58672] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8922026/09/15 08:31:37 INFO Received cleanup request method=DELETE path=/api/pending_closures8932026/09/15 08:31:37 INFO Aborted multipart uploads count=18942026/09/15 08:31:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8952026-09-15 08:31:37.666 UTC [58642] ERROR: Closure does not exist: id=18962026-09-15 08:31:37.666 UTC [58642] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE8972026-09-15 08:31:37.666 UTC [58642] STATEMENT: -- name: CommitPendingClosure :exec898 SELECT commit_pending_closure($1::bigint)899 900--- PASS: TestService_cleanupPendingClosuresHandler (2.16s)901=== CONT TestReadProxyConditionalGet9022026/09/15 08:31:37 OK 20241026095416_initial_model.sql (58.44ms)9032026/09/15 08:31:37 OK 20251210153512_drop_unused_gin_index.sql (7.1ms)9042026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures9052026/09/15 08:31:37 OK 20251218171726_add_pins.sql (10.05ms)9062026/09/15 08:31:37 OK 20260628120000_add_object_size_and_stats.sql (23.08ms)9072026/09/15 08:31:37 goose: successfully migrated database to version: 202606281200009082026/09/15 08:31:37 OK 1_commit_pending_closure.sql (6.93ms)9092026/09/15 08:31:37 OK 2_object_stats_trigger.sql (227.88µs)9102026/09/15 08:31:37 goose: up to current file version: 29112026/09/15 08:31:37 INFO Received uploads request method=POST path=/api/pending_closures9122026/09/15 08:31:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9132026/09/15 08:31:38 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9142026/09/15 08:31:38 INFO Received uploads request method=POST path=/api/pending_closures915--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.90s)916=== CONT TestReadProxyHead9172026-09-15 08:31:38.105 UTC [58679] ERROR: relation "goose_db_version" does not exist at character 369182026-09-15 08:31:38.105 UTC [58679] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9192026-09-15 08:31:38.105 UTC [58680] ERROR: relation "goose_db_version" does not exist at character 369202026-09-15 08:31:38.105 UTC [58680] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC921--- PASS: TestService_Rustfstest (1.83s)922=== CONT TestReadProxyInvalidPath9232026/09/15 08:31:38 OK 20241026095416_initial_model.sql (85.86ms)9242026/09/15 08:31:38 OK 20241026095416_initial_model.sql (87.4ms)9252026/09/15 08:31:38 OK 20251210153512_drop_unused_gin_index.sql (4.94ms)9262026/09/15 08:31:38 OK 20251210153512_drop_unused_gin_index.sql (13.42ms)9272026/09/15 08:31:38 OK 20251218171726_add_pins.sql (21.27ms)9282026/09/15 08:31:38 OK 20251218171726_add_pins.sql (21.78ms)9292026/09/15 08:31:38 OK 20260628120000_add_object_size_and_stats.sql (29.35ms)9302026/09/15 08:31:38 goose: successfully migrated database to version: 202606281200009312026/09/15 08:31:38 OK 20260628120000_add_object_size_and_stats.sql (30.16ms)9322026/09/15 08:31:38 goose: successfully migrated database to version: 202606281200009332026/09/15 08:31:38 OK 1_commit_pending_closure.sql (1.15ms)9342026/09/15 08:31:38 OK 1_commit_pending_closure.sql (1.4ms)9352026/09/15 08:31:38 OK 2_object_stats_trigger.sql (218.38µs)9362026/09/15 08:31:38 goose: up to current file version: 29372026/09/15 08:31:38 OK 2_object_stats_trigger.sql (232.17µs)9382026/09/15 08:31:38 goose: up to current file version: 2939--- PASS: TestReadProxyRangeRequest (1.65s)940=== CONT TestProxyWriteTimeout/1_GiB_nar941--- PASS: TestProxyWriteTimeout (0.00s)942 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)943 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)944 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)945 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)946=== CONT TestReadProxy4049472026/09/15 08:31:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9482026/09/15 08:31:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZGRkYzBkZWEtZjZjMS00ZjQ2LTk1ZGEtNzFmZjkzMzNkNzhjLjk2N2FlMmZhLWQ1OWYtNDQyNi1hMWZiLTNkMGRmMmY2OTYzMXgxNzg5NDYxMDk3MzcyODkxMDAw parts=12949--- PASS: TestRedundantMultipartUpload (3.04s)950=== CONT TestServerTLSConfig951=== RUN TestServerTLSConfig/no_client_CA952=== PAUSE TestServerTLSConfig/no_client_CA953=== RUN TestServerTLSConfig/missing_CA_file954=== PAUSE TestServerTLSConfig/missing_CA_file955=== RUN TestServerTLSConfig/not_a_PEM_file956=== PAUSE TestServerTLSConfig/not_a_PEM_file957=== CONT TestReadProxyNarStreaming958--- PASS: TestReadRedirectKeepsNarinfoProxied (1.62s)959=== CONT TestParseSingleRange960=== RUN TestParseSingleRange/none961=== PAUSE TestParseSingleRange/none962=== RUN TestParseSingleRange/unknown_unit963=== PAUSE TestParseSingleRange/unknown_unit964=== RUN TestParseSingleRange/multi-range_ignored965=== PAUSE TestParseSingleRange/multi-range_ignored966=== RUN TestParseSingleRange/malformed_no_dash967=== PAUSE TestParseSingleRange/malformed_no_dash968=== RUN TestParseSingleRange/malformed_both_empty969=== PAUSE TestParseSingleRange/malformed_both_empty970=== RUN TestParseSingleRange/malformed_end_before_start971=== PAUSE TestParseSingleRange/malformed_end_before_start972=== RUN TestParseSingleRange/closed973=== PAUSE TestParseSingleRange/closed974=== RUN TestParseSingleRange/open-ended975=== PAUSE TestParseSingleRange/open-ended976=== RUN TestParseSingleRange/end_clamped_to_size977=== PAUSE TestParseSingleRange/end_clamped_to_size978=== RUN TestParseSingleRange/suffix979=== PAUSE TestParseSingleRange/suffix980=== RUN TestParseSingleRange/suffix_exceeds_size981=== PAUSE TestParseSingleRange/suffix_exceeds_size982=== RUN TestParseSingleRange/single_byte983=== PAUSE TestParseSingleRange/single_byte984=== RUN TestParseSingleRange/start_past_EOF985=== PAUSE TestParseSingleRange/start_past_EOF986=== RUN TestParseSingleRange/start_far_past_EOF987=== PAUSE TestParseSingleRange/start_far_past_EOF988=== CONT TestReadProxyNarinfoAlreadyDecompressed9892026-09-15 08:31:38.626 UTC [58691] ERROR: relation "goose_db_version" does not exist at character 369902026-09-15 08:31:38.626 UTC [58691] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9912026-09-15 08:31:38.638 UTC [58692] ERROR: relation "goose_db_version" does not exist at character 369922026-09-15 08:31:38.638 UTC [58692] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC993--- PASS: TestReadRedirectNar (1.48s)994=== CONT TestResurrectedObjectNotDeleted9952026/09/15 08:31:38 OK 20241026095416_initial_model.sql (43.52ms)9962026/09/15 08:31:38 OK 20241026095416_initial_model.sql (69.75ms)9972026/09/15 08:31:38 OK 20251210153512_drop_unused_gin_index.sql (5.77ms)9982026/09/15 08:31:38 OK 20251210153512_drop_unused_gin_index.sql (750.88µs)9992026/09/15 08:31:38 OK 20251218171726_add_pins.sql (1.46ms)10002026/09/15 08:31:38 OK 20251218171726_add_pins.sql (1.43ms)10012026/09/15 08:31:38 OK 20260628120000_add_object_size_and_stats.sql (16.42ms)10022026/09/15 08:31:38 goose: successfully migrated database to version: 2026062812000010032026/09/15 08:31:38 OK 20260628120000_add_object_size_and_stats.sql (20.66ms)10042026/09/15 08:31:38 goose: successfully migrated database to version: 2026062812000010052026/09/15 08:31:38 OK 1_commit_pending_closure.sql (2.12ms)10062026/09/15 08:31:38 OK 1_commit_pending_closure.sql (6.42ms)10072026/09/15 08:31:38 OK 2_object_stats_trigger.sql (267.17µs)10082026/09/15 08:31:38 goose: up to current file version: 210092026/09/15 08:31:38 OK 2_object_stats_trigger.sql (244.17µs)10102026/09/15 08:31:38 goose: up to current file version: 21011--- PASS: TestReadProxyDisabled (1.59s)1012=== CONT TestReadProxyNarinfo10132026-09-15 08:31:38.861 UTC [58697] ERROR: relation "goose_db_version" does not exist at character 3610142026-09-15 08:31:38.861 UTC [58697] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10152026/09/15 08:31:38 OK 20241026095416_initial_model.sql (51.92ms)10162026/09/15 08:31:38 OK 20251210153512_drop_unused_gin_index.sql (12.57ms)1017--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.46s)1018=== CONT TestOrphanedObjectsGCStressTest10192026/09/15 08:31:38 OK 20251218171726_add_pins.sql (26.99ms)10202026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (23.97ms)10212026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000010222026/09/15 08:31:39 OK 1_commit_pending_closure.sql (11.11ms)10232026/09/15 08:31:39 OK 2_object_stats_trigger.sql (924.46µs)10242026/09/15 08:31:39 goose: up to current file version: 210252026-09-15 08:31:39.118 UTC [58700] ERROR: relation "goose_db_version" does not exist at character 3610262026-09-15 08:31:39.118 UTC [58700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1027--- PASS: TestReadProxyConditionalGet (1.50s)1028=== CONT TestCompletedNarNotReofferedAcrossClosures10292026/09/15 08:31:39 OK 20241026095416_initial_model.sql (56.16ms)10302026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (6.88ms)10312026-09-15 08:31:39.217 UTC [58703] ERROR: relation "goose_db_version" does not exist at character 3610322026-09-15 08:31:39.217 UTC [58703] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10332026/09/15 08:31:39 OK 20251218171726_add_pins.sql (13.69ms)10342026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (17.19ms)10352026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000010362026/09/15 08:31:39 OK 1_commit_pending_closure.sql (2.06ms)10372026/09/15 08:31:39 OK 2_object_stats_trigger.sql (467.63µs)10382026/09/15 08:31:39 goose: up to current file version: 210392026/09/15 08:31:39 OK 20241026095416_initial_model.sql (94.42ms)10402026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (4.31ms)10412026/09/15 08:31:39 OK 20251218171726_add_pins.sql (6.05ms)10422026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (13.98ms)10432026/09/15 08:31:39 goose: successfully migrated database to version: 202606281200001044--- PASS: TestReadProxyHead (1.37s)1045=== CONT TestOrphanedObjectsGC10462026/09/15 08:31:39 OK 1_commit_pending_closure.sql (8.63ms)10472026-09-15 08:31:39.376 UTC [58704] ERROR: relation "goose_db_version" does not exist at character 3610482026-09-15 08:31:39.376 UTC [58704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10492026-09-15 08:31:39.376 UTC [58705] ERROR: relation "goose_db_version" does not exist at character 3610502026-09-15 08:31:39.376 UTC [58705] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10512026/09/15 08:31:39 OK 2_object_stats_trigger.sql (511.13µs)10522026/09/15 08:31:39 goose: up to current file version: 210532026/09/15 08:31:39 OK 20241026095416_initial_model.sql (95.92ms)10542026/09/15 08:31:39 OK 20241026095416_initial_model.sql (96.71ms)10552026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (2.82ms)10562026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (4.12ms)10572026-09-15 08:31:39.512 UTC [58708] ERROR: relation "goose_db_version" does not exist at character 3610582026-09-15 08:31:39.512 UTC [58708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10592026/09/15 08:31:39 OK 20251218171726_add_pins.sql (8.18ms)10602026/09/15 08:31:39 OK 20251218171726_add_pins.sql (8.21ms)10612026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (17.31ms)10622026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000010632026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (24.09ms)10642026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000010652026/09/15 08:31:39 OK 1_commit_pending_closure.sql (10.6ms)10662026/09/15 08:31:39 OK 1_commit_pending_closure.sql (3.91ms)1067--- PASS: TestReadProxyInvalidPath (1.38s)1068=== CONT TestPinProtectsFromGC10692026/09/15 08:31:39 OK 2_object_stats_trigger.sql (4.45ms)10702026/09/15 08:31:39 goose: up to current file version: 210712026/09/15 08:31:39 OK 2_object_stats_trigger.sql (4.69ms)10722026/09/15 08:31:39 goose: up to current file version: 210732026/09/15 08:31:39 OK 20241026095416_initial_model.sql (53.59ms)10742026-09-15 08:31:39.603 UTC [58711] ERROR: relation "goose_db_version" does not exist at character 3610752026-09-15 08:31:39.603 UTC [58711] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10762026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)10772026/09/15 08:31:39 OK 20251218171726_add_pins.sql (11.22ms)10782026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (23.48ms)10792026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000010802026/09/15 08:31:39 OK 1_commit_pending_closure.sql (2.21ms)10812026/09/15 08:31:39 OK 2_object_stats_trigger.sql (448.92µs)10822026/09/15 08:31:39 goose: up to current file version: 210832026/09/15 08:31:39 OK 20241026095416_initial_model.sql (77.11ms)10842026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (2.81ms)1085--- PASS: TestReadProxy404 (1.36s)1086=== CONT TestObjectStatsTrigger10872026/09/15 08:31:39 OK 20251218171726_add_pins.sql (6.73ms)10882026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (27.14ms)10892026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000010902026/09/15 08:31:39 OK 1_commit_pending_closure.sql (3.69ms)10912026/09/15 08:31:39 OK 2_object_stats_trigger.sql (451.71µs)10922026/09/15 08:31:39 goose: up to current file version: 210932026-09-15 08:31:39.778 UTC [58714] ERROR: relation "goose_db_version" does not exist at character 3610942026-09-15 08:31:39.778 UTC [58714] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10952026/09/15 08:31:39 OK 20241026095416_initial_model.sql (72.51ms)10962026/09/15 08:31:39 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)1097--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.32s)1098=== CONT TestService_healthCheckHandler10992026/09/15 08:31:39 OK 20251218171726_add_pins.sql (12.83ms)11002026/09/15 08:31:39 OK 20260628120000_add_object_size_and_stats.sql (9.22ms)11012026/09/15 08:31:39 goose: successfully migrated database to version: 2026062812000011022026/09/15 08:31:39 OK 1_commit_pending_closure.sql (7.25ms)11032026/09/15 08:31:39 OK 2_object_stats_trigger.sql (469.38µs)11042026/09/15 08:31:39 goose: up to current file version: 211052026-09-15 08:31:39.931 UTC [58717] ERROR: relation "goose_db_version" does not exist at character 3611062026-09-15 08:31:39.931 UTC [58717] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11072026/09/15 08:31:40 OK 20241026095416_initial_model.sql (104.3ms)1108--- PASS: TestReadProxyNarStreaming (1.52s)1109=== CONT TestMultipartCleanup11102026/09/15 08:31:40 OK 20251210153512_drop_unused_gin_index.sql (8.73ms)11112026/09/15 08:31:40 OK 20251218171726_add_pins.sql (17.79ms)11122026/09/15 08:31:40 OK 20260628120000_add_object_size_and_stats.sql (11.8ms)11132026/09/15 08:31:40 goose: successfully migrated database to version: 2026062812000011142026/09/15 08:31:40 OK 1_commit_pending_closure.sql (2.43ms)11152026/09/15 08:31:40 OK 2_object_stats_trigger.sql (519.83µs)11162026/09/15 08:31:40 goose: up to current file version: 211172026-09-15 08:31:40.105 UTC [58720] ERROR: relation "goose_db_version" does not exist at character 3611182026-09-15 08:31:40.105 UTC [58720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11192026/09/15 08:31:40 OK 20241026095416_initial_model.sql (69.63ms)11202026/09/15 08:31:40 OK 20251210153512_drop_unused_gin_index.sql (11.51ms)11212026/09/15 08:31:40 OK 20251218171726_add_pins.sql (4.62ms)11222026/09/15 08:31:40 OK 20260628120000_add_object_size_and_stats.sql (18.4ms)11232026/09/15 08:31:40 goose: successfully migrated database to version: 2026062812000011242026/09/15 08:31:40 OK 1_commit_pending_closure.sql (3.46ms)11252026/09/15 08:31:40 OK 2_object_stats_trigger.sql (691.29µs)11262026/09/15 08:31:40 goose: up to current file version: 211272026-09-15 08:31:40.240 UTC [58721] ERROR: relation "goose_db_version" does not exist at character 3611282026-09-15 08:31:40.240 UTC [58721] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1129--- PASS: TestResurrectedObjectNotDeleted (1.57s)1130=== CONT TestGracefulShutdownDrainsInflight11312026/09/15 08:31:40 INFO Starting HTTP server address=127.0.0.1:5727611322026/09/15 08:31:40 INFO Shutdown signal received, draining in-flight requests timeout=10s11332026/09/15 08:31:40 OK 20241026095416_initial_model.sql (54.06ms)11342026/09/15 08:31:40 OK 20251210153512_drop_unused_gin_index.sql (10.66ms)11352026/09/15 08:31:40 OK 20251218171726_add_pins.sql (7.12ms)1136--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1137=== CONT TestNARDeduplicationMetadataUploadBug11382026/09/15 08:31:40 OK 20260628120000_add_object_size_and_stats.sql (27.68ms)11392026/09/15 08:31:40 goose: successfully migrated database to version: 2026062812000011402026/09/15 08:31:40 OK 1_commit_pending_closure.sql (4.25ms)11412026/09/15 08:31:40 OK 2_object_stats_trigger.sql (1.97ms)11422026/09/15 08:31:40 goose: up to current file version: 21143--- PASS: TestReadProxyNarinfo (1.54s)1144=== CONT TestGCTaskStore_Fail1145--- PASS: TestGCTaskStore_Fail (0.00s)1146=== CONT TestService_NativeMTLS11472026-09-15 08:31:40.405 UTC [58726] ERROR: relation "goose_db_version" does not exist at character 3611482026-09-15 08:31:40.405 UTC [58726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11492026/09/15 08:31:40 OK 20241026095416_initial_model.sql (45.83ms)11502026/09/15 08:31:40 OK 20251210153512_drop_unused_gin_index.sql (8.69ms)11512026/09/15 08:31:40 OK 20251218171726_add_pins.sql (10.69ms)11522026/09/15 08:31:40 OK 20260628120000_add_object_size_and_stats.sql (27.77ms)11532026/09/15 08:31:40 goose: successfully migrated database to version: 2026062812000011542026/09/15 08:31:40 OK 1_commit_pending_closure.sql (3.41ms)11552026/09/15 08:31:40 OK 2_object_stats_trigger.sql (718.58µs)11562026/09/15 08:31:40 goose: up to current file version: 211572026-09-15 08:31:40.545 UTC [58728] ERROR: relation "goose_db_version" does not exist at character 3611582026-09-15 08:31:40.545 UTC [58728] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11592026/09/15 08:31:40 OK 20241026095416_initial_model.sql (52.12ms)11602026/09/15 08:31:40 OK 20251210153512_drop_unused_gin_index.sql (5.4ms)11612026/09/15 08:31:40 OK 20251218171726_add_pins.sql (21.81ms)11622026/09/15 08:31:40 INFO Received uploads request method=POST path=/api/pending_closures11632026/09/15 08:31:40 OK 20260628120000_add_object_size_and_stats.sql (37.9ms)11642026/09/15 08:31:40 goose: successfully migrated database to version: 2026062812000011652026/09/15 08:31:40 OK 1_commit_pending_closure.sql (4.05ms)11662026/09/15 08:31:40 OK 2_object_stats_trigger.sql (620.75µs)11672026/09/15 08:31:40 goose: up to current file version: 211682026-09-15 08:31:40.747 UTC [58729] ERROR: relation "goose_db_version" does not exist at character 3611692026-09-15 08:31:40.747 UTC [58729] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11702026/09/15 08:31:40 OK 20241026095416_initial_model.sql (106.79ms)11712026/09/15 08:31:40 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)11722026/09/15 08:31:40 OK 20251218171726_add_pins.sql (4.78ms)11732026/09/15 08:31:40 OK 20260628120000_add_object_size_and_stats.sql (26.11ms)11742026/09/15 08:31:40 goose: successfully migrated database to version: 2026062812000011752026/09/15 08:31:40 OK 1_commit_pending_closure.sql (3.06ms)11762026/09/15 08:31:40 OK 2_object_stats_trigger.sql (588µs)11772026/09/15 08:31:40 goose: up to current file version: 211782026-09-15 08:31:41.139 UTC [58731] ERROR: relation "goose_db_version" does not exist at character 3611792026-09-15 08:31:41.139 UTC [58731] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11802026-09-15 08:31:41.140 UTC [58732] ERROR: relation "goose_db_version" does not exist at character 3611812026-09-15 08:31:41.140 UTC [58732] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11822026/09/15 08:31:41 OK 20241026095416_initial_model.sql (122.95ms)11832026/09/15 08:31:41 OK 20251210153512_drop_unused_gin_index.sql (11.4ms)11842026/09/15 08:31:41 OK 20241026095416_initial_model.sql (128.76ms)11852026/09/15 08:31:41 OK 20251210153512_drop_unused_gin_index.sql (7.77ms)11862026/09/15 08:31:41 OK 20251218171726_add_pins.sql (27.58ms)11872026/09/15 08:31:41 OK 20251218171726_add_pins.sql (19.57ms)1188--- PASS: TestObjectStatsTrigger (1.62s)1189=== CONT TestGCTaskStore_PhaseUpdates1190--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1191=== CONT TestMetricsInventory11922026/09/15 08:31:41 OK 20260628120000_add_object_size_and_stats.sql (26.55ms)11932026/09/15 08:31:41 goose: successfully migrated database to version: 2026062812000011942026/09/15 08:31:41 OK 20260628120000_add_object_size_and_stats.sql (26.52ms)11952026/09/15 08:31:41 goose: successfully migrated database to version: 2026062812000011962026/09/15 08:31:41 OK 1_commit_pending_closure.sql (1.67ms)11972026/09/15 08:31:41 OK 1_commit_pending_closure.sql (1.77ms)11982026/09/15 08:31:41 OK 2_object_stats_trigger.sql (254.21µs)11992026/09/15 08:31:41 goose: up to current file version: 212002026/09/15 08:31:41 OK 2_object_stats_trigger.sql (307.83µs)12012026/09/15 08:31:41 goose: up to current file version: 21202=== NAME TestOrphanedObjectsGC1203 orphaned_objects_gc_test.go:290: GC Test Summary:1204 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1205 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1206 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1207 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1208 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1209--- PASS: TestOrphanedObjectsGC (2.04s)1210=== CONT TestGCTaskStore_CompletedAllowsNewTask1211--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1212=== CONT TestGCTaskStore_GetReturnsLatest1213--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1214=== CONT TestGCTaskStore_GetEmpty1215--- PASS: TestGCTaskStore_GetEmpty (0.00s)1216=== CONT TestGCTaskStore_ConflictDifferentParams1217--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1218=== CONT TestGCTaskStore_DeduplicateSameParams1219--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1220=== CONT TestGCTaskStore_StartNew1221--- PASS: TestGCTaskStore_StartNew (0.00s)1222=== CONT TestGCMetrics1223=== NAME TestPinProtectsFromGC1224 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-58445-3431720553/TestPinProtectsFromGC3936248091/001/store/sa2xj8mhc7ryv2sxg6jswvwwnhihkmk9-pinned-file.txt1225 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-58445-3431720553/TestPinProtectsFromGC3936248091/001/store/k4m35c1hkfb2lvakfmh5yr3qx4flwfxx-unpinned-file.txt12262026/09/15 08:31:41 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12272026/09/15 08:31:41 INFO Received uploads request method=POST path=/api/pending_closures1228--- PASS: TestService_healthCheckHandler (1.68s)1229=== CONT TestCacheConfigHandler1230=== RUN TestCacheConfigHandler/full_config,_no_issuer1231=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1232=== RUN TestCacheConfigHandler/no_cache_url_configured1233=== PAUSE TestCacheConfigHandler/no_cache_url_configured1234=== RUN TestCacheConfigHandler/no_signing_keys1235=== PAUSE TestCacheConfigHandler/no_signing_keys1236=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1237=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1238=== CONT TestGCBugBareHashReferences12392026/09/15 08:31:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12402026/09/15 08:31:41 INFO Uploading sa2xj8mhc7ryv2sxg6jswvwwnhihkmk9-pinned-file.txt (128B)12412026/09/15 08:31:41 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12422026/09/15 08:31:41 WARN Failed to register uploaded object key=sa2xj8mhc7ryv2sxg6jswvwwnhihkmk9.ls error="server returned 404: 404 page not found\n"12432026/09/15 08:31:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12442026/09/15 08:31:41 INFO Signed narinfos id=1 count=112452026/09/15 08:31:41 INFO Uploading 1 narinfos12462026/09/15 08:31:41 WARN Failed to register uploaded object key=sa2xj8mhc7ryv2sxg6jswvwwnhihkmk9.narinfo error="server returned 404: 404 page not found\n"12472026/09/15 08:31:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12482026/09/15 08:31:41 INFO Completed upload id=112492026/09/15 08:31:41 INFO Upload complete. (199ms)12502026/09/15 08:31:41 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12512026/09/15 08:31:41 INFO Received uploads request method=POST path=/api/pending_closures12522026/09/15 08:31:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12532026/09/15 08:31:41 INFO Uploading k4m35c1hkfb2lvakfmh5yr3qx4flwfxx-unpinned-file.txt (128B)12542026/09/15 08:31:41 INFO Received uploads request method=POST path=/api/pending_closures12552026/09/15 08:31:41 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12562026/09/15 08:31:41 WARN Failed to register uploaded object key=k4m35c1hkfb2lvakfmh5yr3qx4flwfxx.ls error="server returned 404: 404 page not found\n"12572026/09/15 08:31:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12582026/09/15 08:31:41 INFO Signed narinfos id=2 count=112592026/09/15 08:31:41 INFO Uploading 1 narinfos12602026/09/15 08:31:41 WARN Failed to register uploaded object key=k4m35c1hkfb2lvakfmh5yr3qx4flwfxx.narinfo error="server returned 404: 404 page not found\n"12612026/09/15 08:31:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12622026/09/15 08:31:41 INFO Completed upload id=212632026/09/15 08:31:41 INFO Upload complete. (163ms)12642026/09/15 08:31:41 INFO Received create pin request method=POST path=/api/pins/myapp12652026/09/15 08:31:41 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-58445-3431720553/TestPinProtectsFromGC3936248091/001/store/sa2xj8mhc7ryv2sxg6jswvwwnhihkmk9-pinned-file.txt narinfo_key=sa2xj8mhc7ryv2sxg6jswvwwnhihkmk9.narinfo12662026/09/15 08:31:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures12672026/09/15 08:31:41 INFO Garbage collection started12682026/09/15 08:31:41 INFO Aborted multipart uploads count=012692026/09/15 08:31:41 WARN Force mode enabled - objects will be deleted immediately without grace period12702026/09/15 08:31:41 INFO Received cleanup request method=DELETE path=/api/pending_closures12712026/09/15 08:31:41 INFO Aborted multipart uploads count=112722026/09/15 08:31:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1273--- PASS: TestMultipartCleanup (1.93s)1274=== CONT TestClientWithDependencies12752026/09/15 08:31:42 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZGRkYzBkZWEtZjZjMS00ZjQ2LTk1ZGEtNzFmZjkzMzNkNzhjLjNhNzVlOTY4LTJmNzItNGQxNi04MmVhLTU3ZDVmZjFlMTM4MXgxNzg5NDYxMTAwNzAzMjAwMDAw parts=1212762026/09/15 08:31:42 INFO Received uploads request method=POST path=/api/pending_closures1277--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.88s)1278=== CONT TestResolveDBConnectionString1279=== RUN TestResolveDBConnectionString/flag_wins1280=== PAUSE TestResolveDBConnectionString/flag_wins1281=== RUN TestResolveDBConnectionString/file_when_flag_empty1282=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1283=== RUN TestResolveDBConnectionString/missing_file_is_an_error1284=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1285=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1286=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1287=== RUN TestResolveDBConnectionString/nothing_configured1288=== PAUSE TestResolveDBConnectionString/nothing_configured1289=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12902026/09/15 08:31:42 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12912026/09/15 08:31:42 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1292--- PASS: TestService_NativeMTLS (1.70s)1293=== CONT TestCacheConfigHandlerMaxNarSize1294--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1295=== CONT TestClientMultipleUploads12962026/09/15 08:31:42 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=012972026/09/15 08:31:42 INFO Vacuumed table table=pending_closures12982026/09/15 08:31:42 INFO Vacuumed table table=pending_objects12992026/09/15 08:31:42 WARN Rate limiter enabled after throttle name=s3-test rate=513002026/09/15 08:31:42 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1301=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1302 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101303 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001304--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.72s)1305=== CONT TestCreatePendingClosureRejectsOversizedNAR13062026/09/15 08:31:42 INFO Received uploads request method=POST path=/api/pending_closures1307--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1308=== CONT TestClientIntegration13092026/09/15 08:31:42 INFO Vacuumed table table=multipart_uploads13102026/09/15 08:31:42 INFO Vacuumed table table=closures13112026/09/15 08:31:42 INFO Vacuumed table table=objects1312=== NAME TestNARDeduplicationMetadataUploadBug1313 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-58445-3431720553/TestNARDeduplicationMetadataUploadBug3774647610/001/store/4mq16vmgx47x7i8yiw5k4zgh9d9ii39i-file1.txt13142026-09-15 08:31:42.500 UTC [58771] ERROR: relation "goose_db_version" does not exist at character 3613152026-09-15 08:31:42.500 UTC [58771] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13162026-09-15 08:31:42.513 UTC [58772] ERROR: relation "goose_db_version" does not exist at character 3613172026-09-15 08:31:42.513 UTC [58772] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13182026/09/15 08:31:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13192026/09/15 08:31:42 INFO Received uploads request method=POST path=/api/pending_closures13202026/09/15 08:31:42 OK 20241026095416_initial_model.sql (44.5ms)13212026/09/15 08:31:42 OK 20251210153512_drop_unused_gin_index.sql (469.92µs)13222026/09/15 08:31:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13232026/09/15 08:31:42 INFO Uploading 4mq16vmgx47x7i8yiw5k4zgh9d9ii39i-file1.txt (160B)13242026/09/15 08:31:42 OK 20251218171726_add_pins.sql (2.44ms)13252026/09/15 08:31:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13262026/09/15 08:31:42 OK 20241026095416_initial_model.sql (39.1ms)13272026/09/15 08:31:42 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)13282026/09/15 08:31:42 WARN Failed to register uploaded object key=4mq16vmgx47x7i8yiw5k4zgh9d9ii39i.ls error="server returned 404: 404 page not found\n"13292026/09/15 08:31:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13302026/09/15 08:31:42 INFO Signed narinfos id=1 count=113312026/09/15 08:31:42 INFO Uploading 1 narinfos13322026/09/15 08:31:42 WARN Failed to register uploaded object key=4mq16vmgx47x7i8yiw5k4zgh9d9ii39i.narinfo error="server returned 404: 404 page not found\n"13332026/09/15 08:31:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13342026/09/15 08:31:42 OK 20251218171726_add_pins.sql (16.15ms)13352026/09/15 08:31:42 OK 20260628120000_add_object_size_and_stats.sql (25.2ms)13362026/09/15 08:31:42 goose: successfully migrated database to version: 2026062812000013372026/09/15 08:31:42 INFO Completed upload id=113382026/09/15 08:31:42 INFO Upload complete. (124ms)1339 metadata_upload_test.go:54: Retrieved narinfo from S3:1340 StorePath: /nix/var/nix/builds/nix-58445-3431720553/TestNARDeduplicationMetadataUploadBug3774647610/001/store/4mq16vmgx47x7i8yiw5k4zgh9d9ii39i-file1.txt1341 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1342 Compression: zstd1343 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1344 NarSize: 1601345 References: 1346 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13472026/09/15 08:31:42 OK 1_commit_pending_closure.sql (2.44ms)1348 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1349 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1350 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13512026/09/15 08:31:42 OK 2_object_stats_trigger.sql (232.46µs)13522026/09/15 08:31:42 goose: up to current file version: 213532026/09/15 08:31:42 OK 20260628120000_add_object_size_and_stats.sql (21.51ms)13542026/09/15 08:31:42 goose: successfully migrated database to version: 2026062812000013552026/09/15 08:31:42 OK 1_commit_pending_closure.sql (5.91ms)13562026/09/15 08:31:42 OK 2_object_stats_trigger.sql (234.71µs)13572026/09/15 08:31:42 goose: up to current file version: 21358 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-58445-3431720553/TestNARDeduplicationMetadataUploadBug3774647610/001/store/ngz43yk1b07ws5mcc3rdd5npx1g3m3jq-file2.txt13592026-09-15 08:31:42.713 UTC [58779] ERROR: relation "goose_db_version" does not exist at character 3613602026-09-15 08:31:42.713 UTC [58779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13612026/09/15 08:31:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13622026/09/15 08:31:42 INFO Received uploads request method=POST path=/api/pending_closures13632026/09/15 08:31:42 OK 20241026095416_initial_model.sql (59.15ms)13642026/09/15 08:31:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13652026/09/15 08:31:42 OK 20251210153512_drop_unused_gin_index.sql (3.56ms)13662026/09/15 08:31:42 WARN Failed to register uploaded object key=ngz43yk1b07ws5mcc3rdd5npx1g3m3jq.ls error="server returned 404: 404 page not found\n"13672026/09/15 08:31:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13682026/09/15 08:31:42 INFO Signed narinfos id=2 count=113692026/09/15 08:31:42 INFO Uploading 1 narinfos1370--- PASS: TestMetricsInventory (1.47s)1371=== CONT TestGenerateLandingPage1372--- PASS: TestGenerateLandingPage (0.00s)1373=== CONT TestClientErrorHandling1374=== RUN TestClientErrorHandling/InvalidStorePath1375=== PAUSE TestClientErrorHandling/InvalidStorePath1376=== RUN TestClientErrorHandling/InvalidAuthToken1377=== PAUSE TestClientErrorHandling/InvalidAuthToken1378=== RUN TestClientErrorHandling/ServerNotAvailable1379=== PAUSE TestClientErrorHandling/ServerNotAvailable1380=== CONT TestService_ReadAuthMiddleware13812026/09/15 08:31:42 WARN Failed to register uploaded object key=ngz43yk1b07ws5mcc3rdd5npx1g3m3jq.narinfo error="server returned 404: 404 page not found\n"13822026/09/15 08:31:42 OK 20251218171726_add_pins.sql (14.37ms)13832026/09/15 08:31:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13842026/09/15 08:31:42 INFO Completed upload id=213852026/09/15 08:31:42 INFO Upload complete. (103ms)1386=== NAME TestNARDeduplicationMetadataUploadBug1387 metadata_upload_test.go:76: Retrieved narinfo from S3:1388 StorePath: /nix/var/nix/builds/nix-58445-3431720553/TestNARDeduplicationMetadataUploadBug3774647610/001/store/ngz43yk1b07ws5mcc3rdd5npx1g3m3jq-file2.txt1389 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1390 Compression: zstd1391 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1392 NarSize: 1601393 References: 1394 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1395 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1396 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1397 {"version":1,"root":{"type":"regular","size":44}}1398--- PASS: TestNARDeduplicationMetadataUploadBug (2.49s)1399=== CONT TestClientCADerivations14002026/09/15 08:31:42 OK 20260628120000_add_object_size_and_stats.sql (16.7ms)14012026/09/15 08:31:42 goose: successfully migrated database to version: 2026062812000014022026/09/15 08:31:42 OK 1_commit_pending_closure.sql (6.24ms)14032026/09/15 08:31:42 OK 2_object_stats_trigger.sql (278.17µs)14042026/09/15 08:31:42 goose: up to current file version: 214052026-09-15 08:31:42.879 UTC [58789] ERROR: relation "goose_db_version" does not exist at character 3614062026-09-15 08:31:42.879 UTC [58789] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14072026-09-15 08:31:42.923 UTC [58790] ERROR: relation "goose_db_version" does not exist at character 3614082026-09-15 08:31:42.923 UTC [58790] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14092026-09-15 08:31:42.961 UTC [58791] ERROR: relation "goose_db_version" does not exist at character 3614102026-09-15 08:31:42.961 UTC [58791] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14112026/09/15 08:31:42 OK 20241026095416_initial_model.sql (64.05ms)14122026/09/15 08:31:42 OK 20251210153512_drop_unused_gin_index.sql (5.82ms)14132026/09/15 08:31:42 OK 20251218171726_add_pins.sql (16.66ms)14142026/09/15 08:31:43 INFO Aborted multipart uploads count=014152026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (16.22ms)14162026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000014172026/09/15 08:31:43 WARN Force mode enabled - objects will be deleted immediately without grace period14182026/09/15 08:31:43 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=014192026/09/15 08:31:43 OK 1_commit_pending_closure.sql (8.96ms)14202026/09/15 08:31:43 INFO Vacuumed table table=pending_closures14212026/09/15 08:31:43 OK 2_object_stats_trigger.sql (381.25µs)14222026/09/15 08:31:43 goose: up to current file version: 214232026/09/15 08:31:43 INFO Vacuumed table table=pending_objects14242026/09/15 08:31:43 INFO Vacuumed table table=multipart_uploads14252026/09/15 08:31:43 INFO Vacuumed table table=closures14262026/09/15 08:31:43 INFO Vacuumed table table=objects1427--- PASS: TestGCMetrics (1.62s)1428=== CONT TestService_ReadScope_PublicByDefault14292026/09/15 08:31:43 OK 20241026095416_initial_model.sql (73.42ms)14302026/09/15 08:31:43 OK 20251210153512_drop_unused_gin_index.sql (839.96µs)14312026/09/15 08:31:43 OK 20251218171726_add_pins.sql (14.84ms)14322026-09-15 08:31:43.049 UTC [58794] ERROR: relation "goose_db_version" does not exist at character 3614332026-09-15 08:31:43.049 UTC [58794] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14342026/09/15 08:31:43 OK 20241026095416_initial_model.sql (58.39ms)14352026/09/15 08:31:43 OK 20251210153512_drop_unused_gin_index.sql (6.42ms)14362026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (13.12ms)14372026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000014382026/09/15 08:31:43 OK 20251218171726_add_pins.sql (6.05ms)14392026/09/15 08:31:43 OK 1_commit_pending_closure.sql (1.4ms)14402026/09/15 08:31:43 OK 2_object_stats_trigger.sql (275.96µs)14412026/09/15 08:31:43 goose: up to current file version: 214422026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (13.9ms)14432026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000014442026/09/15 08:31:43 OK 1_commit_pending_closure.sql (5.15ms)14452026/09/15 08:31:43 OK 2_object_stats_trigger.sql (269.58µs)14462026/09/15 08:31:43 goose: up to current file version: 214472026/09/15 08:31:43 OK 20241026095416_initial_model.sql (51.58ms)14482026/09/15 08:31:43 OK 20251210153512_drop_unused_gin_index.sql (6.16ms)14492026/09/15 08:31:43 OK 20251218171726_add_pins.sql (14.54ms)14502026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (11.43ms)14512026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000014522026/09/15 08:31:43 OK 1_commit_pending_closure.sql (2.17ms)14532026/09/15 08:31:43 OK 2_object_stats_trigger.sql (454.92µs)14542026/09/15 08:31:43 goose: up to current file version: 21455--- PASS: TestGCBugBareHashReferences (1.80s)1456=== CONT TestCacheStatsHandler14572026-09-15 08:31:43.510 UTC [58805] ERROR: relation "goose_db_version" does not exist at character 3614582026-09-15 08:31:43.510 UTC [58805] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14592026-09-15 08:31:43.515 UTC [58806] ERROR: relation "goose_db_version" does not exist at character 3614602026-09-15 08:31:43.515 UTC [58806] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1461=== NAME TestClientMultipleUploads1462 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-58445-3431720553/TestClientMultipleUploads4284794629/001/store/2qm3fvzv2bi7zh2a0z0c243krn4xjnkd-test-file-0.txt1463=== NAME TestOrphanedObjectsGCStressTest1464 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1465 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion14662026/09/15 08:31:43 OK 20241026095416_initial_model.sql (56.83ms)14672026/09/15 08:31:43 OK 20241026095416_initial_model.sql (57.46ms)14682026/09/15 08:31:43 OK 20251210153512_drop_unused_gin_index.sql (5.32ms)14692026/09/15 08:31:43 OK 20251210153512_drop_unused_gin_index.sql (7.67ms)14702026/09/15 08:31:43 OK 20251218171726_add_pins.sql (16.67ms)14712026/09/15 08:31:43 OK 20251218171726_add_pins.sql (24.29ms)1472=== NAME TestClientMultipleUploads1473 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-58445-3431720553/TestClientMultipleUploads4284794629/001/store/6iy7k9ja3xngmi8p6c9vd7jwixbdniiy-test-file-1.txt14742026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (16.06ms)14752026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000014762026/09/15 08:31:43 INFO Received uploads request method=POST path=/api/pending_closures14772026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (23.46ms)14782026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000014792026/09/15 08:31:43 OK 1_commit_pending_closure.sql (7.44ms)14802026/09/15 08:31:43 OK 2_object_stats_trigger.sql (241.42µs)14812026/09/15 08:31:43 goose: up to current file version: 214822026/09/15 08:31:43 OK 1_commit_pending_closure.sql (7.79ms)14832026/09/15 08:31:43 OK 2_object_stats_trigger.sql (258.88µs)14842026/09/15 08:31:43 goose: up to current file version: 21485=== NAME TestClientWithDependencies1486 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-58445-3431720553/TestClientWithDependencies4212694349/001/store/9s4cryhb7fv8yzy7kfnlbls1p9752875-test-script1487=== NAME TestClientMultipleUploads1488 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-58445-3431720553/TestClientMultipleUploads4284794629/001/store/jgbjmzhxax7ixi4lafk0a5xh0ms79kjb-test-file-2.txt1489=== NAME TestClientWithDependencies1490 client_integration_test.go:596: Found 1 dependencies (including self)14912026/09/15 08:31:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14922026/09/15 08:31:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14932026/09/15 08:31:43 INFO Received uploads request method=POST path=/api/pending_closures14942026/09/15 08:31:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14952026/09/15 08:31:43 INFO Uploading 9s4cryhb7fv8yzy7kfnlbls1p9752875-test-script (136B)14962026/09/15 08:31:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14972026/09/15 08:31:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14982026/09/15 08:31:43 WARN Failed to register uploaded object key=log/0hwj1pkbg9z5c63ij5c0agwy1hbb6rq7-test-script.drv error="server returned 404: 404 page not found\n"14992026/09/15 08:31:43 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGRkYzBkZWEtZjZjMS00ZjQ2LTk1ZGEtNzFmZjkzMzNkNzhjLmJhOTVkMDdjLWI3NmMtNDNiYi1hZGE4LTM4YzMyYmIwMjkwYXgxNzg5NDYxMTAzNjU5OTE0MDAw15002026-09-15 08:31:43.813 UTC [58823] ERROR: relation "goose_db_version" does not exist at character 3615012026-09-15 08:31:43.813 UTC [58823] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15022026/09/15 08:31:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGRkYzBkZWEtZjZjMS00ZjQ2LTk1ZGEtNzFmZjkzMzNkNzhjLmJhOTVkMDdjLWI3NmMtNDNiYi1hZGE4LTM4YzMyYmIwMjkwYXgxNzg5NDYxMTAzNjU5OTE0MDAw parts=11503--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.76s)1504=== CONT TestService_RequireScope_OIDC15052026/09/15 08:31:43 INFO Received uploads request method=POST path=/api/pending_closures15062026/09/15 08:31:43 WARN Failed to register uploaded object key=9s4cryhb7fv8yzy7kfnlbls1p9752875.ls error="server returned 404: 404 page not found\n"15072026/09/15 08:31:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57331/oidc15082026/09/15 08:31:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15092026/09/15 08:31:43 INFO Signed narinfos id=1 count=115102026/09/15 08:31:43 INFO Uploading 1 narinfos15112026/09/15 08:31:43 INFO Received uploads request method=POST path=/api/pending_closures15122026/09/15 08:31:43 INFO Received uploads request method=POST path=/api/pending_closures15132026/09/15 08:31:43 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15142026/09/15 08:31:43 INFO Uploading jgbjmzhxax7ixi4lafk0a5xh0ms79kjb-test-file-2.txt (160B)15152026/09/15 08:31:43 INFO Uploading 2qm3fvzv2bi7zh2a0z0c243krn4xjnkd-test-file-0.txt (160B)15162026/09/15 08:31:43 INFO Uploading 6iy7k9ja3xngmi8p6c9vd7jwixbdniiy-test-file-1.txt (160B)15172026/09/15 08:31:43 WARN Failed to register uploaded object key=9s4cryhb7fv8yzy7kfnlbls1p9752875.narinfo error="server returned 404: 404 page not found\n"15182026/09/15 08:31:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15192026/09/15 08:31:43 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15202026/09/15 08:31:43 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15212026/09/15 08:31:43 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15222026/09/15 08:31:43 INFO Completed upload id=115232026/09/15 08:31:43 INFO Upload complete. (125ms)1524=== NAME TestClientWithDependencies1525 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-58445-3431720553/TestClientWithDependencies4212694349/001/store) requires matching store prefix15262026/09/15 08:31:43 WARN Failed to register uploaded object key=6iy7k9ja3xngmi8p6c9vd7jwixbdniiy.ls error="server returned 404: 404 page not found\n"15272026/09/15 08:31:43 WARN Failed to register uploaded object key=2qm3fvzv2bi7zh2a0z0c243krn4xjnkd.ls error="server returned 404: 404 page not found\n"15282026/09/15 08:31:43 WARN Failed to register uploaded object key=jgbjmzhxax7ixi4lafk0a5xh0ms79kjb.ls error="server returned 404: 404 page not found\n"15292026/09/15 08:31:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15302026/09/15 08:31:43 INFO Signed narinfos id=1 count=115312026/09/15 08:31:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15322026/09/15 08:31:43 INFO Signed narinfos id=2 count=115332026/09/15 08:31:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15342026/09/15 08:31:43 INFO Signed narinfos id=3 count=115352026/09/15 08:31:43 INFO Uploading 3 narinfos15362026/09/15 08:31:43 WARN Failed to register uploaded object key=2qm3fvzv2bi7zh2a0z0c243krn4xjnkd.narinfo error="server returned 404: 404 page not found\n"15372026/09/15 08:31:43 WARN Failed to register uploaded object key=jgbjmzhxax7ixi4lafk0a5xh0ms79kjb.narinfo error="server returned 404: 404 page not found\n"15382026/09/15 08:31:43 WARN Failed to register uploaded object key=6iy7k9ja3xngmi8p6c9vd7jwixbdniiy.narinfo error="server returned 404: 404 page not found\n"15392026/09/15 08:31:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15402026/09/15 08:31:43 INFO Completed upload id=115412026/09/15 08:31:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15422026/09/15 08:31:43 INFO Completed upload id=215432026/09/15 08:31:43 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15442026/09/15 08:31:43 INFO Completed upload id=315452026/09/15 08:31:43 INFO Upload complete. (172ms)1546=== NAME TestClientMultipleUploads1547 client_integration_test.go:350: Uploaded 3 paths in 203.153125ms1548--- PASS: TestClientWithDependencies (1.90s)1549=== CONT TestService_AuthMiddleware_OIDC15502026/09/15 08:31:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01551=== NAME TestPinProtectsFromGC1552 client_integration_test.go:711: Pin successfully protected closure from garbage collection15532026/09/15 08:31:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57344/oidc1554--- PASS: TestClientMultipleUploads (1.86s)1555=== CONT TestService_AuthMiddleware_MTLSProxyHeader15562026/09/15 08:31:43 OK 20241026095416_initial_model.sql (89.86ms)1557--- PASS: TestPinProtectsFromGC (4.40s)1558=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15592026/09/15 08:31:43 OK 20251210153512_drop_unused_gin_index.sql (13.39ms)15602026/09/15 08:31:43 OK 20251218171726_add_pins.sql (16.72ms)15612026/09/15 08:31:43 OK 20260628120000_add_object_size_and_stats.sql (21.04ms)15622026/09/15 08:31:43 goose: successfully migrated database to version: 2026062812000015632026/09/15 08:31:43 OK 1_commit_pending_closure.sql (1.68ms)15642026/09/15 08:31:43 OK 2_object_stats_trigger.sql (233.38µs)15652026/09/15 08:31:43 goose: up to current file version: 21566=== NAME TestClientIntegration1567 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-58445-3431720553/TestClientIntegration1581640174/002/store/q9v8apfl01rgmx8mqifx76li57x4l3kn-test-file.txt15682026/09/15 08:31:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15692026/09/15 08:31:44 INFO Received uploads request method=POST path=/api/pending_closures15702026/09/15 08:31:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15712026/09/15 08:31:44 INFO Uploading q9v8apfl01rgmx8mqifx76li57x4l3kn-test-file.txt (152B)15722026/09/15 08:31:44 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15732026-09-15 08:31:44.214 UTC [58842] ERROR: relation "goose_db_version" does not exist at character 3615742026-09-15 08:31:44.214 UTC [58842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15752026/09/15 08:31:44 WARN Failed to register uploaded object key=q9v8apfl01rgmx8mqifx76li57x4l3kn.ls error="server returned 404: 404 page not found\n"15762026/09/15 08:31:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15772026/09/15 08:31:44 INFO Signed narinfos id=1 count=115782026/09/15 08:31:44 INFO Uploading 1 narinfos15792026/09/15 08:31:44 WARN Failed to register uploaded object key=q9v8apfl01rgmx8mqifx76li57x4l3kn.narinfo error="server returned 404: 404 page not found\n"15802026/09/15 08:31:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15812026/09/15 08:31:44 INFO Completed upload id=115822026/09/15 08:31:44 INFO Upload complete. (206ms)1583--- PASS: TestService_ReadAuthMiddleware (1.44s)1584=== CONT TestIsValidUploadKey/narinfo1585=== CONT TestIsValidUploadKey/realisation_plus_in_output1586=== CONT TestIsValidUploadKey/realisation1587=== CONT TestIsValidUploadKey/nix-cache-info1588=== CONT TestIsValidUploadKey/build_log_equals1589=== CONT TestIsValidUploadKey/build_log_question_mark1590=== CONT TestIsValidUploadKey/build_log_plus_in_name1591=== CONT TestIsValidUploadKey/build_log_home-manager_file1592=== CONT TestIsValidUploadKey/build_log1593=== CONT TestIsValidUploadKey/listing1594=== CONT TestIsValidUploadKey/nar_plain1595=== CONT TestIsValidUploadKey/nar_xz1596=== CONT TestIsValidUploadKey/nar_zst1597=== CONT TestIsValidUploadKey/traversal1598=== CONT TestIsValidUploadKey/unknown_type1599=== CONT TestIsValidUploadKey/empty_key1600=== CONT TestIsValidUploadKey/absolute1601=== CONT TestIsValidUploadKey/traversal_nar1602=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1603=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1604=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1605=== CONT TestIsValidUploadKey/index.html1606--- PASS: TestIsValidUploadKey (0.00s)1607 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1608 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1609 --- PASS: TestIsValidUploadKey/realisation (0.00s)1610 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1611 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1612 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1613 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1614 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1615 --- PASS: TestIsValidUploadKey/build_log (0.00s)1616 --- PASS: TestIsValidUploadKey/listing (0.00s)1617 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1618 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1619 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1620 --- PASS: TestIsValidUploadKey/traversal (0.00s)1621 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1622 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1623 --- PASS: TestIsValidUploadKey/absolute (0.00s)1624 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1625 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1626 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1627 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1628 --- PASS: TestIsValidUploadKey/index.html (0.00s)1629=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16302026/09/15 08:31:44 INFO Received uploads request method=POST path=/1631=== NAME TestClientIntegration1632 client_integration_test.go:293: Retrieved narinfo from S3:1633 StorePath: /nix/var/nix/builds/nix-58445-3431720553/TestClientIntegration1581640174/002/store/q9v8apfl01rgmx8mqifx76li57x4l3kn-test-file.txt1634 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1635 Compression: zstd1636 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11637 NarSize: 1521638 References: 1639 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11640 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1641 client_integration_test.go:294: Decompressed .ls content (64 bytes):1642 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1643 client_integration_test.go:297: Testing garbage collection...16442026/09/15 08:31:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures16452026/09/15 08:31:44 INFO Garbage collection started16462026/09/15 08:31:44 INFO Aborted multipart uploads count=016472026/09/15 08:31:44 WARN Force mode enabled - objects will be deleted immediately without grace period16482026/09/15 08:31:44 OK 20241026095416_initial_model.sql (87.66ms)16492026/09/15 08:31:44 OK 20251210153512_drop_unused_gin_index.sql (5.42ms)16502026/09/15 08:31:44 OK 20251218171726_add_pins.sql (43.44ms)16512026/09/15 08:31:44 OK 20260628120000_add_object_size_and_stats.sql (15.77ms)16522026/09/15 08:31:44 goose: successfully migrated database to version: 2026062812000016532026/09/15 08:31:44 OK 1_commit_pending_closure.sql (7.1ms)16542026/09/15 08:31:44 OK 2_object_stats_trigger.sql (220.42µs)16552026/09/15 08:31:44 goose: up to current file version: 21656=== NAME TestClientCADerivations1657 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-58445-3431720553/TestClientCADerivations1030825761/001/store/4a6gyvsx7ylnp5qqfi7aj8i34qfh6hhm-ca-test1658--- PASS: TestService_ReadScope_PublicByDefault (1.43s)1659=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16602026/09/15 08:31:44 INFO Received complete multipart upload request method=POST path=/1661=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16622026/09/15 08:31:44 INFO Received request for more parts method=POST path=/1663=== NAME TestClientCADerivations1664 client_ca_test.go:139: Found 1 dependencies (including self)1665=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16662026/09/15 08:31:44 INFO Received uploads request method=POST path=/1667=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16682026/09/15 08:31:44 INFO Received complete multipart upload request method=POST path=/1669=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16702026/09/15 08:31:44 INFO Received request for more parts method=POST path=/1671=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16722026/09/15 08:31:44 INFO Received uploads request method=POST path=/1673--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1674 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1675 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1676 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1677 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1678=== CONT TestIsValidCachePath/narinfo1679=== CONT TestIsValidCachePath/index.html1680=== CONT TestIsValidCachePath/short_hash1681=== CONT TestIsValidCachePath/wrong_extension1682=== CONT TestIsValidCachePath/leading_slash1683=== CONT TestIsValidCachePath/empty1684=== CONT TestIsValidCachePath/random_path1685=== CONT TestIsValidCachePath/invalid_char_u1686=== CONT TestIsValidCachePath/invalid_char_e1687=== CONT TestIsValidCachePath/traversal_in_middle1688=== CONT TestIsValidCachePath/traversal_parent1689=== CONT TestIsValidCachePath/nar_uncompressed1690=== CONT TestIsValidCachePath/realisation1691=== CONT TestIsValidCachePath/nix-cache-info1692=== CONT TestIsValidCachePath/ls1693=== CONT TestIsValidCachePath/nar_xz1694=== CONT TestIsValidCachePath/nar_bz21695=== CONT TestIsValidCachePath/nar_zst1696=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1697=== CONT TestIsValidCachePath/log1698=== CONT TestServerTLSConfig/no_client_CA1699=== CONT TestServerTLSConfig/not_a_PEM_file1700--- PASS: TestIsValidCachePath (0.00s)1701 --- PASS: TestIsValidCachePath/narinfo (0.00s)1702 --- PASS: TestIsValidCachePath/index.html (0.00s)1703 --- PASS: TestIsValidCachePath/short_hash (0.00s)1704 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1705 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1706 --- PASS: TestIsValidCachePath/empty (0.00s)1707 --- PASS: TestIsValidCachePath/random_path (0.00s)1708 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1709 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1710 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1711 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1712 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1713 --- PASS: TestIsValidCachePath/realisation (0.00s)1714 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1715 --- PASS: TestIsValidCachePath/ls (0.00s)1716 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1717 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1718 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1719 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1720 --- PASS: TestIsValidCachePath/log (0.00s)1721=== CONT TestServerTLSConfig/missing_CA_file1722--- PASS: TestServerTLSConfig (0.00s)1723 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1724 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1725 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1726=== CONT TestParseSingleRange/none1727=== CONT TestParseSingleRange/open-ended1728=== CONT TestParseSingleRange/start_far_past_EOF1729=== CONT TestParseSingleRange/start_past_EOF1730=== CONT TestParseSingleRange/single_byte1731=== CONT TestParseSingleRange/suffix_exceeds_size1732=== CONT TestParseSingleRange/suffix1733=== CONT TestParseSingleRange/end_clamped_to_size1734=== CONT TestParseSingleRange/malformed_both_empty1735=== CONT TestParseSingleRange/closed1736=== CONT TestParseSingleRange/malformed_end_before_start1737=== CONT TestParseSingleRange/multi-range_ignored1738=== CONT TestParseSingleRange/malformed_no_dash1739=== CONT TestParseSingleRange/unknown_unit1740--- PASS: TestParseSingleRange (0.00s)1741 --- PASS: TestParseSingleRange/none (0.00s)1742 --- PASS: TestParseSingleRange/open-ended (0.00s)1743 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1744 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1745 --- PASS: TestParseSingleRange/single_byte (0.00s)1746 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1747 --- PASS: TestParseSingleRange/suffix (0.00s)1748 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1749 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1750 --- PASS: TestParseSingleRange/closed (0.00s)1751 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1752 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1753 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1754 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1755=== CONT TestCacheConfigHandler/full_config,_no_issuer1756=== CONT TestCacheConfigHandler/no_signing_keys1757=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1758=== CONT TestCacheConfigHandler/no_cache_url_configured1759--- PASS: TestCacheConfigHandler (0.00s)1760 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1761 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1762 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1763 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1764=== CONT TestResolveDBConnectionString/flag_wins1765=== CONT TestResolveDBConnectionString/missing_file_is_an_error1766=== CONT TestResolveDBConnectionString/file_when_flag_empty1767=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1768=== CONT TestResolveDBConnectionString/nothing_configured1769=== CONT TestClientErrorHandling/InvalidStorePath1770--- PASS: TestResolveDBConnectionString (0.01s)1771 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1772 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1773 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1774 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1775 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)17762026/09/15 08:31:44 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=01777--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1778 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1779 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1780 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1781=== CONT TestClientErrorHandling/ServerNotAvailable17822026/09/15 08:31:44 INFO Vacuumed table table=pending_closures17832026/09/15 08:31:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17842026/09/15 08:31:44 INFO Vacuumed table table=pending_objects17852026/09/15 08:31:44 INFO Vacuumed table table=multipart_uploads17862026/09/15 08:31:44 INFO Vacuumed table table=closures17872026/09/15 08:31:44 INFO Received uploads request method=POST path=/api/pending_closures17882026/09/15 08:31:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17892026/09/15 08:31:44 INFO Uploading 4a6gyvsx7ylnp5qqfi7aj8i34qfh6hhm-ca-test (144B)17902026/09/15 08:31:44 INFO Vacuumed table table=objects17912026/09/15 08:31:44 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17922026/09/15 08:31:44 WARN Failed to register uploaded object key=4a6gyvsx7ylnp5qqfi7aj8i34qfh6hhm.ls error="server returned 404: 404 page not found\n"17932026/09/15 08:31:44 WARN Failed to register uploaded object key=log/x6a22711vz25bpm25q88ph2qhdjflw86-ca-test.drv error="server returned 404: 404 page not found\n"17942026/09/15 08:31:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17952026/09/15 08:31:44 INFO Signed narinfos id=1 count=117962026/09/15 08:31:44 INFO Uploading 1 narinfos17972026/09/15 08:31:44 WARN Failed to register uploaded object key=4a6gyvsx7ylnp5qqfi7aj8i34qfh6hhm.narinfo error="server returned 404: 404 page not found\n"17982026/09/15 08:31:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17992026/09/15 08:31:44 INFO Completed upload id=118002026/09/15 08:31:44 INFO Upload complete. (180ms)1801=== NAME TestClientCADerivations1802 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-58445-3431720553/TestClientCADerivations1030825761/001/store/4a6gyvsx7ylnp5qqfi7aj8i34qfh6hhm-ca-test1803 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1804 Compression: zstd1805 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1806 NarSize: 1441807 References: 1808 Deriver: /nix/var/nix/builds/nix-58445-3431720553/TestClientCADerivations1030825761/001/store/x6a22711vz25bpm25q88ph2qhdjflw86-ca-test.drv1809 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1810 client_ca_test.go:185: Checking for realisation files in S3...1811 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1812 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1813--- PASS: TestCacheStatsHandler (1.35s)1814=== CONT TestClientErrorHandling/InvalidAuthToken18152026/09/15 08:31:44 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1816=== NAME TestClientCADerivations1817 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket43?endpoint=http://localhost:57174®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-58445-3431720553/TestClientCADerivations1030825761/001/store'1818 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11819--- PASS: TestClientCADerivations (1.96s)18202026-09-15 08:31:44.846 UTC [58870] ERROR: relation "goose_db_version" does not exist at character 3618212026-09-15 08:31:44.846 UTC [58870] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18222026-09-15 08:31:44.854 UTC [58871] ERROR: relation "goose_db_version" does not exist at character 3618232026-09-15 08:31:44.854 UTC [58871] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18242026/09/15 08:31:44 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.212346ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18252026-09-15 08:31:44.904 UTC [58872] ERROR: relation "goose_db_version" does not exist at character 3618262026-09-15 08:31:44.904 UTC [58872] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18272026/09/15 08:31:44 OK 20241026095416_initial_model.sql (53.17ms)18282026/09/15 08:31:44 OK 20251210153512_drop_unused_gin_index.sql (6.35ms)18292026/09/15 08:31:44 OK 20241026095416_initial_model.sql (52.6ms)18302026/09/15 08:31:44 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)18312026/09/15 08:31:44 OK 20251218171726_add_pins.sql (9.53ms)18322026-09-15 08:31:44.950 UTC [58873] ERROR: relation "goose_db_version" does not exist at character 3618332026-09-15 08:31:44.950 UTC [58873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18342026/09/15 08:31:44 OK 20251218171726_add_pins.sql (12.02ms)18352026/09/15 08:31:44 OK 20260628120000_add_object_size_and_stats.sql (14.46ms)18362026/09/15 08:31:44 goose: successfully migrated database to version: 2026062812000018372026/09/15 08:31:44 OK 1_commit_pending_closure.sql (2.58ms)18382026/09/15 08:31:44 OK 2_object_stats_trigger.sql (303µs)18392026/09/15 08:31:44 goose: up to current file version: 218402026/09/15 08:31:44 OK 20260628120000_add_object_size_and_stats.sql (17.93ms)18412026/09/15 08:31:44 goose: successfully migrated database to version: 2026062812000018422026/09/15 08:31:44 OK 1_commit_pending_closure.sql (1.47ms)18432026/09/15 08:31:44 OK 2_object_stats_trigger.sql (312.54µs)18442026/09/15 08:31:44 goose: up to current file version: 218452026/09/15 08:31:45 OK 20241026095416_initial_model.sql (76.26ms)18462026/09/15 08:31:45 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)18472026/09/15 08:31:45 OK 20251218171726_add_pins.sql (7.78ms)18482026/09/15 08:31:45 OK 20260628120000_add_object_size_and_stats.sql (7.69ms)18492026/09/15 08:31:45 goose: successfully migrated database to version: 2026062812000018502026/09/15 08:31:45 OK 1_commit_pending_closure.sql (8.56ms)18512026/09/15 08:31:45 OK 2_object_stats_trigger.sql (427.25µs)18522026/09/15 08:31:45 goose: up to current file version: 218532026/09/15 08:31:45 OK 20241026095416_initial_model.sql (56.94ms)18542026/09/15 08:31:45 OK 20251210153512_drop_unused_gin_index.sql (8.23ms)18552026/09/15 08:31:45 OK 20251218171726_add_pins.sql (11.7ms)18562026/09/15 08:31:45 OK 20260628120000_add_object_size_and_stats.sql (15.11ms)18572026/09/15 08:31:45 goose: successfully migrated database to version: 2026062812000018582026/09/15 08:31:45 OK 1_commit_pending_closure.sql (3.21ms)18592026/09/15 08:31:45 OK 2_object_stats_trigger.sql (736.38µs)18602026/09/15 08:31:45 goose: up to current file version: 218612026/09/15 08:31:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=376.842346ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1862=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1863=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1864=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1865=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1866=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1867=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1868=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1869=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1870=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1871=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18722026/09/15 08:31:45 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]1873=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18742026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[write]18752026/09/15 08:31:45 WARN Authentication failed token_preview=eyJhbGciOi...TvDY1LOVdw token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1876=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1877--- PASS: TestService_AuthMiddleware_OIDC (1.25s)1878 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1879 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1880 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1881 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1882=== RUN TestService_RequireScope_OIDC/builder_may_write1883=== PAUSE TestService_RequireScope_OIDC/builder_may_write1884=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1885=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1886=== RUN TestService_RequireScope_OIDC/ops_may_admin1887=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1888=== RUN TestService_RequireScope_OIDC/ops_may_not_write1889=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1890=== RUN TestService_RequireScope_OIDC/reader_may_not_write1891=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1892=== RUN TestService_RequireScope_OIDC/static_token_may_admin1893=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1894=== RUN TestService_RequireScope_OIDC/static_token_may_write1895=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1896=== RUN TestService_RequireScope_OIDC/reader_may_read1897=== PAUSE TestService_RequireScope_OIDC/reader_may_read1898=== RUN TestService_RequireScope_OIDC/writer_implies_read1899=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1900=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1901=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1902=== CONT TestService_RequireScope_OIDC/builder_may_write1903=== CONT TestService_RequireScope_OIDC/static_token_may_admin1904=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1905=== CONT TestService_RequireScope_OIDC/reader_may_read1906=== CONT TestService_RequireScope_OIDC/static_token_may_write1907=== CONT TestService_RequireScope_OIDC/ops_may_not_write19082026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[write]19092026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[admin]1910=== CONT TestService_RequireScope_OIDC/reader_may_not_write19112026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[read]1912=== CONT TestService_RequireScope_OIDC/ops_may_admin19132026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[read]1914=== CONT TestService_RequireScope_OIDC/builder_may_not_admin19152026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[admin]1916=== CONT TestService_RequireScope_OIDC/writer_implies_read19172026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[write]19182026/09/15 08:31:45 INFO OIDC auth successful provider=test scopes=[write]1919--- PASS: TestService_RequireScope_OIDC (1.55s)1920 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1921 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1922 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1923 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1924 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1925 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1926 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1927 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1928 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1929 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19302026-09-15 08:31:45.379 UTC [58874] ERROR: relation "goose_db_version" does not exist at character 3619312026-09-15 08:31:45.379 UTC [58874] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1932=== NAME TestOrphanedObjectsGCStressTest1933 orphaned_objects_gc_test.go:509: Stress test completed successfully:1934 orphaned_objects_gc_test.go:510: - Active objects preserved: 201935 orphaned_objects_gc_test.go:511: - Objects deleted: 2101936 orphaned_objects_gc_test.go:512: - Total GC'd: 2101937--- PASS: TestOrphanedObjectsGCStressTest (6.41s)19382026-09-15 08:31:45.438 UTC [58875] ERROR: relation "goose_db_version" does not exist at character 3619392026-09-15 08:31:45.438 UTC [58875] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19402026/09/15 08:31:45 OK 20241026095416_initial_model.sql (42.96ms)19412026/09/15 08:31:45 OK 20251210153512_drop_unused_gin_index.sql (9.73ms)19422026/09/15 08:31:45 OK 20251218171726_add_pins.sql (6.63ms)19432026/09/15 08:31:45 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=821.178953ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19442026/09/15 08:31:45 OK 20260628120000_add_object_size_and_stats.sql (18.81ms)19452026/09/15 08:31:45 goose: successfully migrated database to version: 2026062812000019462026/09/15 08:31:45 OK 1_commit_pending_closure.sql (2.59ms)19472026/09/15 08:31:45 OK 2_object_stats_trigger.sql (521.33µs)19482026/09/15 08:31:45 goose: up to current file version: 219492026/09/15 08:31:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19502026/09/15 08:31:45 WARN mTLS auth: bound subjects configured but subject DN unavailable19512026/09/15 08:31:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1952--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.55s)19532026/09/15 08:31:45 OK 20241026095416_initial_model.sql (37.36ms)19542026/09/15 08:31:45 OK 20251210153512_drop_unused_gin_index.sql (6.62ms)19552026/09/15 08:31:45 OK 20251218171726_add_pins.sql (5.53ms)19562026/09/15 08:31:45 OK 20260628120000_add_object_size_and_stats.sql (10.79ms)19572026/09/15 08:31:45 goose: successfully migrated database to version: 2026062812000019582026/09/15 08:31:45 OK 1_commit_pending_closure.sql (2.51ms)19592026/09/15 08:31:45 OK 2_object_stats_trigger.sql (566.46µs)19602026/09/15 08:31:45 goose: up to current file version: 21961--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.65s)19622026/09/15 08:31:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19632026/09/15 08:31:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19642026/09/15 08:31:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=019652026/09/15 08:31:46 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.595829256s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1966=== NAME TestClientIntegration1967 client_integration_test.go:304: Objects in database after GC:1968 client_integration_test.go:304: Successfully deleted all objects with GC --force1969--- PASS: TestClientIntegration (4.07s)19702026/09/15 08:31:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"19712026/09/15 08:31:47 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19722026/09/15 08:31:48 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.112141ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19732026/09/15 08:31:48 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=399.044958ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19742026/09/15 08:31:48 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=835.967274ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19752026/09/15 08:31:49 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.599296526s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1976--- PASS: TestClientErrorHandling (0.00s)1977 --- PASS: TestClientErrorHandling/InvalidStorePath (1.24s)1978 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.19s)1979 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.57s)1980PASS1981{"timestamp":"2026-09-15T08:31:51.106563Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57213","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1880,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}19822026-09-15 08:31:51.198 UTC [58512] LOG: received smart shutdown request19832026-09-15 08:31:51.199 UTC [58512] LOG: background worker "logical replication launcher" (PID 58522) exited with exit code 119842026-09-15 08:31:51.202 UTC [58517] LOG: shutting down19852026-09-15 08:31:51.202 UTC [58517] LOG: checkpoint starting: shutdown immediate19862026-09-15 08:31:52.147 UTC [58517] LOG: checkpoint complete: wrote 13210 buffers (80.6%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.658 s, sync=0.285 s, total=0.945 s; sync files=17141, longest=0.001 s, average=0.001 s; distance=240173 kB, estimate=240173 kB; lsn=0/10218410, redo lsn=0/1021841019872026-09-15 08:31:52.151 UTC [58512] LOG: database system is shut down1988Running OIDC tests...1989=== RUN TestGlobMatch1990=== PAUSE TestGlobMatch1991=== RUN TestAudienceForIssuer1992=== PAUSE TestAudienceForIssuer1993=== RUN TestValidateToken_ValidToken1994=== PAUSE TestValidateToken_ValidToken1995=== RUN TestValidateToken_WrongAudience1996=== PAUSE TestValidateToken_WrongAudience1997=== RUN TestValidateToken_Expired1998=== PAUSE TestValidateToken_Expired1999=== RUN TestValidateToken_BoundClaimsMismatch2000=== PAUSE TestValidateToken_BoundClaimsMismatch2001=== RUN TestValidateToken_BoundSubjectMismatch2002=== PAUSE TestValidateToken_BoundSubjectMismatch2003=== RUN TestValidateToken_MultipleProviders2004=== PAUSE TestValidateToken_MultipleProviders2005=== RUN TestValidateToken_NoMatchingProvider2006=== PAUSE TestValidateToken_NoMatchingProvider2007=== RUN TestValidateToken_KubernetesServiceAccount2008=== PAUSE TestValidateToken_KubernetesServiceAccount2009=== RUN TestNewValidator_KubernetesRequiresCA2010=== PAUSE TestNewValidator_KubernetesRequiresCA2011=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2012=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2013=== RUN TestScopes_LegacyProviderDefaultsToWrite2014=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2015=== RUN TestScopes_Rules2016=== PAUSE TestScopes_Rules2017=== RUN TestScopes_ConfigValidation2018=== PAUSE TestScopes_ConfigValidation2019=== CONT TestGlobMatch2020=== RUN TestGlobMatch/foo_foo2021=== CONT TestScopes_LegacyProviderDefaultsToWrite2022=== PAUSE TestGlobMatch/foo_foo2023=== RUN TestGlobMatch/foo_bar2024=== PAUSE TestGlobMatch/foo_bar2025=== RUN TestGlobMatch/*_2026=== PAUSE TestGlobMatch/*_2027=== RUN TestGlobMatch/*_anything2028=== PAUSE TestGlobMatch/*_anything2029=== CONT TestValidateToken_NoMatchingProvider2030=== CONT TestValidateToken_BoundSubjectMismatch2031=== CONT TestNewValidator_KubernetesRequiresCA2032=== CONT TestValidateToken_WrongAudience2033=== CONT TestScopes_ConfigValidation2034=== CONT TestValidateToken_ValidToken2035=== CONT TestValidateToken_Expired2036=== CONT TestValidateToken_MultipleProviders2037=== RUN TestGlobMatch/foo*_foo2038=== PAUSE TestGlobMatch/foo*_foo2039=== RUN TestGlobMatch/foo*_foobar2040=== PAUSE TestGlobMatch/foo*_foobar2041=== RUN TestGlobMatch/foo*_bar2042=== PAUSE TestGlobMatch/foo*_bar2043=== RUN TestGlobMatch/*bar_bar2044=== PAUSE TestGlobMatch/*bar_bar2045=== RUN TestGlobMatch/*bar_foobar2046=== PAUSE TestGlobMatch/*bar_foobar2047=== RUN TestGlobMatch/*bar_foo2048=== PAUSE TestGlobMatch/*bar_foo2049=== RUN TestGlobMatch/foo*bar_foobar2050=== PAUSE TestGlobMatch/foo*bar_foobar2051=== RUN TestGlobMatch/foo*bar_foo123bar2052=== PAUSE TestGlobMatch/foo*bar_foo123bar2053=== RUN TestGlobMatch/foo*bar_foobarbaz2054=== PAUSE TestGlobMatch/foo*bar_foobarbaz2055=== RUN TestGlobMatch/*/*_foo/bar2056=== PAUSE TestGlobMatch/*/*_foo/bar2057=== RUN TestGlobMatch/*/*_foo2058=== PAUSE TestGlobMatch/*/*_foo2059=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2060=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2061=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02062=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02063=== RUN TestGlobMatch/refs/*/main_refs/heads/main2064=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2065=== RUN TestGlobMatch/fo?_foo2066=== PAUSE TestGlobMatch/fo?_foo2067=== RUN TestGlobMatch/fo?_fo2068=== PAUSE TestGlobMatch/fo?_fo2069=== RUN TestGlobMatch/fo?_fooo2070=== PAUSE TestGlobMatch/fo?_fooo2071=== RUN TestGlobMatch/?oo_foo2072=== PAUSE TestGlobMatch/?oo_foo2073=== RUN TestGlobMatch/?oo_boo2074=== PAUSE TestGlobMatch/?oo_boo2075=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2076=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2077=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2078=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2079=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2080--- PASS: TestScopes_ConfigValidation (0.00s)2081=== CONT TestValidateToken_KubernetesServiceAccount20822026/09/15 08:31:52 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57406/oidc20832026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57409/oidc20842026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57407/oidc20852026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57405/oidc20862026/09/15 08:31:52 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57413/oidc20872026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57412/oidc20882026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57408/oidc2089--- PASS: TestValidateToken_ValidToken (0.01s)2090=== CONT TestAudienceForIssuer2091--- PASS: TestAudienceForIssuer (0.00s)2092=== CONT TestScopes_Rules2093--- PASS: TestValidateToken_WrongAudience (0.01s)2094=== CONT TestValidateToken_BoundClaimsMismatch20952026/09/15 08:31:52 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12320962026/09/15 08:31:52 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57411/oidc2097--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2098=== CONT TestGlobMatch/foo_foo2099=== CONT TestGlobMatch/*bar_bar2100=== CONT TestGlobMatch/foo*bar_foobarbaz2101=== CONT TestGlobMatch/foo*bar_foo123bar2102=== CONT TestGlobMatch/foo*bar_foobar2103=== CONT TestGlobMatch/*bar_foo2104=== CONT TestGlobMatch/*bar_foobar2105=== CONT TestGlobMatch/fo?_fo2106=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2107=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2108=== CONT TestGlobMatch/?oo_boo2109=== CONT TestGlobMatch/?oo_foo2110=== CONT TestGlobMatch/fo?_fooo2111--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2112=== CONT TestGlobMatch/fo?_foo2113=== CONT TestGlobMatch/refs/*/main_refs/heads/main2114=== CONT TestGlobMatch/foo*_foo2115=== CONT TestGlobMatch/foo*_bar2116=== CONT TestGlobMatch/foo*_foobar2117=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2118=== CONT TestGlobMatch/*_2119=== CONT TestGlobMatch/*_anything2120=== CONT TestGlobMatch/*/*_foo2121=== CONT TestGlobMatch/foo_bar2122=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02123=== CONT TestGlobMatch/*/*_foo/bar2124--- PASS: TestGlobMatch (0.00s)2125 --- PASS: TestGlobMatch/foo_foo (0.00s)2126 --- PASS: TestGlobMatch/*bar_bar (0.00s)2127 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2128 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2129 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2130 --- PASS: TestGlobMatch/*bar_foo (0.00s)2131 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2132 --- PASS: TestGlobMatch/fo?_fo (0.00s)2133 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2134 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2135 --- PASS: TestGlobMatch/?oo_boo (0.00s)2136 --- PASS: TestGlobMatch/?oo_foo (0.00s)2137 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2138 --- PASS: TestGlobMatch/fo?_foo (0.00s)2139 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)21402026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57428/oidc2141 --- PASS: TestGlobMatch/foo*_foo (0.00s)2142 --- PASS: TestGlobMatch/foo*_bar (0.00s)2143 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2144 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2145 --- PASS: TestGlobMatch/*_ (0.00s)2146 --- PASS: TestGlobMatch/*_anything (0.00s)2147 --- PASS: TestGlobMatch/*/*_foo (0.00s)2148 --- PASS: TestGlobMatch/foo_bar (0.00s)2149 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2150 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)21512026/09/15 08:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57427/oidc2152--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2153--- PASS: TestValidateToken_Expired (0.01s)21542026/09/15 08:31:52 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:574232155--- PASS: TestValidateToken_MultipleProviders (0.01s)2156--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2157--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)2158--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)21592026/09/15 08:31:52 http: TLS handshake error from 127.0.0.1:57414: remote error: tls: bad certificate2160--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2161--- PASS: TestScopes_Rules (0.01s)2162PASS2163Running hook tests...2164=== RUN TestSendPathsEmpty2165=== PAUSE TestSendPathsEmpty2166=== RUN TestQueueEnqueueAndFetch2167=== PAUSE TestQueueEnqueueAndFetch2168=== RUN TestQueueDeduplication2169=== PAUSE TestQueueDeduplication2170=== RUN TestQueueRemove2171=== PAUSE TestQueueRemove2172=== RUN TestQueueFetchBatchLimit2173=== PAUSE TestQueueFetchBatchLimit2174=== RUN TestQueueRetryMovesToBack2175=== PAUSE TestQueueRetryMovesToBack2176=== RUN TestQueueFetchRemoveLifecycle2177=== PAUSE TestQueueFetchRemoveLifecycle2178=== RUN TestQueueConcurrentWriters2179=== PAUSE TestQueueConcurrentWriters2180=== RUN TestQueueRemoveLargeClosure2181=== PAUSE TestQueueRemoveLargeClosure2182=== RUN TestServerClientIntegration2183=== PAUSE TestServerClientIntegration2184=== RUN TestServerQueueError2185=== PAUSE TestServerQueueError2186=== RUN TestGetListenerSocketActivation2187 server_test.go:210: === RUN TestGetListenerSocketActivation2188 --- PASS: TestGetListenerSocketActivation (0.00s)2189 PASS2190 2191--- PASS: TestGetListenerSocketActivation (0.01s)2192=== RUN TestDrainIsolatesPoisonPath2193=== PAUSE TestDrainIsolatesPoisonPath2194=== RUN TestRunNotBlockedByPoisonHead2195=== PAUSE TestRunNotBlockedByPoisonHead2196=== RUN TestDrainGivesUpWhenServerDown2197=== PAUSE TestDrainGivesUpWhenServerDown2198=== RUN TestFailedPathPrunedByLaterClosure2199=== PAUSE TestFailedPathPrunedByLaterClosure2200=== RUN TestWorkerUploadsAndRemoves2201=== PAUSE TestWorkerUploadsAndRemoves2202=== RUN TestWorkerSkipsGCdPaths2203=== PAUSE TestWorkerSkipsGCdPaths2204=== RUN TestWorkerPrunesClosureDeps2205=== PAUSE TestWorkerPrunesClosureDeps2206=== RUN TestDrainTimeout2207=== PAUSE TestDrainTimeout2208=== CONT TestSendPathsEmpty2209=== CONT TestServerQueueError2210=== CONT TestWorkerUploadsAndRemoves2211--- PASS: TestSendPathsEmpty (0.00s)2212=== CONT TestServerClientIntegration2213=== CONT TestQueueRemoveLargeClosure2214=== CONT TestQueueConcurrentWriters2215=== CONT TestQueueFetchRemoveLifecycle2216=== CONT TestQueueRetryMovesToBack2217=== CONT TestQueueFetchBatchLimit2218=== CONT TestQueueRemove2219=== CONT TestQueueDeduplication22202026/09/15 08:31:53 ERROR Failed to queue paths error="permission denied" count=12221--- PASS: TestServerClientIntegration (0.00s)2222=== CONT TestQueueEnqueueAndFetch2223--- PASS: TestServerQueueError (0.00s)2224=== CONT TestDrainGivesUpWhenServerDown22252026/09/15 08:31:53 INFO Upload queue status pending=222262026/09/15 08:31:53 INFO Uploading batch count=22227--- PASS: TestQueueFetchBatchLimit (0.01s)2228=== CONT TestFailedPathPrunedByLaterClosure2229--- PASS: TestQueueEnqueueAndFetch (0.01s)2230=== CONT TestWorkerPrunesClosureDeps2231--- PASS: TestQueueDeduplication (0.01s)2232=== CONT TestDrainTimeout2233--- PASS: TestQueueRemove (0.01s)2234=== CONT TestRunNotBlockedByPoisonHead22352026/09/15 08:31:53 INFO Uploading batch count=222362026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=222372026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainGivesUpWhenServerDown1015249929/002/a22382026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainGivesUpWhenServerDown1015249929/002/b2239--- PASS: TestQueueRetryMovesToBack (0.01s)2240=== CONT TestWorkerSkipsGCdPaths2241--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2242=== CONT TestDrainIsolatesPoisonPath22432026/09/15 08:31:53 INFO Uploading batch count=222442026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=222452026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainGivesUpWhenServerDown1015249929/002/c22462026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainGivesUpWhenServerDown1015249929/002/d22472026/09/15 08:31:53 INFO Uploading batch count=122482026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=122492026/09/15 08:31:53 INFO Uploading batch count=222502026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=222512026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainGivesUpWhenServerDown1015249929/002/e22522026/09/15 08:31:53 INFO Uploading batch count=122532026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainGivesUpWhenServerDown1015249929/002/f22542026/09/15 08:31:53 INFO Upload queue status pending=222552026/09/15 08:31:53 INFO Uploading batch count=222562026/09/15 08:31:53 INFO Uploading batch count=122572026/09/15 08:31:53 INFO Uploading batch count=122582026/09/15 08:31:53 ERROR Drain finished with paths left in queue remaining=1022592026/09/15 08:31:53 INFO Uploading batch count=422602026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=422612026/09/15 08:31:53 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-58445-3431720553/TestDrainIsolatesPoisonPath1707389498/002/bbb22622026/09/15 08:31:53 INFO Upload queue status pending=322632026/09/15 08:31:53 INFO Uploading batch count=122642026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=122652026/09/15 08:31:53 INFO Upload queue status pending=222662026/09/15 08:31:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-58445-3431720553/TestWorkerSkipsGCdPaths732837153/002/nonexistent2267--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)22682026/09/15 08:31:53 INFO Uploading batch count=122692026/09/15 08:31:53 INFO Uploading batch count=122702026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=122712026/09/15 08:31:53 INFO Uploading batch count=122722026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=12273--- PASS: TestDrainGivesUpWhenServerDown (0.01s)22742026/09/15 08:31:53 INFO Uploading batch count=122752026/09/15 08:31:53 ERROR Upload failed error="upload failed" count=122762026/09/15 08:31:53 ERROR Drain finished with paths left in queue remaining=12277--- PASS: TestDrainIsolatesPoisonPath (0.01s)2278--- PASS: TestWorkerUploadsAndRemoves (0.03s)2279--- PASS: TestWorkerPrunesClosureDeps (0.02s)2280--- PASS: TestWorkerSkipsGCdPaths (0.02s)2281--- PASS: TestQueueRemoveLargeClosure (0.06s)2282--- PASS: TestQueueConcurrentWriters (0.13s)22832026/09/15 08:31:53 ERROR Upload failed error="context deadline exceeded" count=222842026/09/15 08:31:53 ERROR Drain finished with paths left in queue remaining=42285--- PASS: TestDrainTimeout (0.21s)22862026/09/15 08:31:54 INFO Uploading batch count=122872026/09/15 08:31:54 INFO Uploading batch count=122882026/09/15 08:31:54 INFO Uploading batch count=122892026/09/15 08:31:54 ERROR Upload failed error="upload failed" count=122902026/09/15 08:31:54 INFO Uploading batch count=122912026/09/15 08:31:54 ERROR Upload failed error="upload failed" count=122922026/09/15 08:31:54 INFO Uploading batch count=122932026/09/15 08:31:54 ERROR Upload failed error="upload failed" count=122942026/09/15 08:31:54 INFO Uploading batch count=122952026/09/15 08:31:54 ERROR Upload failed error="upload failed" count=122962026/09/15 08:31:54 ERROR Drain finished with paths left in queue remaining=12297--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2298PASS