niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #187
· 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 TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestStreamPushReportsEveryPath47=== PAUSE TestStreamPushReportsEveryPath48=== RUN TestStreamPushBatchesUnderLoad49=== PAUSE TestStreamPushBatchesUnderLoad50=== RUN TestStreamPushIsolatesFailures51=== PAUSE TestStreamPushIsolatesFailures52=== RUN TestStreamPushGivesUpOnDeadServer53=== PAUSE TestStreamPushGivesUpOnDeadServer54=== RUN TestSetClientTLS55=== PAUSE TestSetClientTLS56=== RUN TestSetClientTLSDoesNotMutateDefaultTransport57=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport58=== RUN TestSetClientTLSErrors59=== PAUSE TestSetClientTLSErrors60=== RUN TestStaticToken61=== PAUSE TestStaticToken62=== RUN TestFileTokenReadsAndCaches63=== PAUSE TestFileTokenReadsAndCaches64=== RUN TestFileTokenMissing65=== PAUSE TestFileTokenMissing66=== RUN TestFileTokenEmpty67=== PAUSE TestFileTokenEmpty68=== RUN TestScriptTokenNoExpiryRerunsEveryCall69=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall70=== RUN TestScriptTokenCachesUntilRefresh71=== PAUSE TestScriptTokenCachesUntilRefresh72=== RUN TestScriptTokenEmptyToken73=== PAUSE TestScriptTokenEmptyToken74=== RUN TestScriptTokenBadJSON75=== PAUSE TestScriptTokenBadJSON76=== RUN TestScriptTokenScriptFails77=== PAUSE TestScriptTokenScriptFails78=== RUN TestScriptTokenEmptyCommand79=== PAUSE TestScriptTokenEmptyCommand80=== CONT TestDoServerRequestAttachesToken81=== CONT TestScriptTokenEmptyCommand82=== CONT TestScriptTokenScriptFails83--- PASS: TestScriptTokenEmptyCommand (0.00s)84=== CONT TestSetClientTLSErrors85=== CONT TestDoWithRetry_BodyReplayedViaGetBody86=== CONT TestSetClientTLSDoesNotMutateDefaultTransport87=== CONT TestScriptTokenNoExpiryRerunsEveryCall88=== CONT TestFileTokenEmpty89=== CONT TestStreamPushBatchesUnderLoad90=== CONT TestSetClientTLS91=== CONT TestShellSplitErrors92--- PASS: TestShellSplitErrors (0.00s)93=== CONT TestStreamPushGivesUpOnDeadServer942026/09/09 10:29:33 ERROR Upload failed error="connection refused" count=20952026/09/09 10:29:33 ERROR Server seems unavailable, giving up on batch untried=1796=== CONT TestStreamPushIsolatesFailures97--- PASS: TestFileTokenEmpty (0.00s)98--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)99=== CONT TestStreamPushReportsEveryPath1002026/09/09 10:29:33 ERROR Upload failed error="bad path" count=3101--- PASS: TestStreamPushReportsEveryPath (0.00s)102=== CONT TestResolveStorePath103=== CONT TestEncodeNixBase32WithRealHash104--- PASS: TestStreamPushIsolatesFailures (0.00s)105--- PASS: TestEncodeNixBase32WithRealHash (0.00s)106=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1072026/09/09 10:29:33 WARN Rate limiter enabled after throttle name=server-test rate=51082026/09/09 10:29:33 WARN Rate limiter enabled after throttle name=server-test rate=51092026/09/09 10:29:33 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:61088110--- PASS: TestDoServerRequestAttachesToken (0.01s)111=== CONT TestRateLimiterFeedback112=== RUN TestRateLimiterFeedback/429_enables_limiter113=== PAUSE TestRateLimiterFeedback/429_enables_limiter114=== RUN TestRateLimiterFeedback/503_enables_limiter115=== PAUSE TestRateLimiterFeedback/503_enables_limiter116=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter117=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter118=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter119=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter120=== CONT TestPathInfoCACompatibility121=== RUN TestPathInfoCACompatibility/null_ca_field122=== PAUSE TestPathInfoCACompatibility/null_ca_field123=== RUN TestPathInfoCACompatibility/old_string_format_-_text124=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text125=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive126=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive127=== RUN TestPathInfoCACompatibility/new_structured_format_-_text128=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text129=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method130=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method131=== CONT TestParsePathInfoJSONMultiplePaths132=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1332026/09/09 10:29:33 WARN Rate limiter backed off name=server-test rate=5134=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1352026/09/09 10:29:33 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:61088136=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths137=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths138=== CONT TestParsePathInfoJSON139=== RUN TestParsePathInfoJSON/Nix_format140=== PAUSE TestParsePathInfoJSON/Nix_format141=== RUN TestParsePathInfoJSON/Lix_format142=== PAUSE TestParsePathInfoJSON/Lix_format143=== RUN TestParsePathInfoJSON/empty_input144=== PAUSE TestParsePathInfoJSON/empty_input145=== RUN TestSetClientTLSErrors/missing_cert_file146=== RUN TestParsePathInfoJSON/whitespace_only147=== PAUSE TestSetClientTLSErrors/missing_cert_file148=== PAUSE TestParsePathInfoJSON/whitespace_only149=== RUN TestParsePathInfoJSON/invalid_JSON150=== RUN TestSetClientTLSErrors/missing_key_file151=== PAUSE TestSetClientTLSErrors/missing_key_file152=== RUN TestSetClientTLSErrors/missing_ca_file153=== PAUSE TestParsePathInfoJSON/invalid_JSON154=== PAUSE TestSetClientTLSErrors/missing_ca_file155=== CONT TestGetStorePathHash156=== RUN TestSetClientTLSErrors/invalid_ca_file157=== RUN TestGetStorePathHash/valid_store_path158=== PAUSE TestSetClientTLSErrors/invalid_ca_file159=== PAUSE TestGetStorePathHash/valid_store_path160=== RUN TestGetStorePathHash/basename_without_hyphen_should_error161=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error162=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error163=== CONT TestConvertHashToNix32164=== RUN TestConvertHashToNix32/SRI_format_to_Nix32165=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32166--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)167=== RUN TestConvertHashToNix32/already_Nix32_format168=== CONT TestPathInfoHashCompatibility169=== PAUSE TestConvertHashToNix32/already_Nix32_format170=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)171=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)172=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon173=== RUN TestConvertHashToNix32/invalid_format174=== PAUSE TestConvertHashToNix32/invalid_format175=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon176=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error177=== CONT TestStaticToken178=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI179=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI180=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512181=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error182=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error183=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512184=== CONT TestFileTokenMissing185=== CONT TestShellSplit186=== CONT TestScriptTokenBadJSON187--- PASS: TestStaticToken (0.00s)188--- PASS: TestShellSplit (0.00s)189=== CONT TestScriptTokenEmptyToken190--- PASS: TestResolveStorePath (0.00s)191=== CONT TestScriptTokenCachesUntilRefresh192--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)193=== CONT TestUploadMultipart_SupersededByPeer194=== RUN TestUploadMultipart_SupersededByPeer/exists195=== PAUSE TestUploadMultipart_SupersededByPeer/exists196=== RUN TestUploadMultipart_SupersededByPeer/missing197=== PAUSE TestUploadMultipart_SupersededByPeer/missing198=== CONT TestEncodeNixBase32199=== RUN TestEncodeNixBase32/test_string_hash200=== PAUSE TestEncodeNixBase32/test_string_hash201=== RUN TestEncodeNixBase32/empty_input202=== PAUSE TestEncodeNixBase32/empty_input203=== RUN TestSetClientTLS/rejects_connection_without_client_cert204=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert205=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA206=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA207=== RUN TestSetClientTLS/preserves_debug_logging_transport208=== CONT TestDumpPathWriterError209=== PAUSE TestSetClientTLS/preserves_debug_logging_transport210=== CONT TestDumpPathSingleFile211--- PASS: TestFileTokenMissing (0.00s)212=== CONT TestDumpPathMatchesNix213--- PASS: TestScriptTokenScriptFails (0.01s)214=== CONT TestFilterOversizedClosures215=== RUN TestFilterOversizedClosures/no_limit_keeps_everything216=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything217=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped218=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped219=== RUN TestFilterOversizedClosures/all_closures_skipped220=== PAUSE TestFilterOversizedClosures/all_closures_skipped221=== CONT TestPartSizeForNAR222=== RUN TestPartSizeForNAR/zero_stays_at_minimum223=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum224=== RUN TestPartSizeForNAR/small_stays_at_minimum225=== PAUSE TestPartSizeForNAR/small_stays_at_minimum226=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum227=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum228=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts229=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts230=== RUN TestPartSizeForNAR/1_TiB231=== PAUSE TestPartSizeForNAR/1_TiB232=== RUN TestPartSizeForNAR/5_TiB_S3_max_object233=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object234=== RUN TestPartSizeForNAR/capped_at_5_GiB235=== PAUSE TestPartSizeForNAR/capped_at_5_GiB236=== CONT TestCaseHackSuffix237--- PASS: TestScriptTokenBadJSON (0.01s)238=== CONT TestFileTokenReadsAndCaches239--- PASS: TestScriptTokenEmptyToken (0.01s)240=== CONT TestRateLimiterFeedback/429_enables_limiter2412026/09/09 10:29:33 WARN Rate limiter enabled after throttle name=server-test rate=52422026/09/09 10:29:33 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:610942432026/09/09 10:29:33 WARN Rate limiter backed off name=server-test rate=5244=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter245--- PASS: TestFileTokenReadsAndCaches (0.00s)246=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter247=== CONT TestRateLimiterFeedback/503_enables_limiter2482026/09/09 10:29:33 WARN Rate limiter enabled after throttle name=server-test rate=5249=== CONT TestPathInfoCACompatibility/null_ca_field2502026/09/09 10:29:33 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:61099251=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2522026/09/09 10:29:33 WARN Rate limiter backed off name=server-test rate=5253=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method254--- PASS: TestRateLimiterFeedback (0.00s)255 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)256 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)257 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)258 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)259=== CONT TestPathInfoCACompatibility/new_structured_format_-_text260=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive261=== CONT TestPathInfoCACompatibility/old_string_format_-_text262=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths263--- PASS: TestPathInfoCACompatibility (0.00s)264 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)265 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)266 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)267 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)268 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)269=== CONT TestParsePathInfoJSON/Nix_format270--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)271 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)272 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)273=== CONT TestSetClientTLSErrors/missing_cert_file274=== CONT TestParsePathInfoJSON/invalid_JSON275=== CONT TestParsePathInfoJSON/whitespace_only276=== CONT TestParsePathInfoJSON/empty_input277=== CONT TestParsePathInfoJSON/Lix_format278=== CONT TestSetClientTLSErrors/missing_ca_file279--- PASS: TestParsePathInfoJSON (0.00s)280 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)281 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)282 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)283 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)284 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)285=== CONT TestSetClientTLSErrors/invalid_ca_file286=== CONT TestSetClientTLSErrors/missing_key_file287=== CONT TestConvertHashToNix32/SRI_format_to_Nix32288=== CONT TestConvertHashToNix32/already_Nix32_format289=== CONT TestConvertHashToNix32/invalid_format290=== CONT TestGetStorePathHash/valid_store_path291=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)292=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512293=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI294--- PASS: TestConvertHashToNix32 (0.00s)295 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)296 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)297 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)298=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon299=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error300=== CONT TestGetStorePathHash/basename_without_hyphen_should_error301--- PASS: TestPathInfoHashCompatibility (0.00s)302 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)303 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)304 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)305 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)306=== CONT TestUploadMultipart_SupersededByPeer/exists307=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error308--- PASS: TestGetStorePathHash (0.00s)309 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)310 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)311 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)312 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)313=== CONT TestEncodeNixBase32/test_string_hash314=== CONT TestUploadMultipart_SupersededByPeer/missing315--- PASS: TestSetClientTLSErrors (0.01s)316 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)317 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)318 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)319 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)320=== CONT TestSetClientTLS/rejects_connection_without_client_cert321--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)322 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)323 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)324=== CONT TestEncodeNixBase32/empty_input325--- PASS: TestEncodeNixBase32 (0.00s)326 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)327 --- PASS: TestEncodeNixBase32/empty_input (0.00s)328=== CONT TestSetClientTLS/preserves_debug_logging_transport329=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA330=== CONT TestFilterOversizedClosures/no_limit_keeps_everything331=== CONT TestFilterOversizedClosures/all_closures_skipped3322026/09/09 10:29:33 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=50333=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3342026/09/09 10:29:33 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=2000335--- PASS: TestFilterOversizedClosures (0.00s)336 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)337 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)338 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)339=== CONT TestPartSizeForNAR/zero_stays_at_minimum340=== CONT TestPartSizeForNAR/1_TiB341=== CONT TestPartSizeForNAR/capped_at_5_GiB342=== CONT TestPartSizeForNAR/5_TiB_S3_max_object343=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum344=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts345=== CONT TestPartSizeForNAR/small_stays_at_minimum346--- PASS: TestPartSizeForNAR (0.00s)347 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)348 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)349 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)350 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)351 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)352 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)353 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)354--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)3552026/09/09 10:29:33 http: TLS handshake error from 127.0.0.1:61105: read tcp 127.0.0.1:61093->127.0.0.1:61105: use of closed network connection356--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)357--- PASS: TestSetClientTLS (0.01s)358 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)359 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)360 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)361--- PASS: TestDumpPathWriterError (0.04s)362--- PASS: TestStreamPushBatchesUnderLoad (0.10s)363--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)364--- PASS: TestDumpPathSingleFile (6.34s)365--- PASS: TestCaseHackSuffix (6.33s)366--- PASS: TestDumpPathMatchesNix (6.35s)367PASS368Running server tests...369The files belonging to this database system will be owned by user "_nixbld1".370This user must also own the server process.371372The database cluster will be initialized with locale "C".373The default database encoding has accordingly been set to "SQL_ASCII".374The default text search configuration will be set to "english".375376Data page checksums are enabled.377378creating directory /nix/var/nix/builds/nix-24452-4259264778/postgres117939102/data ... ok379creating subdirectories ... ok380selecting dynamic shared memory implementation ... posix381selecting default "max_connections" ... 100382selecting default "shared_buffers" ... 128MB383selecting default time zone ... UTC384creating configuration files ... ok385running bootstrap script ... ok386performing post-bootstrap initialization ... ok387syncing data to disk ... ok388389initdb: warning: enabling "trust" authentication for local connections390initdb: 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.391392Success. You can now start the database server using:393394 pg_ctl -D /nix/var/nix/builds/nix-24452-4259264778/postgres117939102/data -l logfile start3953962026-09-09 10:29:42.284 UTC [24626] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit3972026-09-09 10:29:42.285 UTC [24626] LOG: listening on Unix socket "/nix/var/nix/builds/nix-24452-4259264778/postgres117939102/.s.PGSQL.5432"3982026-09-09 10:29:42.287 UTC [24633] LOG: database system was shut down at 2026-09-09 10:29:42 UTC3992026-09-09 10:29:42.287 UTC [24626] LOG: database system is ready to accept connections400/nix/var/nix/builds/nix-24452-4259264778/postgres117939102:5432 - accepting connections401=== RUN TestService_AuthMiddleware402=== PAUSE TestService_AuthMiddleware403=== RUN TestService_AuthMiddleware_MTLSProxyHeader404=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader405=== RUN TestService_AuthMiddleware_MTLSBoundSubjects406=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects407=== RUN TestService_ReadAuthMiddleware408=== PAUSE TestService_ReadAuthMiddleware409=== RUN TestService_AuthMiddleware_OIDC410=== PAUSE TestService_AuthMiddleware_OIDC411=== RUN TestService_RequireScope_OIDC412=== PAUSE TestService_RequireScope_OIDC413=== RUN TestService_ReadScope_PublicByDefault414=== PAUSE TestService_ReadScope_PublicByDefault415=== RUN TestCacheConfigHandler416=== PAUSE TestCacheConfigHandler417=== RUN TestCacheStatsHandler418=== PAUSE TestCacheStatsHandler419=== RUN TestClientCADerivations420=== PAUSE TestClientCADerivations421=== RUN TestClientErrorHandling422=== PAUSE TestClientErrorHandling423=== RUN TestClientIntegration424=== PAUSE TestClientIntegration425=== RUN TestClientMultipleUploads426=== PAUSE TestClientMultipleUploads427=== RUN TestClientWithDependencies428=== PAUSE TestClientWithDependencies429=== RUN TestPinProtectsFromGC430=== PAUSE TestPinProtectsFromGC431=== RUN TestResolveDBConnectionString432=== PAUSE TestResolveDBConnectionString433=== RUN TestGCAdvisoryLockBlocksConcurrentRun4342026-09-09 10:29:44.732 UTC [24712] ERROR: relation "goose_db_version" does not exist at character 364352026-09-09 10:29:44.732 UTC [24712] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4362026/09/09 10:29:44 OK 20241026095416_initial_model.sql (4.12ms)4372026/09/09 10:29:44 OK 20251210153512_drop_unused_gin_index.sql (471.79µs)4382026/09/09 10:29:44 OK 20251218171726_add_pins.sql (871.63µs)4392026/09/09 10:29:44 OK 20260628120000_add_object_size_and_stats.sql (900.29µs)4402026/09/09 10:29:44 goose: successfully migrated database to version: 202606281200004412026/09/09 10:29:44 OK 1_commit_pending_closure.sql (992.88µs)4422026/09/09 10:29:44 OK 2_object_stats_trigger.sql (219.33µs)4432026/09/09 10:29:44 goose: up to current file version: 2444--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.37s)445=== RUN TestGCBugBareHashReferences446=== PAUSE TestGCBugBareHashReferences447=== RUN TestGCMetrics448=== PAUSE TestGCMetrics449=== RUN TestGCTaskStore_StartNew450=== PAUSE TestGCTaskStore_StartNew451=== RUN TestGCTaskStore_DeduplicateSameParams452=== PAUSE TestGCTaskStore_DeduplicateSameParams453=== RUN TestGCTaskStore_ConflictDifferentParams454=== PAUSE TestGCTaskStore_ConflictDifferentParams455=== RUN TestGCTaskStore_GetEmpty456=== PAUSE TestGCTaskStore_GetEmpty457=== RUN TestGCTaskStore_GetReturnsLatest458=== PAUSE TestGCTaskStore_GetReturnsLatest459=== RUN TestGCTaskStore_CompletedAllowsNewTask460=== PAUSE TestGCTaskStore_CompletedAllowsNewTask461=== RUN TestGCTaskStore_PhaseUpdates462=== PAUSE TestGCTaskStore_PhaseUpdates463=== RUN TestGCTaskStore_Fail464=== PAUSE TestGCTaskStore_Fail465=== RUN TestGracefulShutdownDrainsInflight466=== PAUSE TestGracefulShutdownDrainsInflight467=== RUN TestService_healthCheckHandler468=== PAUSE TestService_healthCheckHandler469=== RUN TestService_readinessHandler470=== PAUSE TestService_readinessHandler471=== RUN TestGenerateLandingPage472=== PAUSE TestGenerateLandingPage473=== RUN TestCacheConfigHandlerMaxNarSize474=== PAUSE TestCacheConfigHandlerMaxNarSize475=== RUN TestCreatePendingClosureRejectsOversizedNAR476=== PAUSE TestCreatePendingClosureRejectsOversizedNAR477=== RUN TestNARDeduplicationMetadataUploadBug478=== PAUSE TestNARDeduplicationMetadataUploadBug479=== RUN TestMetricsInventory480=== PAUSE TestMetricsInventory481=== RUN TestService_NativeMTLS482=== PAUSE TestService_NativeMTLS483=== RUN TestServerTLSConfig484=== PAUSE TestServerTLSConfig485=== RUN TestMultipartCleanup486=== PAUSE TestMultipartCleanup487=== RUN TestObjectStatsTrigger488=== PAUSE TestObjectStatsTrigger489=== RUN TestOrphanedObjectsGC490=== PAUSE TestOrphanedObjectsGC491=== RUN TestOrphanedObjectsGCStressTest492=== PAUSE TestOrphanedObjectsGCStressTest493=== RUN TestResurrectedObjectNotDeleted494=== PAUSE TestResurrectedObjectNotDeleted495=== RUN TestParseSingleRange496=== PAUSE TestParseSingleRange497=== RUN TestIsValidCachePath498=== PAUSE TestIsValidCachePath499=== RUN TestReadProxyNarinfo500=== PAUSE TestReadProxyNarinfo501=== RUN TestReadProxyNarinfoAlreadyDecompressed502=== PAUSE TestReadProxyNarinfoAlreadyDecompressed503=== RUN TestReadProxyNarStreaming504=== PAUSE TestReadProxyNarStreaming505=== RUN TestReadProxy404506=== PAUSE TestReadProxy404507=== RUN TestReadProxyInvalidPath508=== PAUSE TestReadProxyInvalidPath509=== RUN TestReadProxyHead510=== PAUSE TestReadProxyHead511=== RUN TestReadProxyConditionalGet512=== PAUSE TestReadProxyConditionalGet513=== RUN TestReadProxyRootRedirectsToIndexHTML514=== PAUSE TestReadProxyRootRedirectsToIndexHTML515=== RUN TestReadProxyDisabled516=== PAUSE TestReadProxyDisabled517=== RUN TestReadRedirectNar518=== PAUSE TestReadRedirectNar519=== RUN TestReadRedirectKeepsNarinfoProxied520=== PAUSE TestReadRedirectKeepsNarinfoProxied521=== RUN TestReadProxyRangeRequest522=== PAUSE TestReadProxyRangeRequest523=== RUN TestReadRedirectUsesPublicS3URL524=== PAUSE TestReadRedirectUsesPublicS3URL525=== RUN TestRedundantMultipartUpload526=== PAUSE TestRedundantMultipartUpload527=== RUN TestCompleteMultipartUpload_ErrorButObjectExists528=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists529=== RUN TestCompletedNarNotReofferedAcrossClosures530=== PAUSE TestCompletedNarNotReofferedAcrossClosures531=== RUN TestPresignedUploadRegisteredBeforeCommit532=== PAUSE TestPresignedUploadRegisteredBeforeCommit533=== RUN TestService_Rustfstest534=== PAUSE TestService_Rustfstest535=== RUN TestParseSize536=== PAUSE TestParseSize537=== RUN TestSkippedUploadsHandler538=== PAUSE TestSkippedUploadsHandler539=== RUN TestSystemdListenerNotActivated540--- PASS: TestSystemdListenerNotActivated (0.00s)541=== RUN TestWatchdogBeatsWhenHealthy542--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)543=== RUN TestWatchdogSkipsWhenUnhealthy5442026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5452026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5462026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5472026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5482026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5492026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5502026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5512026/09/09 10:29:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5522026/09/09 10:29:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5532026/09/09 10:29:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"554--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)555=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle556=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle557=== RUN TestProxyWriteTimeout558=== PAUSE TestProxyWriteTimeout559=== RUN TestIsValidUploadKey560=== PAUSE TestIsValidUploadKey561=== RUN TestUploadHandlersRejectInvalidKeys562=== PAUSE TestUploadHandlersRejectInvalidKeys563=== RUN TestUploadHandlersRejectOversizedBody564=== PAUSE TestUploadHandlersRejectOversizedBody565=== RUN TestService_cleanupPendingClosuresHandler566=== PAUSE TestService_cleanupPendingClosuresHandler567=== RUN TestService_createPendingClosureHandler568=== PAUSE TestService_createPendingClosureHandler569=== RUN TestService_verifyS3Integrity570=== PAUSE TestService_verifyS3Integrity571=== RUN TestCompleteMultipartUnregistered572=== PAUSE TestCompleteMultipartUnregistered573=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT574=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT575=== CONT TestService_AuthMiddleware576=== CONT TestObjectStatsTrigger577=== CONT TestService_readinessHandler578=== CONT TestGCTaskStore_DeduplicateSameParams579=== CONT TestGCTaskStore_PhaseUpdates580--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)581=== CONT TestGCTaskStore_CompletedAllowsNewTask582--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)583--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)584=== CONT TestGCTaskStore_GetReturnsLatest585--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)586=== CONT TestGCTaskStore_GetEmpty587--- PASS: TestGCTaskStore_GetEmpty (0.00s)588=== CONT TestServerTLSConfig589=== CONT TestGCTaskStore_ConflictDifferentParams590--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)591=== RUN TestServerTLSConfig/no_client_CA592=== CONT TestService_NativeMTLS593=== PAUSE TestServerTLSConfig/no_client_CA594=== RUN TestServerTLSConfig/missing_CA_file595=== PAUSE TestServerTLSConfig/missing_CA_file596=== RUN TestServerTLSConfig/not_a_PEM_file597=== CONT TestService_healthCheckHandler598=== CONT TestGCTaskStore_Fail599=== CONT TestMetricsInventory600--- PASS: TestGCTaskStore_Fail (0.00s)601=== CONT TestClientErrorHandling602=== CONT TestMultipartCleanup603=== CONT TestGracefulShutdownDrainsInflight604=== PAUSE TestServerTLSConfig/not_a_PEM_file605=== RUN TestClientErrorHandling/InvalidStorePath606=== CONT TestGCTaskStore_StartNew607--- PASS: TestGCTaskStore_StartNew (0.00s)608=== PAUSE TestClientErrorHandling/InvalidStorePath609=== CONT TestGCMetrics610=== RUN TestClientErrorHandling/InvalidAuthToken611=== PAUSE TestClientErrorHandling/InvalidAuthToken612=== RUN TestClientErrorHandling/ServerNotAvailable613=== PAUSE TestClientErrorHandling/ServerNotAvailable614=== CONT TestGCBugBareHashReferences6152026/09/09 10:29:45 INFO Starting HTTP server address=127.0.0.1:611566162026/09/09 10:29:45 INFO Shutdown signal received, draining in-flight requests timeout=10s617--- PASS: TestGracefulShutdownDrainsInflight (0.08s)618=== CONT TestResolveDBConnectionString619=== RUN TestResolveDBConnectionString/flag_wins620=== PAUSE TestResolveDBConnectionString/flag_wins621=== RUN TestResolveDBConnectionString/file_when_flag_empty622=== PAUSE TestResolveDBConnectionString/file_when_flag_empty623=== RUN TestResolveDBConnectionString/missing_file_is_an_error624=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error625=== RUN TestResolveDBConnectionString/PGHOST_allows_empty626=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty627=== RUN TestResolveDBConnectionString/nothing_configured628=== PAUSE TestResolveDBConnectionString/nothing_configured629=== CONT TestPinProtectsFromGC6302026-09-09 10:29:45.338 UTC [24734] ERROR: relation "goose_db_version" does not exist at character 366312026-09-09 10:29:45.338 UTC [24734] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6322026-09-09 10:29:45.339 UTC [24735] ERROR: relation "goose_db_version" does not exist at character 366332026-09-09 10:29:45.339 UTC [24735] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6342026-09-09 10:29:45.340 UTC [24737] ERROR: relation "goose_db_version" does not exist at character 366352026-09-09 10:29:45.340 UTC [24737] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6362026-09-09 10:29:45.340 UTC [24736] ERROR: relation "goose_db_version" does not exist at character 366372026-09-09 10:29:45.340 UTC [24736] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6382026-09-09 10:29:45.347 UTC [24738] ERROR: relation "goose_db_version" does not exist at character 366392026-09-09 10:29:45.347 UTC [24738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6402026-09-09 10:29:45.347 UTC [24740] ERROR: relation "goose_db_version" does not exist at character 366412026-09-09 10:29:45.347 UTC [24740] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6422026-09-09 10:29:45.348 UTC [24739] ERROR: relation "goose_db_version" does not exist at character 366432026-09-09 10:29:45.348 UTC [24739] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6442026-09-09 10:29:45.351 UTC [24742] ERROR: relation "goose_db_version" does not exist at character 366452026-09-09 10:29:45.351 UTC [24742] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6462026-09-09 10:29:45.351 UTC [24741] ERROR: relation "goose_db_version" does not exist at character 366472026-09-09 10:29:45.351 UTC [24741] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6482026-09-09 10:29:45.351 UTC [24743] ERROR: relation "goose_db_version" does not exist at character 366492026-09-09 10:29:45.351 UTC [24743] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6502026/09/09 10:29:45 OK 20241026095416_initial_model.sql (5.52ms)6512026/09/09 10:29:45 OK 20241026095416_initial_model.sql (5.73ms)6522026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (973.46µs)6532026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (599.67µs)6542026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.84ms)6552026/09/09 10:29:45 OK 20241026095416_initial_model.sql (8.57ms)6562026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.9ms)6572026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (721.46µs)6582026/09/09 10:29:45 OK 20241026095416_initial_model.sql (8.05ms)6592026/09/09 10:29:45 OK 20241026095416_initial_model.sql (5.64ms)6602026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (1.45ms)6612026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200006622026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (574.04µs)6632026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (786.96µs)6642026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.21ms)6652026/09/09 10:29:45 OK 1_commit_pending_closure.sql (1.23ms)6662026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (2.48ms)6672026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200006682026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.26ms)6692026/09/09 10:29:45 OK 2_object_stats_trigger.sql (571.58µs)6702026/09/09 10:29:45 goose: up to current file version: 26712026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (1.48ms)6722026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200006732026/09/09 10:29:45 OK 20241026095416_initial_model.sql (7.04ms)6742026/09/09 10:29:45 OK 20241026095416_initial_model.sql (7.59ms)6752026/09/09 10:29:45 OK 20251218171726_add_pins.sql (2.04ms)6762026/09/09 10:29:45 OK 1_commit_pending_closure.sql (1.64ms)6772026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (857.71µs)6782026/09/09 10:29:45 OK 1_commit_pending_closure.sql (1.1ms)6792026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (853.54µs)6802026/09/09 10:29:45 OK 2_object_stats_trigger.sql (654.92µs)6812026/09/09 10:29:45 goose: up to current file version: 26822026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (2.12ms)6832026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200006842026/09/09 10:29:45 OK 2_object_stats_trigger.sql (468.21µs)6852026/09/09 10:29:45 goose: up to current file version: 26862026/09/09 10:29:45 OK 20241026095416_initial_model.sql (6.45ms)6872026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (1.4ms)6882026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200006892026/09/09 10:29:45 OK 20241026095416_initial_model.sql (6.19ms)6902026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.7ms)6912026/09/09 10:29:45 OK 1_commit_pending_closure.sql (1.02ms)6922026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.66ms)6932026/09/09 10:29:45 OK 2_object_stats_trigger.sql (279.13µs)6942026/09/09 10:29:45 goose: up to current file version: 26952026/09/09 10:29:45 OK 1_commit_pending_closure.sql (1.27ms)6962026/09/09 10:29:45 OK 2_object_stats_trigger.sql (191.88µs)6972026/09/09 10:29:45 goose: up to current file version: 26982026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (5.57ms)6992026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (5.61ms)7002026/09/09 10:29:45 OK 20241026095416_initial_model.sql (11.07ms)7012026/09/09 10:29:45 OK 20251210153512_drop_unused_gin_index.sql (457.29µs)7022026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.19ms)7032026/09/09 10:29:45 OK 20251218171726_add_pins.sql (1.13ms)7042026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (6.38ms)7052026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200007062026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (6.71ms)7072026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200007082026/09/09 10:29:45 OK 20251218171726_add_pins.sql (828.17µs)7092026/09/09 10:29:45 OK 1_commit_pending_closure.sql (74.82ms)7102026/09/09 10:29:45 OK 1_commit_pending_closure.sql (74.97ms)7112026/09/09 10:29:45 OK 2_object_stats_trigger.sql (239.38µs)7122026/09/09 10:29:45 goose: up to current file version: 27132026/09/09 10:29:45 OK 2_object_stats_trigger.sql (254.46µs)7142026/09/09 10:29:45 goose: up to current file version: 27152026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (80.35ms)7162026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200007172026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (80.8ms)7182026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200007192026/09/09 10:29:45 OK 20260628120000_add_object_size_and_stats.sql (80.56ms)7202026/09/09 10:29:45 goose: successfully migrated database to version: 202606281200007212026/09/09 10:29:45 OK 1_commit_pending_closure.sql (1.37ms)7222026/09/09 10:29:45 OK 1_commit_pending_closure.sql (952.96µs)7232026/09/09 10:29:45 OK 2_object_stats_trigger.sql (221.63µs)7242026/09/09 10:29:45 goose: up to current file version: 27252026/09/09 10:29:45 OK 2_object_stats_trigger.sql (230.38µs)7262026/09/09 10:29:45 goose: up to current file version: 27272026/09/09 10:29:45 OK 1_commit_pending_closure.sql (7.78ms)7282026/09/09 10:29:45 OK 2_object_stats_trigger.sql (223.54µs)7292026/09/09 10:29:45 goose: up to current file version: 27302026/09/09 10:29:45 INFO Received uploads request method=POST path=/api/pending_closures7312026/09/09 10:29:45 INFO Received cleanup request method=DELETE path=/api/pending_closures7322026/09/09 10:29:45 INFO Aborted multipart uploads count=07332026/09/09 10:29:45 INFO Aborted multipart uploads count=17342026/09/09 10:29:45 WARN Force mode enabled - objects will be deleted immediately without grace period7352026/09/09 10:29:45 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=07362026/09/09 10:29:45 INFO Vacuumed table table=pending_closures7372026/09/09 10:29:45 INFO Vacuumed table table=pending_objects738--- PASS: TestMultipartCleanup (0.65s)739=== CONT TestClientWithDependencies7402026/09/09 10:29:45 INFO Vacuumed table table=multipart_uploads7412026/09/09 10:29:45 INFO Vacuumed table table=closures7422026/09/09 10:29:45 INFO Vacuumed table table=objects743--- PASS: TestGCMetrics (0.66s)744=== CONT TestClientMultipleUploads745--- PASS: TestMetricsInventory (0.79s)746=== CONT TestClientIntegration7472026/09/09 10:29:45 WARN readiness check failed error="closed pool"748--- PASS: TestService_readinessHandler (0.89s)749=== CONT TestService_RequireScope_OIDC7502026/09/09 10:29:45 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61168/oidc7512026/09/09 10:29:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"7522026/09/09 10:29:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"753--- PASS: TestService_NativeMTLS (1.21s)754=== CONT TestClientCADerivations7552026-09-09 10:29:46.277 UTC [24754] ERROR: relation "goose_db_version" does not exist at character 367562026-09-09 10:29:46.277 UTC [24754] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7572026-09-09 10:29:46.277 UTC [24755] ERROR: relation "goose_db_version" does not exist at character 367582026-09-09 10:29:46.277 UTC [24755] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC759--- PASS: TestGCBugBareHashReferences (1.26s)760=== CONT TestCacheStatsHandler7612026-09-09 10:29:46.338 UTC [24759] ERROR: relation "goose_db_version" does not exist at character 367622026-09-09 10:29:46.338 UTC [24759] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026/09/09 10:29:46 OK 20241026095416_initial_model.sql (51.88ms)7642026/09/09 10:29:46 OK 20241026095416_initial_model.sql (44.09ms)7652026/09/09 10:29:46 OK 20251210153512_drop_unused_gin_index.sql (8.19ms)7662026/09/09 10:29:46 OK 20251210153512_drop_unused_gin_index.sql (8.18ms)7672026/09/09 10:29:46 OK 20251218171726_add_pins.sql (14.55ms)7682026/09/09 10:29:46 OK 20251218171726_add_pins.sql (14.6ms)7692026/09/09 10:29:46 OK 20260628120000_add_object_size_and_stats.sql (15ms)7702026/09/09 10:29:46 goose: successfully migrated database to version: 202606281200007712026/09/09 10:29:46 OK 20260628120000_add_object_size_and_stats.sql (15.07ms)7722026/09/09 10:29:46 goose: successfully migrated database to version: 202606281200007732026/09/09 10:29:46 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"774--- PASS: TestService_AuthMiddleware (1.37s)775=== CONT TestCacheConfigHandler776=== RUN TestCacheConfigHandler/full_config,_no_issuer777=== PAUSE TestCacheConfigHandler/full_config,_no_issuer778=== RUN TestCacheConfigHandler/no_cache_url_configured779=== PAUSE TestCacheConfigHandler/no_cache_url_configured780=== RUN TestCacheConfigHandler/no_signing_keys781=== PAUSE TestCacheConfigHandler/no_signing_keys782=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator783=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator784=== CONT TestService_ReadScope_PublicByDefault7852026/09/09 10:29:46 OK 1_commit_pending_closure.sql (15.94ms)7862026/09/09 10:29:46 OK 1_commit_pending_closure.sql (17.49ms)7872026/09/09 10:29:46 OK 2_object_stats_trigger.sql (2.81ms)7882026/09/09 10:29:46 goose: up to current file version: 27892026/09/09 10:29:46 OK 2_object_stats_trigger.sql (4.96ms)7902026/09/09 10:29:46 goose: up to current file version: 27912026/09/09 10:29:46 OK 20241026095416_initial_model.sql (38.62ms)7922026/09/09 10:29:46 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)7932026/09/09 10:29:46 OK 20251218171726_add_pins.sql (11.45ms)7942026/09/09 10:29:46 OK 20260628120000_add_object_size_and_stats.sql (14.19ms)7952026/09/09 10:29:46 goose: successfully migrated database to version: 202606281200007962026/09/09 10:29:46 OK 1_commit_pending_closure.sql (1.9ms)7972026/09/09 10:29:46 OK 2_object_stats_trigger.sql (462.54µs)7982026/09/09 10:29:46 goose: up to current file version: 27992026-09-09 10:29:46.450 UTC [24762] ERROR: relation "goose_db_version" does not exist at character 368002026-09-09 10:29:46.450 UTC [24762] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC801--- PASS: TestService_healthCheckHandler (1.49s)802=== CONT TestCreatePendingClosureRejectsOversizedNAR8032026/09/09 10:29:46 INFO Received uploads request method=POST path=/api/pending_closures804--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)805=== CONT TestNARDeduplicationMetadataUploadBug8062026/09/09 10:29:46 OK 20241026095416_initial_model.sql (80.72ms)8072026/09/09 10:29:46 OK 20251210153512_drop_unused_gin_index.sql (6.61ms)8082026/09/09 10:29:46 OK 20251218171726_add_pins.sql (10.79ms)8092026/09/09 10:29:46 OK 20260628120000_add_object_size_and_stats.sql (12.88ms)8102026/09/09 10:29:46 goose: successfully migrated database to version: 202606281200008112026/09/09 10:29:46 OK 1_commit_pending_closure.sql (2.06ms)8122026/09/09 10:29:46 OK 2_object_stats_trigger.sql (404.25µs)8132026/09/09 10:29:46 goose: up to current file version: 28142026-09-09 10:29:46.808 UTC [24768] ERROR: relation "goose_db_version" does not exist at character 368152026-09-09 10:29:46.808 UTC [24768] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC816--- PASS: TestObjectStatsTrigger (1.79s)817=== CONT TestReadRedirectUsesPublicS3URL818=== NAME TestPinProtectsFromGC819 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-24452-4259264778/TestPinProtectsFromGC372202969/001/store/j8xd6wbv4w3x81qywayhxmd6726xmb0g-pinned-file.txt820 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-24452-4259264778/TestPinProtectsFromGC372202969/001/store/yzxa3hpr4n8j43by4vgm1g66p1wb6h7n-unpinned-file.txt8212026/09/09 10:29:46 OK 20241026095416_initial_model.sql (43.18ms)8222026/09/09 10:29:46 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)8232026-09-09 10:29:46.879 UTC [24773] ERROR: relation "goose_db_version" does not exist at character 368242026-09-09 10:29:46.879 UTC [24773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026/09/09 10:29:46 OK 20251218171726_add_pins.sql (6.21ms)8262026/09/09 10:29:46 OK 20260628120000_add_object_size_and_stats.sql (15.66ms)8272026/09/09 10:29:46 goose: successfully migrated database to version: 202606281200008282026/09/09 10:29:46 OK 1_commit_pending_closure.sql (5.64ms)8292026/09/09 10:29:46 OK 2_object_stats_trigger.sql (228.71µs)8302026/09/09 10:29:46 goose: up to current file version: 28312026/09/09 10:29:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8322026/09/09 10:29:46 OK 20241026095416_initial_model.sql (43.56ms)8332026/09/09 10:29:46 OK 20251210153512_drop_unused_gin_index.sql (1.12ms)8342026/09/09 10:29:46 INFO Received uploads request method=POST path=/api/pending_closures8352026/09/09 10:29:46 OK 20251218171726_add_pins.sql (20.21ms)8362026/09/09 10:29:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8372026/09/09 10:29:46 INFO Uploading j8xd6wbv4w3x81qywayhxmd6726xmb0g-pinned-file.txt (128B)8382026/09/09 10:29:46 OK 20260628120000_add_object_size_and_stats.sql (7.16ms)8392026/09/09 10:29:46 goose: successfully migrated database to version: 202606281200008402026/09/09 10:29:46 OK 1_commit_pending_closure.sql (1.75ms)8412026/09/09 10:29:46 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"8422026/09/09 10:29:46 OK 2_object_stats_trigger.sql (272.38µs)8432026/09/09 10:29:46 goose: up to current file version: 28442026/09/09 10:29:46 WARN Failed to register uploaded object key=j8xd6wbv4w3x81qywayhxmd6726xmb0g.ls error="server returned 404: 404 page not found\n"8452026/09/09 10:29:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8462026/09/09 10:29:46 INFO Signed narinfos id=1 count=18472026/09/09 10:29:46 INFO Uploading 1 narinfos8482026/09/09 10:29:46 WARN Failed to register uploaded object key=j8xd6wbv4w3x81qywayhxmd6726xmb0g.narinfo error="server returned 404: 404 page not found\n"8492026/09/09 10:29:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8502026/09/09 10:29:47 INFO Completed upload id=18512026/09/09 10:29:47 INFO Upload complete. (130ms)8522026-09-09 10:29:47.058 UTC [24786] ERROR: relation "goose_db_version" does not exist at character 368532026-09-09 10:29:47.058 UTC [24786] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8542026/09/09 10:29:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8552026/09/09 10:29:47 OK 20241026095416_initial_model.sql (27.34ms)8562026/09/09 10:29:47 OK 20251210153512_drop_unused_gin_index.sql (7.01ms)8572026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures8582026/09/09 10:29:47 OK 20251218171726_add_pins.sql (43.27ms)8592026/09/09 10:29:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8602026/09/09 10:29:47 INFO Uploading yzxa3hpr4n8j43by4vgm1g66p1wb6h7n-unpinned-file.txt (128B)8612026-09-09 10:29:47.156 UTC [24793] ERROR: relation "goose_db_version" does not exist at character 368622026-09-09 10:29:47.156 UTC [24793] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8632026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"8642026/09/09 10:29:47 WARN Failed to register uploaded object key=yzxa3hpr4n8j43by4vgm1g66p1wb6h7n.ls error="server returned 404: 404 page not found\n"8652026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign8662026/09/09 10:29:47 INFO Signed narinfos id=2 count=18672026/09/09 10:29:47 INFO Uploading 1 narinfos8682026/09/09 10:29:47 OK 20260628120000_add_object_size_and_stats.sql (17.48ms)8692026/09/09 10:29:47 goose: successfully migrated database to version: 20260628120000870=== NAME TestClientMultipleUploads871 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-24452-4259264778/TestClientMultipleUploads2653091975/001/store/z6mlmiic1ry34p6a6xk6vvn5k9842swx-test-file-0.txt872=== NAME TestClientWithDependencies873 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-24452-4259264778/TestClientWithDependencies2572304900/001/store/cbgm4z0k07kamjjfj4sgrd05da7k22zn-test-script8742026/09/09 10:29:47 WARN Failed to register uploaded object key=yzxa3hpr4n8j43by4vgm1g66p1wb6h7n.narinfo error="server returned 404: 404 page not found\n"8752026/09/09 10:29:47 OK 1_commit_pending_closure.sql (6.63ms)8762026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8772026/09/09 10:29:47 OK 2_object_stats_trigger.sql (844.75µs)8782026/09/09 10:29:47 goose: up to current file version: 28792026/09/09 10:29:47 INFO Completed upload id=28802026/09/09 10:29:47 INFO Upload complete. (135ms)8812026/09/09 10:29:47 INFO Received create pin request method=POST path=/api/pins/myapp8822026/09/09 10:29:47 OK 20241026095416_initial_model.sql (33.88ms)883 client_integration_test.go:596: Found 1 dependencies (including self)8842026/09/09 10:29:47 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-24452-4259264778/TestPinProtectsFromGC372202969/001/store/j8xd6wbv4w3x81qywayhxmd6726xmb0g-pinned-file.txt narinfo_key=j8xd6wbv4w3x81qywayhxmd6726xmb0g.narinfo8852026/09/09 10:29:47 OK 20251210153512_drop_unused_gin_index.sql (4.81ms)8862026/09/09 10:29:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures8872026/09/09 10:29:47 INFO Garbage collection started8882026/09/09 10:29:47 INFO Aborted multipart uploads count=08892026/09/09 10:29:47 WARN Force mode enabled - objects will be deleted immediately without grace period8902026/09/09 10:29:47 OK 20251218171726_add_pins.sql (15.81ms)891=== NAME TestClientMultipleUploads892 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-24452-4259264778/TestClientMultipleUploads2653091975/001/store/30sd08cfgjm9h40klmi880v0a2qd0ad5-test-file-1.txt8932026/09/09 10:29:47 OK 20260628120000_add_object_size_and_stats.sql (2.59ms)8942026/09/09 10:29:47 goose: successfully migrated database to version: 202606281200008952026/09/09 10:29:47 OK 1_commit_pending_closure.sql (1.68ms)8962026/09/09 10:29:47 OK 2_object_stats_trigger.sql (333.42µs)8972026/09/09 10:29:47 goose: up to current file version: 2898 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-24452-4259264778/TestClientMultipleUploads2653091975/001/store/7fbmwd43v8xr1qbifkrbxn80ippvv8gy-test-file-2.txt8992026/09/09 10:29:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9002026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures9012026/09/09 10:29:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9022026/09/09 10:29:47 INFO Uploading cbgm4z0k07kamjjfj4sgrd05da7k22zn-test-script (136B)9032026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"9042026/09/09 10:29:47 WARN Failed to register uploaded object key=log/gfc8x4n0f7r6mhapm90m4ivkp45wr7z2-test-script.drv error="server returned 404: 404 page not found\n"9052026/09/09 10:29:47 WARN Failed to register uploaded object key=cbgm4z0k07kamjjfj4sgrd05da7k22zn.ls error="server returned 404: 404 page not found\n"9062026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9072026/09/09 10:29:47 INFO Signed narinfos id=1 count=1908=== NAME TestClientIntegration909 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-24452-4259264778/TestClientIntegration3178619489/002/store/w3xydjryjhgxa6dwqi4ii9m3dj3gs8dd-test-file.txt9102026/09/09 10:29:47 INFO Uploading 1 narinfos9112026/09/09 10:29:47 WARN Failed to register uploaded object key=cbgm4z0k07kamjjfj4sgrd05da7k22zn.narinfo error="server returned 404: 404 page not found\n"9122026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9132026-09-09 10:29:47.326 UTC [24812] ERROR: relation "goose_db_version" does not exist at character 369142026-09-09 10:29:47.326 UTC [24812] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9152026/09/09 10:29:47 INFO Completed upload id=19162026/09/09 10:29:47 INFO Upload complete. (94ms)917=== NAME TestClientWithDependencies918 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-24452-4259264778/TestClientWithDependencies2572304900/001/store) requires matching store prefix9192026/09/09 10:29:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"920--- PASS: TestClientWithDependencies (1.67s)921=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT922=== RUN TestService_RequireScope_OIDC/builder_may_write923=== PAUSE TestService_RequireScope_OIDC/builder_may_write924=== RUN TestService_RequireScope_OIDC/builder_may_not_admin925=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin926=== RUN TestService_RequireScope_OIDC/ops_may_admin927=== PAUSE TestService_RequireScope_OIDC/ops_may_admin928=== RUN TestService_RequireScope_OIDC/ops_may_not_write929=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write930=== RUN TestService_RequireScope_OIDC/reader_may_not_write931=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write932=== RUN TestService_RequireScope_OIDC/static_token_may_admin933=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin934=== RUN TestService_RequireScope_OIDC/static_token_may_write935=== PAUSE TestService_RequireScope_OIDC/static_token_may_write936=== RUN TestService_RequireScope_OIDC/reader_may_read937=== PAUSE TestService_RequireScope_OIDC/reader_may_read938=== RUN TestService_RequireScope_OIDC/writer_implies_read939=== PAUSE TestService_RequireScope_OIDC/writer_implies_read940=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read941=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read942=== CONT TestCompleteMultipartUnregistered9432026/09/09 10:29:47 OK 20241026095416_initial_model.sql (28.82ms)9442026/09/09 10:29:47 OK 20251210153512_drop_unused_gin_index.sql (5ms)9452026/09/09 10:29:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9462026/09/09 10:29:47 OK 20251218171726_add_pins.sql (7.83ms)9472026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures9482026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures9492026/09/09 10:29:47 OK 20260628120000_add_object_size_and_stats.sql (8.42ms)9502026/09/09 10:29:47 goose: successfully migrated database to version: 202606281200009512026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures9522026/09/09 10:29:47 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9532026/09/09 10:29:47 INFO Uploading z6mlmiic1ry34p6a6xk6vvn5k9842swx-test-file-0.txt (160B)9542026/09/09 10:29:47 INFO Uploading 30sd08cfgjm9h40klmi880v0a2qd0ad5-test-file-1.txt (160B)9552026/09/09 10:29:47 INFO Uploading 7fbmwd43v8xr1qbifkrbxn80ippvv8gy-test-file-2.txt (160B)9562026/09/09 10:29:47 OK 1_commit_pending_closure.sql (8.22ms)9572026/09/09 10:29:47 OK 2_object_stats_trigger.sql (231.21µs)9582026/09/09 10:29:47 goose: up to current file version: 29592026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"9602026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"9612026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9622026/09/09 10:29:47 WARN Failed to register uploaded object key=z6mlmiic1ry34p6a6xk6vvn5k9842swx.ls error="server returned 404: 404 page not found\n"9632026/09/09 10:29:47 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=09642026/09/09 10:29:47 WARN Failed to register uploaded object key=7fbmwd43v8xr1qbifkrbxn80ippvv8gy.ls error="server returned 404: 404 page not found\n"9652026/09/09 10:29:47 WARN Failed to register uploaded object key=30sd08cfgjm9h40klmi880v0a2qd0ad5.ls error="server returned 404: 404 page not found\n"9662026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9672026/09/09 10:29:47 INFO Signed narinfos id=1 count=19682026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9692026/09/09 10:29:47 INFO Signed narinfos id=2 count=19702026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign9712026/09/09 10:29:47 INFO Signed narinfos id=3 count=19722026/09/09 10:29:47 INFO Uploading 3 narinfos9732026/09/09 10:29:47 INFO Vacuumed table table=pending_closures9742026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures9752026/09/09 10:29:47 WARN Failed to register uploaded object key=z6mlmiic1ry34p6a6xk6vvn5k9842swx.narinfo error="server returned 404: 404 page not found\n"9762026/09/09 10:29:47 WARN Failed to register uploaded object key=30sd08cfgjm9h40klmi880v0a2qd0ad5.narinfo error="server returned 404: 404 page not found\n"9772026/09/09 10:29:47 INFO Vacuumed table table=pending_objects9782026/09/09 10:29:47 WARN Failed to register uploaded object key=7fbmwd43v8xr1qbifkrbxn80ippvv8gy.narinfo error="server returned 404: 404 page not found\n"9792026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9802026/09/09 10:29:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9812026/09/09 10:29:47 INFO Uploading w3xydjryjhgxa6dwqi4ii9m3dj3gs8dd-test-file.txt (152B)9822026/09/09 10:29:47 INFO Vacuumed table table=multipart_uploads9832026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"9842026/09/09 10:29:47 INFO Vacuumed table table=closures9852026/09/09 10:29:47 INFO Completed upload id=19862026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9872026/09/09 10:29:47 WARN Failed to register uploaded object key=w3xydjryjhgxa6dwqi4ii9m3dj3gs8dd.ls error="server returned 404: 404 page not found\n"9882026/09/09 10:29:47 INFO Completed upload id=29892026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9902026/09/09 10:29:47 INFO Vacuumed table table=objects9912026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete9922026/09/09 10:29:47 INFO Signed narinfos id=1 count=19932026/09/09 10:29:47 INFO Uploading 1 narinfos9942026/09/09 10:29:47 INFO Completed upload id=39952026/09/09 10:29:47 INFO Upload complete. (145ms)996=== NAME TestClientMultipleUploads997 client_integration_test.go:350: Uploaded 3 paths in 181.58525ms9982026/09/09 10:29:47 WARN Failed to register uploaded object key=w3xydjryjhgxa6dwqi4ii9m3dj3gs8dd.narinfo error="server returned 404: 404 page not found\n"9992026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10002026/09/09 10:29:47 INFO Completed upload id=110012026/09/09 10:29:47 INFO Upload complete. (119ms)1002=== NAME TestClientIntegration1003 client_integration_test.go:293: Retrieved narinfo from S3:1004 StorePath: /nix/var/nix/builds/nix-24452-4259264778/TestClientIntegration3178619489/002/store/w3xydjryjhgxa6dwqi4ii9m3dj3gs8dd-test-file.txt1005 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1006 Compression: zstd1007 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11008 NarSize: 1521009 References: 1010 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11011 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1012 client_integration_test.go:294: Decompressed .ls content (64 bytes):1013 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1014 client_integration_test.go:297: Testing garbage collection...1015--- PASS: TestClientMultipleUploads (1.79s)1016=== CONT TestService_verifyS3Integrity10172026/09/09 10:29:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures10182026/09/09 10:29:47 INFO Garbage collection started10192026/09/09 10:29:47 INFO Aborted multipart uploads count=010202026/09/09 10:29:47 WARN Force mode enabled - objects will be deleted immediately without grace period1021--- PASS: TestCacheStatsHandler (1.33s)1022=== CONT TestService_createPendingClosureHandler10232026/09/09 10:29:47 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=010242026/09/09 10:29:47 INFO Vacuumed table table=pending_closures10252026/09/09 10:29:47 INFO Vacuumed table table=pending_objects1026--- PASS: TestService_ReadScope_PublicByDefault (1.32s)1027=== CONT TestService_cleanupPendingClosuresHandler10282026/09/09 10:29:47 INFO Vacuumed table table=multipart_uploads10292026/09/09 10:29:47 INFO Vacuumed table table=closures10302026/09/09 10:29:47 INFO Vacuumed table table=objects1031=== NAME TestClientCADerivations1032 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-24452-4259264778/TestClientCADerivations2811616552/001/store/n8n9rk6rlbk2z3bcfnnpf9wvj97whv29-ca-test1033 client_ca_test.go:139: Found 1 dependencies (including self)10342026-09-09 10:29:47.819 UTC [24846] ERROR: relation "goose_db_version" does not exist at character 3610352026-09-09 10:29:47.819 UTC [24846] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10362026/09/09 10:29:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10372026/09/09 10:29:47 OK 20241026095416_initial_model.sql (35.69ms)10382026/09/09 10:29:47 INFO Received uploads request method=POST path=/api/pending_closures10392026/09/09 10:29:47 OK 20251210153512_drop_unused_gin_index.sql (5.34ms)10402026/09/09 10:29:47 OK 20251218171726_add_pins.sql (6.01ms)10412026/09/09 10:29:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10422026/09/09 10:29:47 INFO Uploading n8n9rk6rlbk2z3bcfnnpf9wvj97whv29-ca-test (144B)10432026/09/09 10:29:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"10442026/09/09 10:29:47 WARN Failed to register uploaded object key=log/p72c1zabgnlckza7ahxqppygwr1d0mys-ca-test.drv error="server returned 404: 404 page not found\n"10452026/09/09 10:29:47 OK 20260628120000_add_object_size_and_stats.sql (14.94ms)10462026/09/09 10:29:47 goose: successfully migrated database to version: 2026062812000010472026-09-09 10:29:47.909 UTC [24852] ERROR: relation "goose_db_version" does not exist at character 3610482026-09-09 10:29:47.909 UTC [24852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10492026/09/09 10:29:47 WARN Failed to register uploaded object key=n8n9rk6rlbk2z3bcfnnpf9wvj97whv29.ls error="server returned 404: 404 page not found\n"10502026/09/09 10:29:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10512026/09/09 10:29:47 INFO Signed narinfos id=1 count=110522026/09/09 10:29:47 INFO Uploading 1 narinfos10532026/09/09 10:29:47 OK 1_commit_pending_closure.sql (1.18ms)10542026/09/09 10:29:47 OK 2_object_stats_trigger.sql (670.79µs)10552026/09/09 10:29:47 goose: up to current file version: 210562026/09/09 10:29:47 WARN Failed to register uploaded object key=n8n9rk6rlbk2z3bcfnnpf9wvj97whv29.narinfo error="server returned 404: 404 page not found\n"10572026/09/09 10:29:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10582026/09/09 10:29:47 INFO Completed upload id=110592026/09/09 10:29:47 INFO Upload complete. (128ms)1060 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-24452-4259264778/TestClientCADerivations2811616552/001/store/n8n9rk6rlbk2z3bcfnnpf9wvj97whv29-ca-test1061 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1062 Compression: zstd1063 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1064 NarSize: 1441065 References: 1066 Deriver: /nix/var/nix/builds/nix-24452-4259264778/TestClientCADerivations2811616552/001/store/p72c1zabgnlckza7ahxqppygwr1d0mys-ca-test.drv1067 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1068 client_ca_test.go:185: Checking for realisation files in S3...1069 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1070 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1071=== NAME TestNARDeduplicationMetadataUploadBug1072 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-24452-4259264778/TestNARDeduplicationMetadataUploadBug613393386/001/store/5aqahzngcnh1c0rh7p8yfi0djplnncbn-file1.txt1073=== NAME TestClientCADerivations1074 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket16?endpoint=http://localhost:61113®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-24452-4259264778/TestClientCADerivations2811616552/001/store'1075 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 110762026/09/09 10:29:48 OK 20241026095416_initial_model.sql (59.64ms)10772026/09/09 10:29:48 OK 20251210153512_drop_unused_gin_index.sql (7.18ms)10782026/09/09 10:29:48 OK 20251218171726_add_pins.sql (12.86ms)1079--- PASS: TestClientCADerivations (1.78s)1080=== CONT TestUploadHandlersRejectOversizedBody10812026/09/09 10:29:48 OK 20260628120000_add_object_size_and_stats.sql (8.13ms)10822026/09/09 10:29:48 goose: successfully migrated database to version: 2026062812000010832026/09/09 10:29:48 OK 1_commit_pending_closure.sql (1.17ms)10842026/09/09 10:29:48 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10852026/09/09 10:29:48 OK 2_object_stats_trigger.sql (1.11ms)10862026/09/09 10:29:48 goose: up to current file version: 21087=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1088=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1089=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1090=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1091=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1092=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1093=== CONT TestUploadHandlersRejectInvalidKeys1094=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1095=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1096=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1097=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1098=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1099=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1100=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1101=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1102=== CONT TestIsValidUploadKey1103=== RUN TestIsValidUploadKey/narinfo1104=== PAUSE TestIsValidUploadKey/narinfo1105=== RUN TestIsValidUploadKey/nar_zst1106=== PAUSE TestIsValidUploadKey/nar_zst1107=== RUN TestIsValidUploadKey/nar_xz1108=== PAUSE TestIsValidUploadKey/nar_xz1109=== RUN TestIsValidUploadKey/nar_plain1110=== PAUSE TestIsValidUploadKey/nar_plain1111=== RUN TestIsValidUploadKey/listing1112=== PAUSE TestIsValidUploadKey/listing1113=== RUN TestIsValidUploadKey/build_log1114=== PAUSE TestIsValidUploadKey/build_log1115=== RUN TestIsValidUploadKey/build_log_home-manager_file1116=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1117=== RUN TestIsValidUploadKey/build_log_plus_in_name1118=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1119=== RUN TestIsValidUploadKey/build_log_question_mark1120=== PAUSE TestIsValidUploadKey/build_log_question_mark1121=== RUN TestIsValidUploadKey/build_log_equals1122=== PAUSE TestIsValidUploadKey/build_log_equals1123=== RUN TestIsValidUploadKey/realisation1124=== PAUSE TestIsValidUploadKey/realisation1125=== RUN TestIsValidUploadKey/realisation_plus_in_output1126=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1127=== RUN TestIsValidUploadKey/nix-cache-info1128=== PAUSE TestIsValidUploadKey/nix-cache-info1129=== RUN TestIsValidUploadKey/index.html1130=== PAUSE TestIsValidUploadKey/index.html1131=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1132=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1133=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1134=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1135=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1136=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1137=== RUN TestIsValidUploadKey/traversal1138=== PAUSE TestIsValidUploadKey/traversal1139=== RUN TestIsValidUploadKey/traversal_nar1140=== PAUSE TestIsValidUploadKey/traversal_nar1141=== RUN TestIsValidUploadKey/absolute1142=== PAUSE TestIsValidUploadKey/absolute1143=== RUN TestIsValidUploadKey/empty_key1144=== PAUSE TestIsValidUploadKey/empty_key1145=== RUN TestIsValidUploadKey/unknown_type1146=== PAUSE TestIsValidUploadKey/unknown_type1147=== CONT TestProxyWriteTimeout1148=== RUN TestProxyWriteTimeout/narinfo1149=== PAUSE TestProxyWriteTimeout/narinfo1150=== RUN TestProxyWriteTimeout/1_GiB_nar1151=== PAUSE TestProxyWriteTimeout/1_GiB_nar1152=== RUN TestProxyWriteTimeout/10_GiB_nar1153=== PAUSE TestProxyWriteTimeout/10_GiB_nar1154=== RUN TestProxyWriteTimeout/unknown_size1155=== PAUSE TestProxyWriteTimeout/unknown_size1156=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11572026-09-09 10:29:48.047 UTC [24861] ERROR: relation "goose_db_version" does not exist at character 3611582026-09-09 10:29:48.047 UTC [24861] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1159--- PASS: TestReadRedirectUsesPublicS3URL (1.23s)1160=== CONT TestSkippedUploadsHandler11612026/09/09 10:29:48 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001162--- PASS: TestSkippedUploadsHandler (0.00s)1163=== CONT TestParseSize1164--- PASS: TestParseSize (0.00s)1165=== CONT TestService_Rustfstest11662026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures11672026/09/09 10:29:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11682026/09/09 10:29:48 INFO Uploading 5aqahzngcnh1c0rh7p8yfi0djplnncbn-file1.txt (160B)11692026/09/09 10:29:48 OK 20241026095416_initial_model.sql (29.55ms)11702026/09/09 10:29:48 OK 20251210153512_drop_unused_gin_index.sql (5.38ms)11712026/09/09 10:29:48 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11722026/09/09 10:29:48 WARN Failed to register uploaded object key=5aqahzngcnh1c0rh7p8yfi0djplnncbn.ls error="server returned 404: 404 page not found\n"11732026/09/09 10:29:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11742026/09/09 10:29:48 INFO Signed narinfos id=1 count=111752026/09/09 10:29:48 INFO Uploading 1 narinfos11762026/09/09 10:29:48 OK 20251218171726_add_pins.sql (8.19ms)11772026/09/09 10:29:48 WARN Failed to register uploaded object key=5aqahzngcnh1c0rh7p8yfi0djplnncbn.narinfo error="server returned 404: 404 page not found\n"11782026/09/09 10:29:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11792026-09-09 10:29:48.124 UTC [24867] ERROR: relation "goose_db_version" does not exist at character 3611802026-09-09 10:29:48.124 UTC [24867] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11812026/09/09 10:29:48 INFO Completed upload id=111822026/09/09 10:29:48 INFO Upload complete. (133ms)1183=== NAME TestNARDeduplicationMetadataUploadBug1184 metadata_upload_test.go:54: Retrieved narinfo from S3:1185 StorePath: /nix/var/nix/builds/nix-24452-4259264778/TestNARDeduplicationMetadataUploadBug613393386/001/store/5aqahzngcnh1c0rh7p8yfi0djplnncbn-file1.txt1186 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1187 Compression: zstd1188 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1189 NarSize: 1601190 References: 1191 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1192 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1193 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1194 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11952026/09/09 10:29:48 OK 20260628120000_add_object_size_and_stats.sql (19.58ms)11962026/09/09 10:29:48 goose: successfully migrated database to version: 2026062812000011972026/09/09 10:29:48 OK 1_commit_pending_closure.sql (1.53ms)11982026/09/09 10:29:48 OK 2_object_stats_trigger.sql (235.13µs)11992026/09/09 10:29:48 goose: up to current file version: 212002026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures1201 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-24452-4259264778/TestNARDeduplicationMetadataUploadBug613393386/001/store/6144wzpc5dr6agmvrrwgjq2d19cvpfbz-file2.txt12022026/09/09 10:29:48 OK 20241026095416_initial_model.sql (38.37ms)12032026/09/09 10:29:48 OK 20251210153512_drop_unused_gin_index.sql (9.68ms)1204--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.85s)1205=== CONT TestPresignedUploadRegisteredBeforeCommit12062026/09/09 10:29:48 OK 20251218171726_add_pins.sql (9.22ms)12072026/09/09 10:29:48 OK 20260628120000_add_object_size_and_stats.sql (12.16ms)12082026/09/09 10:29:48 goose: successfully migrated database to version: 2026062812000012092026/09/09 10:29:48 OK 1_commit_pending_closure.sql (1.26ms)12102026/09/09 10:29:48 OK 2_object_stats_trigger.sql (274.25µs)12112026/09/09 10:29:48 goose: up to current file version: 212122026/09/09 10:29:48 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12132026-09-09 10:29:48.276 UTC [24877] ERROR: relation "goose_db_version" does not exist at character 3612142026-09-09 10:29:48.276 UTC [24877] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12152026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures12162026/09/09 10:29:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12172026/09/09 10:29:48 WARN Failed to register uploaded object key=6144wzpc5dr6agmvrrwgjq2d19cvpfbz.ls error="server returned 404: 404 page not found\n"12182026/09/09 10:29:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12192026/09/09 10:29:48 INFO Signed narinfos id=2 count=112202026/09/09 10:29:48 INFO Uploading 1 narinfos12212026/09/09 10:29:48 WARN Failed to register uploaded object key=6144wzpc5dr6agmvrrwgjq2d19cvpfbz.narinfo error="server returned 404: 404 page not found\n"12222026/09/09 10:29:48 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12232026/09/09 10:29:48 INFO Completed upload id=212242026/09/09 10:29:48 INFO Upload complete. (103ms)1225=== NAME TestNARDeduplicationMetadataUploadBug1226 metadata_upload_test.go:76: Retrieved narinfo from S3:1227 StorePath: /nix/var/nix/builds/nix-24452-4259264778/TestNARDeduplicationMetadataUploadBug613393386/001/store/6144wzpc5dr6agmvrrwgjq2d19cvpfbz-file2.txt1228 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1229 Compression: zstd1230 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1231 NarSize: 1601232 References: 1233 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1234 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1235 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1236 {"version":1,"root":{"type":"regular","size":44}}12372026/09/09 10:29:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12382026/09/09 10:29:48 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1239--- PASS: TestCompleteMultipartUnregistered (0.94s)1240=== CONT TestCompletedNarNotReofferedAcrossClosures1241--- PASS: TestNARDeduplicationMetadataUploadBug (1.80s)1242=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12432026/09/09 10:29:48 OK 20241026095416_initial_model.sql (73.77ms)12442026/09/09 10:29:48 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)12452026/09/09 10:29:48 OK 20251218171726_add_pins.sql (2.2ms)12462026/09/09 10:29:48 OK 20260628120000_add_object_size_and_stats.sql (16.62ms)12472026/09/09 10:29:48 goose: successfully migrated database to version: 2026062812000012482026/09/09 10:29:48 OK 1_commit_pending_closure.sql (1.1ms)12492026/09/09 10:29:48 OK 2_object_stats_trigger.sql (230µs)12502026/09/09 10:29:48 goose: up to current file version: 212512026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures12522026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures12532026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures12542026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures12552026-09-09 10:29:48.805 UTC [24883] ERROR: relation "goose_db_version" does not exist at character 3612562026-09-09 10:29:48.805 UTC [24883] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12572026-09-09 10:29:48.815 UTC [24884] ERROR: relation "goose_db_version" does not exist at character 3612582026-09-09 10:29:48.815 UTC [24884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12592026/09/09 10:29:48 INFO Received cleanup request method=DELETE path=/api/pending_closures12602026/09/09 10:29:48 INFO Aborted multipart uploads count=012612026/09/09 10:29:48 INFO Received uploads request method=POST path=/api/pending_closures12622026/09/09 10:29:48 INFO Received cleanup request method=DELETE path=/api/pending_closures12632026/09/09 10:29:48 INFO Aborted multipart uploads count=112642026/09/09 10:29:48 OK 20241026095416_initial_model.sql (89.51ms)12652026/09/09 10:29:48 OK 20251210153512_drop_unused_gin_index.sql (867.38µs)12662026/09/09 10:29:48 OK 20241026095416_initial_model.sql (79.9ms)12672026/09/09 10:29:48 OK 20251218171726_add_pins.sql (3.1ms)12682026/09/09 10:29:48 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)12692026/09/09 10:29:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12702026-09-09 10:29:48.945 UTC [24877] ERROR: Closure does not exist: id=112712026-09-09 10:29:48.945 UTC [24877] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE12722026-09-09 10:29:48.945 UTC [24877] STATEMENT: -- name: CommitPendingClosure :exec1273 SELECT commit_pending_closure($1::bigint)1274 1275--- PASS: TestService_cleanupPendingClosuresHandler (1.22s)1276=== CONT TestRedundantMultipartUpload12772026/09/09 10:29:48 OK 20251218171726_add_pins.sql (25.78ms)12782026/09/09 10:29:48 OK 20260628120000_add_object_size_and_stats.sql (34.41ms)12792026/09/09 10:29:48 goose: successfully migrated database to version: 2026062812000012802026/09/09 10:29:48 OK 1_commit_pending_closure.sql (6.86ms)12812026/09/09 10:29:48 OK 2_object_stats_trigger.sql (341.38µs)12822026/09/09 10:29:48 goose: up to current file version: 212832026/09/09 10:29:48 OK 20260628120000_add_object_size_and_stats.sql (34.96ms)12842026/09/09 10:29:48 goose: successfully migrated database to version: 2026062812000012852026/09/09 10:29:49 OK 1_commit_pending_closure.sql (12.12ms)12862026/09/09 10:29:49 OK 2_object_stats_trigger.sql (324µs)12872026/09/09 10:29:49 goose: up to current file version: 212882026-09-09 10:29:49.176 UTC [24887] ERROR: relation "goose_db_version" does not exist at character 3612892026-09-09 10:29:49.176 UTC [24887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12902026/09/09 10:29:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01291=== NAME TestPinProtectsFromGC1292 client_integration_test.go:711: Pin successfully protected closure from garbage collection1293--- PASS: TestService_Rustfstest (1.18s)1294=== CONT TestReadProxy4041295--- PASS: TestPinProtectsFromGC (4.15s)1296=== CONT TestReadProxyRangeRequest12972026/09/09 10:29:49 OK 20241026095416_initial_model.sql (152.85ms)12982026/09/09 10:29:49 OK 20251210153512_drop_unused_gin_index.sql (7.66ms)12992026/09/09 10:29:49 OK 20251218171726_add_pins.sql (23.21ms)13002026/09/09 10:29:49 OK 20260628120000_add_object_size_and_stats.sql (35.52ms)13012026/09/09 10:29:49 goose: successfully migrated database to version: 2026062812000013022026/09/09 10:29:49 OK 1_commit_pending_closure.sql (9.94ms)13032026/09/09 10:29:49 OK 2_object_stats_trigger.sql (510µs)13042026/09/09 10:29:49 goose: up to current file version: 213052026/09/09 10:29:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01306=== NAME TestClientIntegration1307 client_integration_test.go:304: Objects in database after GC:1308 client_integration_test.go:304: Successfully deleted all objects with GC --force13092026/09/09 10:29:49 INFO Received uploads request method=POST path=/api/pending_closures13102026-09-09 10:29:49.549 UTC [24892] ERROR: relation "goose_db_version" does not exist at character 3613112026-09-09 10:29:49.549 UTC [24892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13122026-09-09 10:29:49.565 UTC [24893] ERROR: relation "goose_db_version" does not exist at character 3613132026-09-09 10:29:49.565 UTC [24893] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1314--- PASS: TestClientIntegration (3.75s)1315=== CONT TestReadRedirectKeepsNarinfoProxied13162026/09/09 10:29:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13172026/09/09 10:29:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MDY2ODMwZDctMDVkZC00ZGJiLWE1ZWItMjhmMmIxYTIzZDY5LjZlNjIyOTcyLTFmZTAtNGNjNy05MzUyLWY3NjdmYWY2NTBmMHgxNzg4OTQ5Nzg4NDc2NDIwMDAw parts=1013182026/09/09 10:29:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13192026/09/09 10:29:49 INFO Completed upload id=113202026/09/09 10:29:49 INFO Received uploads request method=POST path=/api/pending_closures13212026/09/09 10:29:49 INFO Received uploads request method=POST path=/api/pending_closures13222026/09/09 10:29:49 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13232026/09/09 10:29:49 WARN Found objects in DB but missing from S3, will re-upload count=11324--- PASS: TestService_verifyS3Integrity (2.24s)1325=== CONT TestReadRedirectNar13262026/09/09 10:29:49 OK 20241026095416_initial_model.sql (183.76ms)13272026/09/09 10:29:49 OK 20251210153512_drop_unused_gin_index.sql (11.24ms)13282026/09/09 10:29:49 INFO Received uploads request method=POST path=/api/pending_closures13292026/09/09 10:29:49 OK 20241026095416_initial_model.sql (195.42ms)13302026/09/09 10:29:49 OK 20251210153512_drop_unused_gin_index.sql (5.47ms)13312026/09/09 10:29:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13322026/09/09 10:29:49 OK 20251218171726_add_pins.sql (40.29ms)13332026/09/09 10:29:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13342026/09/09 10:29:49 OK 20251218171726_add_pins.sql (12.01ms)13352026/09/09 10:29:49 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13362026/09/09 10:29:49 INFO Received uploads request method=POST path=/api/pending_closures1337--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.64s)1338=== CONT TestReadProxyDisabled13392026/09/09 10:29:49 OK 20260628120000_add_object_size_and_stats.sql (11.36ms)13402026/09/09 10:29:49 goose: successfully migrated database to version: 2026062812000013412026/09/09 10:29:49 OK 20260628120000_add_object_size_and_stats.sql (5.47ms)13422026/09/09 10:29:49 goose: successfully migrated database to version: 2026062812000013432026/09/09 10:29:49 OK 1_commit_pending_closure.sql (3.28ms)13442026/09/09 10:29:49 OK 1_commit_pending_closure.sql (1.88ms)13452026/09/09 10:29:49 OK 2_object_stats_trigger.sql (681.04µs)13462026/09/09 10:29:49 goose: up to current file version: 213472026/09/09 10:29:49 OK 2_object_stats_trigger.sql (605.29µs)13482026/09/09 10:29:49 goose: up to current file version: 213492026/09/09 10:29:49 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MDY2ODMwZDctMDVkZC00ZGJiLWE1ZWItMjhmMmIxYTIzZDY5LmNjMzVlYWU5LWViZDUtNDJhYS1iYTY0LTZiOWYyOTQyOWUxYXgxNzg4OTQ5Nzg4NjczOTQ5MDAw parts=1013502026/09/09 10:29:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13512026/09/09 10:29:49 INFO Completed upload id=113522026/09/09 10:29:49 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013532026/09/09 10:29:49 INFO Received uploads request method=POST path=/api/pending_closures13542026/09/09 10:29:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures13552026/09/09 10:29:49 INFO Aborted multipart uploads count=013562026/09/09 10:29:49 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=013572026/09/09 10:29:49 INFO Vacuumed table table=pending_closures13582026/09/09 10:29:49 INFO Vacuumed table table=pending_objects13592026/09/09 10:29:49 INFO Vacuumed table table=multipart_uploads13602026/09/09 10:29:49 INFO Vacuumed table table=closures13612026/09/09 10:29:49 INFO Vacuumed table table=objects13622026/09/09 10:29:50 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013632026/09/09 10:29:50 INFO Received uploads request method=POST path=/api/pending_closures1364--- PASS: TestService_createPendingClosureHandler (2.39s)1365=== CONT TestReadProxyRootRedirectsToIndexHTML13662026/09/09 10:29:50 INFO Received uploads request method=POST path=/api/pending_closures13672026-09-09 10:29:50.272 UTC [24903] ERROR: relation "goose_db_version" does not exist at character 3613682026-09-09 10:29:50.272 UTC [24903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13692026/09/09 10:29:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13702026/09/09 10:29:50 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDY2ODMwZDctMDVkZC00ZGJiLWE1ZWItMjhmMmIxYTIzZDY5LjgzY2IxZTYxLThiNjktNDc2OS04Y2QyLTM5Yzk3NTZkMWFlNXgxNzg4OTQ5NzkwMjU1NTE2MDAw13712026/09/09 10:29:50 OK 20241026095416_initial_model.sql (107.67ms)13722026/09/09 10:29:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDY2ODMwZDctMDVkZC00ZGJiLWE1ZWItMjhmMmIxYTIzZDY5LjgzY2IxZTYxLThiNjktNDc2OS04Y2QyLTM5Yzk3NTZkMWFlNXgxNzg4OTQ5NzkwMjU1NTE2MDAw parts=11373--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.10s)1374=== CONT TestReadProxyConditionalGet13752026/09/09 10:29:50 OK 20251210153512_drop_unused_gin_index.sql (4.54ms)13762026/09/09 10:29:50 OK 20251218171726_add_pins.sql (17.37ms)13772026-09-09 10:29:50.451 UTC [24906] ERROR: relation "goose_db_version" does not exist at character 3613782026-09-09 10:29:50.451 UTC [24906] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13792026/09/09 10:29:50 OK 20260628120000_add_object_size_and_stats.sql (8.81ms)13802026/09/09 10:29:50 goose: successfully migrated database to version: 2026062812000013812026/09/09 10:29:50 OK 1_commit_pending_closure.sql (1.92ms)13822026/09/09 10:29:50 OK 2_object_stats_trigger.sql (477.13µs)13832026/09/09 10:29:50 goose: up to current file version: 213842026-09-09 10:29:50.520 UTC [24907] ERROR: relation "goose_db_version" does not exist at character 3613852026-09-09 10:29:50.520 UTC [24907] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13862026/09/09 10:29:50 OK 20241026095416_initial_model.sql (109.95ms)13872026/09/09 10:29:50 OK 20251210153512_drop_unused_gin_index.sql (7.65ms)13882026/09/09 10:29:50 OK 20251218171726_add_pins.sql (7.29ms)13892026/09/09 10:29:50 OK 20260628120000_add_object_size_and_stats.sql (23.62ms)13902026/09/09 10:29:50 goose: successfully migrated database to version: 2026062812000013912026/09/09 10:29:50 OK 1_commit_pending_closure.sql (9.3ms)13922026/09/09 10:29:50 OK 2_object_stats_trigger.sql (471.88µs)13932026/09/09 10:29:50 goose: up to current file version: 213942026/09/09 10:29:50 OK 20241026095416_initial_model.sql (142.32ms)13952026/09/09 10:29:50 INFO Received uploads request method=POST path=/api/pending_closures13962026/09/09 10:29:50 OK 20251210153512_drop_unused_gin_index.sql (8.75ms)13972026/09/09 10:29:50 OK 20251218171726_add_pins.sql (41.85ms)13982026/09/09 10:29:50 OK 20260628120000_add_object_size_and_stats.sql (40.85ms)13992026/09/09 10:29:50 goose: successfully migrated database to version: 2026062812000014002026/09/09 10:29:50 INFO Received uploads request method=POST path=/api/pending_closures14012026/09/09 10:29:50 OK 1_commit_pending_closure.sql (13.39ms)14022026/09/09 10:29:50 OK 2_object_stats_trigger.sql (960.29µs)14032026/09/09 10:29:50 goose: up to current file version: 214042026-09-09 10:29:50.975 UTC [24908] ERROR: relation "goose_db_version" does not exist at character 3614052026-09-09 10:29:50.975 UTC [24908] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1406--- PASS: TestReadProxy404 (1.81s)1407=== CONT TestReadProxyHead14082026/09/09 10:29:51 OK 20241026095416_initial_model.sql (319.81ms)14092026/09/09 10:29:51 OK 20251210153512_drop_unused_gin_index.sql (13.05ms)14102026-09-09 10:29:51.398 UTC [24911] ERROR: relation "goose_db_version" does not exist at character 3614112026-09-09 10:29:51.398 UTC [24911] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14122026/09/09 10:29:51 OK 20251218171726_add_pins.sql (11.33ms)1413--- PASS: TestReadProxyRangeRequest (2.15s)1414=== CONT TestReadProxyInvalidPath14152026/09/09 10:29:51 OK 20260628120000_add_object_size_and_stats.sql (44.03ms)14162026/09/09 10:29:51 goose: successfully migrated database to version: 2026062812000014172026/09/09 10:29:51 OK 1_commit_pending_closure.sql (13.9ms)14182026/09/09 10:29:51 OK 2_object_stats_trigger.sql (531.38µs)14192026/09/09 10:29:51 goose: up to current file version: 214202026/09/09 10:29:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14212026/09/09 10:29:51 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MDY2ODMwZDctMDVkZC00ZGJiLWE1ZWItMjhmMmIxYTIzZDY5LjJhYmMyNWIxLTA5NjItNDU5Ny1hODgzLTc1MjM3NTIxYTU5ZXgxNzg4OTQ5NzkwMDI4MTI0MDAw parts=1214222026/09/09 10:29:51 INFO Received uploads request method=POST path=/api/pending_closures1423--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.29s)1424=== CONT TestCacheConfigHandlerMaxNarSize1425--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1426=== CONT TestGenerateLandingPage1427--- PASS: TestGenerateLandingPage (0.00s)1428=== CONT TestIsValidCachePath1429=== RUN TestIsValidCachePath/narinfo1430=== PAUSE TestIsValidCachePath/narinfo1431=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1432=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1433=== RUN TestIsValidCachePath/nar_zst1434=== PAUSE TestIsValidCachePath/nar_zst1435=== RUN TestIsValidCachePath/nar_xz1436=== PAUSE TestIsValidCachePath/nar_xz1437=== RUN TestIsValidCachePath/nar_bz21438=== PAUSE TestIsValidCachePath/nar_bz21439=== RUN TestIsValidCachePath/nar_uncompressed1440=== PAUSE TestIsValidCachePath/nar_uncompressed1441=== RUN TestIsValidCachePath/ls1442=== PAUSE TestIsValidCachePath/ls1443=== RUN TestIsValidCachePath/log1444=== PAUSE TestIsValidCachePath/log1445=== RUN TestIsValidCachePath/realisation1446=== PAUSE TestIsValidCachePath/realisation1447=== RUN TestIsValidCachePath/nix-cache-info1448=== PAUSE TestIsValidCachePath/nix-cache-info1449=== RUN TestIsValidCachePath/index.html1450=== PAUSE TestIsValidCachePath/index.html1451=== RUN TestIsValidCachePath/traversal_parent1452=== PAUSE TestIsValidCachePath/traversal_parent1453=== RUN TestIsValidCachePath/traversal_in_middle1454=== PAUSE TestIsValidCachePath/traversal_in_middle1455=== RUN TestIsValidCachePath/invalid_char_e1456=== PAUSE TestIsValidCachePath/invalid_char_e1457=== RUN TestIsValidCachePath/invalid_char_u1458=== PAUSE TestIsValidCachePath/invalid_char_u1459=== RUN TestIsValidCachePath/random_path1460=== PAUSE TestIsValidCachePath/random_path1461=== RUN TestIsValidCachePath/empty1462=== PAUSE TestIsValidCachePath/empty1463=== RUN TestIsValidCachePath/leading_slash1464=== PAUSE TestIsValidCachePath/leading_slash1465=== RUN TestIsValidCachePath/wrong_extension1466=== PAUSE TestIsValidCachePath/wrong_extension1467=== RUN TestIsValidCachePath/short_hash1468=== PAUSE TestIsValidCachePath/short_hash1469=== CONT TestReadProxyNarStreaming14702026-09-09 10:29:51.668 UTC [24914] ERROR: relation "goose_db_version" does not exist at character 3614712026-09-09 10:29:51.668 UTC [24914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14722026/09/09 10:29:51 OK 20241026095416_initial_model.sql (185.92ms)14732026/09/09 10:29:51 OK 20251210153512_drop_unused_gin_index.sql (14.84ms)14742026/09/09 10:29:51 OK 20251218171726_add_pins.sql (21.63ms)14752026/09/09 10:29:51 OK 20260628120000_add_object_size_and_stats.sql (40.36ms)14762026/09/09 10:29:51 goose: successfully migrated database to version: 2026062812000014772026/09/09 10:29:51 OK 1_commit_pending_closure.sql (6.57ms)14782026/09/09 10:29:51 OK 2_object_stats_trigger.sql (567.46µs)14792026/09/09 10:29:51 goose: up to current file version: 21480--- PASS: TestReadRedirectKeepsNarinfoProxied (2.22s)1481=== CONT TestReadProxyNarinfoAlreadyDecompressed14822026/09/09 10:29:51 OK 20241026095416_initial_model.sql (210.4ms)14832026/09/09 10:29:51 OK 20251210153512_drop_unused_gin_index.sql (15.31ms)14842026-09-09 10:29:51.963 UTC [24919] ERROR: relation "goose_db_version" does not exist at character 3614852026-09-09 10:29:51.963 UTC [24919] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14862026/09/09 10:29:51 OK 20251218171726_add_pins.sql (22.65ms)14872026/09/09 10:29:52 OK 20260628120000_add_object_size_and_stats.sql (44.56ms)14882026/09/09 10:29:52 goose: successfully migrated database to version: 2026062812000014892026/09/09 10:29:52 OK 1_commit_pending_closure.sql (3.56ms)14902026/09/09 10:29:52 OK 2_object_stats_trigger.sql (589.29µs)14912026/09/09 10:29:52 goose: up to current file version: 21492--- PASS: TestReadRedirectNar (2.37s)1493=== CONT TestReadProxyNarinfo14942026/09/09 10:29:52 OK 20241026095416_initial_model.sql (87.62ms)14952026/09/09 10:29:52 OK 20251210153512_drop_unused_gin_index.sql (13.36ms)14962026/09/09 10:29:52 OK 20251218171726_add_pins.sql (41.1ms)14972026/09/09 10:29:52 OK 20260628120000_add_object_size_and_stats.sql (34.71ms)14982026/09/09 10:29:52 goose: successfully migrated database to version: 2026062812000014992026/09/09 10:29:52 OK 1_commit_pending_closure.sql (3.93ms)15002026/09/09 10:29:52 OK 2_object_stats_trigger.sql (717µs)15012026/09/09 10:29:52 goose: up to current file version: 21502--- PASS: TestReadProxyDisabled (2.48s)1503=== CONT TestResurrectedObjectNotDeleted15042026-09-09 10:29:52.441 UTC [24924] ERROR: relation "goose_db_version" does not exist at character 3615052026-09-09 10:29:52.441 UTC [24924] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15062026/09/09 10:29:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1507--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.59s)1508=== CONT TestParseSingleRange1509=== RUN TestParseSingleRange/none1510=== PAUSE TestParseSingleRange/none1511=== RUN TestParseSingleRange/unknown_unit1512=== PAUSE TestParseSingleRange/unknown_unit1513=== RUN TestParseSingleRange/multi-range_ignored1514=== PAUSE TestParseSingleRange/multi-range_ignored1515=== RUN TestParseSingleRange/malformed_no_dash1516=== PAUSE TestParseSingleRange/malformed_no_dash1517=== RUN TestParseSingleRange/malformed_both_empty1518=== PAUSE TestParseSingleRange/malformed_both_empty1519=== RUN TestParseSingleRange/malformed_end_before_start1520=== PAUSE TestParseSingleRange/malformed_end_before_start1521=== RUN TestParseSingleRange/closed1522=== PAUSE TestParseSingleRange/closed1523=== RUN TestParseSingleRange/open-ended1524=== PAUSE TestParseSingleRange/open-ended1525=== RUN TestParseSingleRange/end_clamped_to_size1526=== PAUSE TestParseSingleRange/end_clamped_to_size1527=== RUN TestParseSingleRange/suffix1528=== PAUSE TestParseSingleRange/suffix1529=== RUN TestParseSingleRange/suffix_exceeds_size1530=== PAUSE TestParseSingleRange/suffix_exceeds_size1531=== RUN TestParseSingleRange/single_byte1532=== PAUSE TestParseSingleRange/single_byte1533=== RUN TestParseSingleRange/start_past_EOF1534=== PAUSE TestParseSingleRange/start_past_EOF1535=== RUN TestParseSingleRange/start_far_past_EOF1536=== PAUSE TestParseSingleRange/start_far_past_EOF1537=== CONT TestService_ReadAuthMiddleware15382026/09/09 10:29:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MDY2ODMwZDctMDVkZC00ZGJiLWE1ZWItMjhmMmIxYTIzZDY5LmU5NzJiZDMwLTU4YjEtNGY1ZC1hZThlLTQyYWUwM2ExMmY0N3gxNzg4OTQ5NzkwNzQ5MjgxMDAw parts=121539--- PASS: TestRedundantMultipartUpload (3.75s)1540=== CONT TestService_AuthMiddleware_OIDC15412026/09/09 10:29:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61314/oidc15422026/09/09 10:29:52 OK 20241026095416_initial_model.sql (191.65ms)15432026/09/09 10:29:52 OK 20251210153512_drop_unused_gin_index.sql (9.27ms)15442026/09/09 10:29:52 OK 20251218171726_add_pins.sql (20.18ms)15452026/09/09 10:29:52 OK 20260628120000_add_object_size_and_stats.sql (6.07ms)15462026/09/09 10:29:52 goose: successfully migrated database to version: 2026062812000015472026/09/09 10:29:52 OK 1_commit_pending_closure.sql (1.96ms)15482026/09/09 10:29:52 OK 2_object_stats_trigger.sql (401.79µs)15492026/09/09 10:29:52 goose: up to current file version: 215502026-09-09 10:29:52.776 UTC [24929] ERROR: relation "goose_db_version" does not exist at character 3615512026-09-09 10:29:52.776 UTC [24929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15522026/09/09 10:29:53 OK 20241026095416_initial_model.sql (175.52ms)15532026/09/09 10:29:53 OK 20251210153512_drop_unused_gin_index.sql (14.32ms)15542026/09/09 10:29:53 OK 20251218171726_add_pins.sql (38.02ms)1555--- PASS: TestReadProxyConditionalGet (2.63s)1556=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15572026/09/09 10:29:53 OK 20260628120000_add_object_size_and_stats.sql (34.78ms)15582026/09/09 10:29:53 goose: successfully migrated database to version: 2026062812000015592026/09/09 10:29:53 OK 1_commit_pending_closure.sql (3.5ms)15602026/09/09 10:29:53 OK 2_object_stats_trigger.sql (492.46µs)15612026/09/09 10:29:53 goose: up to current file version: 215622026-09-09 10:29:53.229 UTC [24932] ERROR: relation "goose_db_version" does not exist at character 3615632026-09-09 10:29:53.229 UTC [24932] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1564--- PASS: TestReadProxyHead (2.42s)1565=== CONT TestService_AuthMiddleware_MTLSProxyHeader15662026-09-09 10:29:53.462 UTC [24933] ERROR: relation "goose_db_version" does not exist at character 3615672026-09-09 10:29:53.462 UTC [24933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15682026/09/09 10:29:53 OK 20241026095416_initial_model.sql (166.33ms)15692026/09/09 10:29:53 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)15702026/09/09 10:29:53 OK 20251218171726_add_pins.sql (2.88ms)15712026-09-09 10:29:53.477 UTC [24935] ERROR: relation "goose_db_version" does not exist at character 3615722026-09-09 10:29:53.477 UTC [24935] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15732026/09/09 10:29:53 OK 20260628120000_add_object_size_and_stats.sql (11.09ms)15742026/09/09 10:29:53 goose: successfully migrated database to version: 2026062812000015752026/09/09 10:29:53 OK 1_commit_pending_closure.sql (2.46ms)15762026/09/09 10:29:53 OK 2_object_stats_trigger.sql (477.21µs)15772026/09/09 10:29:53 goose: up to current file version: 215782026/09/09 10:29:53 OK 20241026095416_initial_model.sql (80.3ms)15792026/09/09 10:29:53 OK 20241026095416_initial_model.sql (90.95ms)15802026/09/09 10:29:53 OK 20251210153512_drop_unused_gin_index.sql (13.92ms)15812026/09/09 10:29:53 OK 20251210153512_drop_unused_gin_index.sql (10.67ms)15822026/09/09 10:29:53 OK 20251218171726_add_pins.sql (32.59ms)15832026/09/09 10:29:53 OK 20251218171726_add_pins.sql (22.38ms)15842026/09/09 10:29:53 OK 20260628120000_add_object_size_and_stats.sql (35.41ms)15852026/09/09 10:29:53 goose: successfully migrated database to version: 2026062812000015862026/09/09 10:29:53 OK 20260628120000_add_object_size_and_stats.sql (35.09ms)15872026/09/09 10:29:53 goose: successfully migrated database to version: 2026062812000015882026/09/09 10:29:53 OK 1_commit_pending_closure.sql (6.3ms)15892026/09/09 10:29:53 OK 2_object_stats_trigger.sql (1.4ms)15902026/09/09 10:29:53 goose: up to current file version: 215912026/09/09 10:29:53 OK 1_commit_pending_closure.sql (13.67ms)15922026/09/09 10:29:53 OK 2_object_stats_trigger.sql (1.57ms)15932026/09/09 10:29:53 goose: up to current file version: 21594--- PASS: TestReadProxyInvalidPath (2.33s)1595=== CONT TestOrphanedObjectsGCStressTest15962026-09-09 10:29:53.963 UTC [24940] ERROR: relation "goose_db_version" does not exist at character 3615972026-09-09 10:29:53.963 UTC [24940] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15982026/09/09 10:29:54 WARN Rate limiter enabled after throttle name=s3-test rate=515992026/09/09 10:29:54 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1600=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1601 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101602 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001603--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.08s)1604=== CONT TestOrphanedObjectsGC1605--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.33s)1606=== CONT TestServerTLSConfig/not_a_PEM_file1607=== CONT TestServerTLSConfig/no_client_CA1608=== CONT TestServerTLSConfig/missing_CA_file1609--- PASS: TestServerTLSConfig (0.00s)1610 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1611 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1612 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1613=== CONT TestClientErrorHandling/InvalidStorePath16142026/09/09 10:29:54 OK 20241026095416_initial_model.sql (212.55ms)16152026/09/09 10:29:54 OK 20251210153512_drop_unused_gin_index.sql (21.54ms)16162026/09/09 10:29:54 OK 20251218171726_add_pins.sql (25.06ms)16172026/09/09 10:29:54 OK 20260628120000_add_object_size_and_stats.sql (39.91ms)16182026/09/09 10:29:54 goose: successfully migrated database to version: 2026062812000016192026/09/09 10:29:54 OK 1_commit_pending_closure.sql (16.5ms)16202026/09/09 10:29:54 OK 2_object_stats_trigger.sql (1.93ms)16212026/09/09 10:29:54 goose: up to current file version: 216222026-09-09 10:29:54.411 UTC [24945] ERROR: relation "goose_db_version" does not exist at character 3616232026-09-09 10:29:54.411 UTC [24945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1624--- PASS: TestReadProxyNarStreaming (2.81s)1625=== CONT TestClientErrorHandling/ServerNotAvailable16262026-09-09 10:29:54.508 UTC [24947] ERROR: relation "goose_db_version" does not exist at character 3616272026-09-09 10:29:54.508 UTC [24947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16282026-09-09 10:29:54.546 UTC [24949] ERROR: relation "goose_db_version" does not exist at character 3616292026-09-09 10:29:54.546 UTC [24949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16302026/09/09 10:29:54 OK 20241026095416_initial_model.sql (142.11ms)16312026/09/09 10:29:54 OK 20251210153512_drop_unused_gin_index.sql (12.33ms)16322026/09/09 10:29:54 OK 20251218171726_add_pins.sql (12.64ms)16332026/09/09 10:29:54 OK 20241026095416_initial_model.sql (115.52ms)1634--- PASS: TestReadProxyNarinfo (2.58s)1635=== CONT TestClientErrorHandling/InvalidAuthToken16362026/09/09 10:29:54 OK 20251210153512_drop_unused_gin_index.sql (8.25ms)16372026/09/09 10:29:54 OK 20251218171726_add_pins.sql (9.79ms)16382026/09/09 10:29:54 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-config16392026/09/09 10:29:54 OK 20260628120000_add_object_size_and_stats.sql (18.34ms)16402026/09/09 10:29:54 goose: successfully migrated database to version: 2026062812000016412026/09/09 10:29:54 OK 1_commit_pending_closure.sql (2.88ms)16422026/09/09 10:29:54 OK 2_object_stats_trigger.sql (237.5µs)16432026/09/09 10:29:54 goose: up to current file version: 216442026/09/09 10:29:54 OK 20241026095416_initial_model.sql (93.19ms)16452026/09/09 10:29:54 OK 20251210153512_drop_unused_gin_index.sql (8.79ms)16462026/09/09 10:29:54 OK 20260628120000_add_object_size_and_stats.sql (35.35ms)16472026/09/09 10:29:54 goose: successfully migrated database to version: 2026062812000016482026/09/09 10:29:54 OK 1_commit_pending_closure.sql (1.12ms)16492026/09/09 10:29:54 OK 2_object_stats_trigger.sql (217.92µs)16502026/09/09 10:29:54 goose: up to current file version: 216512026/09/09 10:29:54 OK 20251218171726_add_pins.sql (27.73ms)16522026/09/09 10:29:54 OK 20260628120000_add_object_size_and_stats.sql (26.77ms)16532026/09/09 10:29:54 goose: successfully migrated database to version: 2026062812000016542026/09/09 10:29:54 OK 1_commit_pending_closure.sql (2ms)16552026/09/09 10:29:54 OK 2_object_stats_trigger.sql (223.04µs)16562026/09/09 10:29:54 goose: up to current file version: 216572026/09/09 10:29:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.977493ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16582026-09-09 10:29:54.906 UTC [24956] ERROR: relation "goose_db_version" does not exist at character 3616592026-09-09 10:29:54.906 UTC [24956] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16602026/09/09 10:29:54 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=402.846741ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16612026/09/09 10:29:55 OK 20241026095416_initial_model.sql (69.9ms)16622026/09/09 10:29:55 OK 20251210153512_drop_unused_gin_index.sql (3.69ms)1663--- PASS: TestResurrectedObjectNotDeleted (2.72s)1664=== CONT TestResolveDBConnectionString/flag_wins1665=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1666=== CONT TestResolveDBConnectionString/nothing_configured1667=== CONT TestResolveDBConnectionString/missing_file_is_an_error1668=== CONT TestResolveDBConnectionString/file_when_flag_empty1669=== CONT TestCacheConfigHandler/full_config,_no_issuer1670=== CONT TestCacheConfigHandler/no_signing_keys1671=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1672=== CONT TestCacheConfigHandler/no_cache_url_configured1673--- PASS: TestCacheConfigHandler (0.00s)1674 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1675 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1676 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1677 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1678=== CONT TestService_RequireScope_OIDC/builder_may_write16792026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[write]1680=== CONT TestService_RequireScope_OIDC/static_token_may_admin1681=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1682=== CONT TestService_RequireScope_OIDC/writer_implies_read16832026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[write]1684=== CONT TestService_RequireScope_OIDC/reader_may_read16852026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[read]1686=== CONT TestService_RequireScope_OIDC/static_token_may_write1687=== CONT TestService_RequireScope_OIDC/ops_may_not_write16882026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[admin]1689=== CONT TestService_RequireScope_OIDC/reader_may_not_write16902026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[read]1691=== CONT TestService_RequireScope_OIDC/ops_may_admin16922026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[admin]1693=== CONT TestService_RequireScope_OIDC/builder_may_not_admin16942026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[write]1695=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16962026/09/09 10:29:55 INFO Received complete multipart upload request method=POST path=/1697--- PASS: TestResolveDBConnectionString (0.01s)1698 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1699 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1700 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1701 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1702 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1703--- PASS: TestService_RequireScope_OIDC (1.46s)1704 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1705 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1706 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1707 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1708 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1709 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1710 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1711 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1712 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1713 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)17142026/09/09 10:29:55 OK 20251218171726_add_pins.sql (13.22ms)17152026/09/09 10:29:55 OK 20260628120000_add_object_size_and_stats.sql (22.03ms)17162026/09/09 10:29:55 goose: successfully migrated database to version: 2026062812000017172026/09/09 10:29:55 OK 1_commit_pending_closure.sql (1.82ms)17182026/09/09 10:29:55 OK 2_object_stats_trigger.sql (476.21µs)17192026/09/09 10:29:55 goose: up to current file version: 21720=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17212026/09/09 10:29:55 INFO Received uploads request method=POST path=/17222026-09-09 10:29:55.103 UTC [24957] ERROR: relation "goose_db_version" does not exist at character 3617232026-09-09 10:29:55.103 UTC [24957] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1724=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1725=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1726=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1727=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1728=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1729=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1730=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1731=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1732=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17332026/09/09 10:29:55 INFO Received request for more parts method=POST path=/1734=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17352026/09/09 10:29:55 INFO Received uploads request method=POST path=/1736=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17372026/09/09 10:29:55 INFO Received complete multipart upload request method=POST path=/1738=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17392026/09/09 10:29:55 INFO Received request for more parts method=POST path=/1740=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17412026/09/09 10:29:55 INFO Received uploads request method=POST path=/1742--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1743 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1744 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1745 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1746 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1747=== CONT TestIsValidUploadKey/narinfo1748=== CONT TestIsValidUploadKey/realisation_plus_in_output1749=== CONT TestIsValidUploadKey/unknown_type1750=== CONT TestIsValidUploadKey/empty_key1751=== CONT TestIsValidUploadKey/absolute1752=== CONT TestIsValidUploadKey/traversal_nar1753=== CONT TestIsValidUploadKey/traversal1754=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1755=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1756=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1757=== CONT TestIsValidUploadKey/index.html1758=== CONT TestIsValidUploadKey/nix-cache-info1759=== CONT TestIsValidUploadKey/build_log_home-manager_file1760=== CONT TestIsValidUploadKey/realisation1761=== CONT TestIsValidUploadKey/build_log_equals1762=== CONT TestIsValidUploadKey/build_log_question_mark1763=== CONT TestIsValidUploadKey/build_log_plus_in_name1764=== CONT TestIsValidUploadKey/nar_plain1765=== CONT TestIsValidUploadKey/build_log1766=== CONT TestIsValidUploadKey/listing1767=== CONT TestIsValidUploadKey/nar_xz1768=== CONT TestIsValidUploadKey/nar_zst1769--- PASS: TestIsValidUploadKey (0.00s)1770 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1771 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1772 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1773 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1774 --- PASS: TestIsValidUploadKey/absolute (0.00s)1775 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1776 --- PASS: TestIsValidUploadKey/traversal (0.00s)1777 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1778 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1779 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1780 --- PASS: TestIsValidUploadKey/index.html (0.00s)1781 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1782 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1783 --- PASS: TestIsValidUploadKey/realisation (0.00s)1784 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1785 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1786 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1787 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1788 --- PASS: TestIsValidUploadKey/build_log (0.00s)1789 --- PASS: TestIsValidUploadKey/listing (0.00s)1790 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1791 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1792=== CONT TestProxyWriteTimeout/narinfo1793=== CONT TestProxyWriteTimeout/10_GiB_nar1794=== CONT TestProxyWriteTimeout/unknown_size1795=== CONT TestProxyWriteTimeout/1_GiB_nar1796--- PASS: TestProxyWriteTimeout (0.00s)1797 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1798 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1799 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1800 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1801=== CONT TestIsValidCachePath/narinfo1802=== CONT TestIsValidCachePath/index.html1803=== CONT TestIsValidCachePath/short_hash1804=== CONT TestIsValidCachePath/wrong_extension1805=== CONT TestIsValidCachePath/leading_slash1806=== CONT TestIsValidCachePath/empty1807=== CONT TestIsValidCachePath/random_path1808=== CONT TestIsValidCachePath/invalid_char_u1809=== CONT TestIsValidCachePath/invalid_char_e1810=== CONT TestIsValidCachePath/traversal_in_middle1811=== CONT TestIsValidCachePath/traversal_parent1812=== CONT TestIsValidCachePath/nar_uncompressed1813=== CONT TestIsValidCachePath/nix-cache-info1814=== CONT TestIsValidCachePath/realisation1815=== CONT TestIsValidCachePath/log1816=== CONT TestIsValidCachePath/ls1817=== CONT TestIsValidCachePath/nar_xz1818=== CONT TestIsValidCachePath/nar_bz21819=== CONT TestIsValidCachePath/nar_zst1820=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1821--- PASS: TestIsValidCachePath (0.00s)1822 --- PASS: TestIsValidCachePath/narinfo (0.00s)1823 --- PASS: TestIsValidCachePath/index.html (0.00s)1824 --- PASS: TestIsValidCachePath/short_hash (0.00s)1825 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1826 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1827 --- PASS: TestIsValidCachePath/empty (0.00s)1828 --- PASS: TestIsValidCachePath/random_path (0.00s)1829 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1830 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1831 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1832 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1833 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1834 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1835 --- PASS: TestIsValidCachePath/realisation (0.00s)1836 --- PASS: TestIsValidCachePath/log (0.00s)1837 --- PASS: TestIsValidCachePath/ls (0.00s)1838 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1839 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1840 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1841 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1842=== CONT TestParseSingleRange/none1843=== CONT TestParseSingleRange/open-ended1844=== CONT TestParseSingleRange/start_far_past_EOF1845=== CONT TestParseSingleRange/start_past_EOF1846=== CONT TestParseSingleRange/single_byte1847=== CONT TestParseSingleRange/suffix_exceeds_size1848=== CONT TestParseSingleRange/suffix1849=== CONT TestParseSingleRange/end_clamped_to_size1850=== CONT TestParseSingleRange/malformed_both_empty1851=== CONT TestParseSingleRange/closed1852=== CONT TestParseSingleRange/malformed_end_before_start1853=== CONT TestParseSingleRange/multi-range_ignored1854=== CONT TestParseSingleRange/malformed_no_dash1855=== CONT TestParseSingleRange/unknown_unit1856--- PASS: TestParseSingleRange (0.00s)1857 --- PASS: TestParseSingleRange/none (0.00s)1858 --- PASS: TestParseSingleRange/open-ended (0.00s)1859 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1860 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1861 --- PASS: TestParseSingleRange/single_byte (0.00s)1862 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1863 --- PASS: TestParseSingleRange/suffix (0.00s)1864 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1865 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1866 --- PASS: TestParseSingleRange/closed (0.00s)1867 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1868 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1869 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1870 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1871=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token18722026-09-09 10:29:55.162 UTC [24958] ERROR: relation "goose_db_version" does not exist at character 3618732026-09-09 10:29:55.162 UTC [24958] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18742026/09/09 10:29:55 INFO OIDC auth successful provider=test scopes=[write]1875=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18762026/09/09 10:29:55 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]1877=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18782026/09/09 10:29:55 WARN Authentication failed token_preview=eyJhbGciOi...Jp4FGx9jDQ token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1879=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1880--- PASS: TestService_AuthMiddleware_OIDC (2.45s)1881 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1882 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1883 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1884 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)18852026/09/09 10:29:55 OK 20241026095416_initial_model.sql (49.22ms)18862026/09/09 10:29:55 OK 20251210153512_drop_unused_gin_index.sql (629.54µs)18872026/09/09 10:29:55 OK 20251218171726_add_pins.sql (9.82ms)18882026/09/09 10:29:55 OK 20260628120000_add_object_size_and_stats.sql (28.69ms)18892026/09/09 10:29:55 goose: successfully migrated database to version: 2026062812000018902026/09/09 10:29:55 OK 1_commit_pending_closure.sql (1.09ms)18912026/09/09 10:29:55 OK 2_object_stats_trigger.sql (227.25µs)18922026/09/09 10:29:55 goose: up to current file version: 218932026/09/09 10:29:55 OK 20241026095416_initial_model.sql (50.43ms)18942026/09/09 10:29:55 OK 20251210153512_drop_unused_gin_index.sql (6.13ms)18952026/09/09 10:29:55 OK 20251218171726_add_pins.sql (1.59ms)18962026/09/09 10:29:55 OK 20260628120000_add_object_size_and_stats.sql (15.81ms)18972026/09/09 10:29:55 goose: successfully migrated database to version: 2026062812000018982026/09/09 10:29:55 OK 1_commit_pending_closure.sql (1.06ms)18992026/09/09 10:29:55 OK 2_object_stats_trigger.sql (208.08µs)19002026/09/09 10:29:55 goose: up to current file version: 219012026-09-09 10:29:55.268 UTC [24959] ERROR: relation "goose_db_version" does not exist at character 3619022026-09-09 10:29:55.268 UTC [24959] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19032026-09-09 10:29:55.277 UTC [24960] ERROR: relation "goose_db_version" does not exist at character 3619042026-09-09 10:29:55.277 UTC [24960] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1905--- PASS: TestService_ReadAuthMiddleware (2.71s)19062026/09/09 10:29:55 OK 20241026095416_initial_model.sql (22.39ms)19072026/09/09 10:29:55 OK 20241026095416_initial_model.sql (31.3ms)19082026/09/09 10:29:55 OK 20251210153512_drop_unused_gin_index.sql (568.5µs)19092026/09/09 10:29:55 OK 20251210153512_drop_unused_gin_index.sql (536.33µs)19102026/09/09 10:29:55 OK 20251218171726_add_pins.sql (4.13ms)19112026/09/09 10:29:55 OK 20251218171726_add_pins.sql (4.17ms)19122026/09/09 10:29:55 OK 20260628120000_add_object_size_and_stats.sql (9.75ms)19132026/09/09 10:29:55 goose: successfully migrated database to version: 2026062812000019142026/09/09 10:29:55 OK 20260628120000_add_object_size_and_stats.sql (10.32ms)19152026/09/09 10:29:55 goose: successfully migrated database to version: 2026062812000019162026/09/09 10:29:55 OK 1_commit_pending_closure.sql (965.92µs)19172026/09/09 10:29:55 OK 2_object_stats_trigger.sql (221.58µs)19182026/09/09 10:29:55 goose: up to current file version: 219192026/09/09 10:29:55 OK 1_commit_pending_closure.sql (840.96µs)19202026/09/09 10:29:55 OK 2_object_stats_trigger.sql (179.33µs)19212026/09/09 10:29:55 goose: up to current file version: 21922--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1923 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1924 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1925 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)19262026/09/09 10:29:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=875.098812ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19272026-09-09 10:29:55.422 UTC [24961] ERROR: relation "goose_db_version" does not exist at character 3619282026-09-09 10:29:55.422 UTC [24961] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19292026/09/09 10:29:55 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19302026/09/09 10:29:55 WARN mTLS auth: bound subjects configured but subject DN unavailable19312026/09/09 10:29:55 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1932--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.39s)19332026/09/09 10:29:55 OK 20241026095416_initial_model.sql (20.45ms)19342026/09/09 10:29:55 OK 20251210153512_drop_unused_gin_index.sql (3.75ms)19352026/09/09 10:29:55 OK 20251218171726_add_pins.sql (5.65ms)19362026/09/09 10:29:55 OK 20260628120000_add_object_size_and_stats.sql (1.4ms)19372026/09/09 10:29:55 goose: successfully migrated database to version: 2026062812000019382026/09/09 10:29:55 OK 1_commit_pending_closure.sql (4.99ms)19392026/09/09 10:29:55 OK 2_object_stats_trigger.sql (203.96µs)19402026/09/09 10:29:55 goose: up to current file version: 21941--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.07s)1942=== NAME TestOrphanedObjectsGC1943 orphaned_objects_gc_test.go:290: GC Test Summary:1944 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1945 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1946 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1947 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1948 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1949--- PASS: TestOrphanedObjectsGC (1.82s)19502026/09/09 10:29:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19512026/09/09 10:29:56 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1952=== NAME TestOrphanedObjectsGCStressTest1953 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1954 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1955 orphaned_objects_gc_test.go:509: Stress test completed successfully:1956 orphaned_objects_gc_test.go:510: - Active objects preserved: 201957 orphaned_objects_gc_test.go:511: - Objects deleted: 2101958 orphaned_objects_gc_test.go:512: - Total GC'd: 2101959--- PASS: TestOrphanedObjectsGCStressTest (2.47s)19602026/09/09 10:29:56 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.743143903s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19612026/09/09 10:29:58 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"19622026/09/09 10:29:58 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_closures19632026/09/09 10:29:58 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.699368ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19642026/09/09 10:29:58 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=362.519291ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19652026/09/09 10:29:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=754.717656ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19662026/09/09 10:29:59 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.50367974s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1967--- PASS: TestClientErrorHandling (0.00s)1968 --- PASS: TestClientErrorHandling/InvalidStorePath (1.72s)1969 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.41s)1970 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.62s)1971PASS1972{"timestamp":"2026-09-09T10:30:01.050427Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:61270","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1866,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}19732026-09-09 10:30:01.137 UTC [24626] LOG: received smart shutdown request19742026-09-09 10:30:01.137 UTC [24626] LOG: background worker "logical replication launcher" (PID 24636) exited with exit code 119752026-09-09 10:30:01.147 UTC [24631] LOG: shutting down19762026-09-09 10:30:01.147 UTC [24631] LOG: checkpoint starting: shutdown immediate19772026-09-09 10:30:02.233 UTC [24631] LOG: checkpoint complete: wrote 13331 buffers (81.4%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.793 s, sync=0.291 s, total=1.087 s; sync files=17141, longest=0.001 s, average=0.001 s; distance=240172 kB, estimate=240172 kB; lsn=0/102180F0, redo lsn=0/102180F019782026-09-09 10:30:02.237 UTC [24626] LOG: database system is shut down1979Running OIDC tests...1980=== RUN TestGlobMatch1981=== PAUSE TestGlobMatch1982=== RUN TestAudienceForIssuer1983=== PAUSE TestAudienceForIssuer1984=== RUN TestValidateToken_ValidToken1985=== PAUSE TestValidateToken_ValidToken1986=== RUN TestValidateToken_WrongAudience1987=== PAUSE TestValidateToken_WrongAudience1988=== RUN TestValidateToken_Expired1989=== PAUSE TestValidateToken_Expired1990=== RUN TestValidateToken_BoundClaimsMismatch1991=== PAUSE TestValidateToken_BoundClaimsMismatch1992=== RUN TestValidateToken_BoundSubjectMismatch1993=== PAUSE TestValidateToken_BoundSubjectMismatch1994=== RUN TestValidateToken_MultipleProviders1995=== PAUSE TestValidateToken_MultipleProviders1996=== RUN TestValidateToken_NoMatchingProvider1997=== PAUSE TestValidateToken_NoMatchingProvider1998=== RUN TestValidateToken_KubernetesServiceAccount1999=== PAUSE TestValidateToken_KubernetesServiceAccount2000=== RUN TestNewValidator_KubernetesRequiresCA2001=== PAUSE TestNewValidator_KubernetesRequiresCA2002=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2003=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2004=== RUN TestScopes_LegacyProviderDefaultsToWrite2005=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2006=== RUN TestScopes_Rules2007=== PAUSE TestScopes_Rules2008=== RUN TestScopes_ConfigValidation2009=== PAUSE TestScopes_ConfigValidation2010=== CONT TestGlobMatch2011=== CONT TestValidateToken_BoundClaimsMismatch2012=== CONT TestNewValidator_KubernetesRequiresCA2013=== CONT TestValidateToken_Expired2014=== CONT TestValidateToken_NoMatchingProvider2015=== CONT TestValidateToken_MultipleProviders2016=== CONT TestValidateToken_BoundSubjectMismatch2017=== CONT TestAudienceForIssuer2018=== CONT TestValidateToken_WrongAudience2019--- PASS: TestAudienceForIssuer (0.00s)2020=== CONT TestScopes_Rules2021=== CONT TestValidateToken_ValidToken2022=== RUN TestGlobMatch/foo_foo2023=== PAUSE TestGlobMatch/foo_foo2024=== RUN TestGlobMatch/foo_bar2025=== PAUSE TestGlobMatch/foo_bar2026=== RUN TestGlobMatch/*_2027=== PAUSE TestGlobMatch/*_2028=== RUN TestGlobMatch/*_anything2029=== PAUSE TestGlobMatch/*_anything2030=== RUN TestGlobMatch/foo*_foo2031=== PAUSE TestGlobMatch/foo*_foo2032=== RUN TestGlobMatch/foo*_foobar2033=== PAUSE TestGlobMatch/foo*_foobar2034=== RUN TestGlobMatch/foo*_bar2035=== PAUSE TestGlobMatch/foo*_bar2036=== RUN TestGlobMatch/*bar_bar2037=== PAUSE TestGlobMatch/*bar_bar2038=== RUN TestGlobMatch/*bar_foobar2039=== PAUSE TestGlobMatch/*bar_foobar2040=== RUN TestGlobMatch/*bar_foo2041=== PAUSE TestGlobMatch/*bar_foo2042=== RUN TestGlobMatch/foo*bar_foobar2043=== PAUSE TestGlobMatch/foo*bar_foobar2044=== RUN TestGlobMatch/foo*bar_foo123bar2045=== PAUSE TestGlobMatch/foo*bar_foo123bar2046=== RUN TestGlobMatch/foo*bar_foobarbaz2047=== PAUSE TestGlobMatch/foo*bar_foobarbaz2048=== RUN TestGlobMatch/*/*_foo/bar2049=== PAUSE TestGlobMatch/*/*_foo/bar2050=== RUN TestGlobMatch/*/*_foo2051=== PAUSE TestGlobMatch/*/*_foo2052=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2053=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2054=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02055=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02056=== RUN TestGlobMatch/refs/*/main_refs/heads/main2057=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2058=== RUN TestGlobMatch/fo?_foo2059=== PAUSE TestGlobMatch/fo?_foo2060=== RUN TestGlobMatch/fo?_fo2061=== PAUSE TestGlobMatch/fo?_fo2062=== RUN TestGlobMatch/fo?_fooo2063=== PAUSE TestGlobMatch/fo?_fooo2064=== RUN TestGlobMatch/?oo_foo2065=== PAUSE TestGlobMatch/?oo_foo2066=== RUN TestGlobMatch/?oo_boo2067=== PAUSE TestGlobMatch/?oo_boo2068=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2069=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2070=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2071=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2072=== CONT TestScopes_ConfigValidation2073--- PASS: TestScopes_ConfigValidation (0.00s)2074=== CONT TestScopes_LegacyProviderDefaultsToWrite20752026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61394/oidc20762026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61390/oidc20772026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61391/oidc20782026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61393/oidc20792026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61389/oidc20802026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61397/oidc20812026/09/09 10:30:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:61392/oidc20822026/09/09 10:30:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:61398/oidc2083--- PASS: TestValidateToken_Expired (0.01s)2084=== CONT TestValidateToken_KubernetesIssuerFromOwnToken20852026/09/09 10:30:03 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:61395/oidc2086--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2087=== CONT TestValidateToken_KubernetesServiceAccount2088--- PASS: TestValidateToken_WrongAudience (0.01s)2089=== CONT TestGlobMatch/foo_foo2090=== CONT TestGlobMatch/*/*_foo/bar2091=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2092=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2093=== CONT TestGlobMatch/?oo_boo2094=== CONT TestGlobMatch/?oo_foo2095=== CONT TestGlobMatch/fo?_fooo2096=== CONT TestGlobMatch/fo?_fo2097=== CONT TestGlobMatch/fo?_foo2098=== CONT TestGlobMatch/refs/*/main_refs/heads/main2099=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02100=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2101=== CONT TestGlobMatch/*/*_foo2102=== CONT TestGlobMatch/*bar_bar2103=== CONT TestGlobMatch/foo*bar_foobarbaz2104=== CONT TestGlobMatch/foo*bar_foo123bar2105=== CONT TestGlobMatch/foo*bar_foobar2106=== CONT TestGlobMatch/*bar_foo2107=== CONT TestGlobMatch/*bar_foobar2108=== CONT TestGlobMatch/foo*_foo2109=== CONT TestGlobMatch/foo*_bar2110=== CONT TestGlobMatch/foo*_foobar21112026/09/09 10:30:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61408/oidc2112=== CONT TestGlobMatch/*_2113=== CONT TestGlobMatch/*_anything2114=== CONT TestGlobMatch/foo_bar2115--- PASS: TestGlobMatch (0.00s)2116 --- PASS: TestGlobMatch/foo_foo (0.00s)2117 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2118 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2119 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2120 --- PASS: TestGlobMatch/?oo_boo (0.00s)2121 --- PASS: TestGlobMatch/?oo_foo (0.00s)2122 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2123 --- PASS: TestGlobMatch/fo?_fo (0.00s)2124 --- PASS: TestGlobMatch/fo?_foo (0.00s)2125 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2126 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2127 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2128 --- PASS: TestGlobMatch/*/*_foo (0.00s)2129 --- PASS: TestGlobMatch/*bar_bar (0.00s)2130 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2131 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2132 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2133 --- PASS: TestGlobMatch/*bar_foo (0.00s)2134 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2135 --- PASS: TestGlobMatch/foo*_foo (0.00s)2136 --- PASS: TestGlobMatch/foo*_bar (0.00s)2137 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2138 --- PASS: TestGlobMatch/*_ (0.00s)2139 --- PASS: TestGlobMatch/*_anything (0.00s)2140 --- PASS: TestGlobMatch/foo_bar (0.00s)2141--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2142--- PASS: TestValidateToken_ValidToken (0.01s)2143--- PASS: TestValidateToken_MultipleProviders (0.01s)2144--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2145--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)21462026/09/09 10:30:03 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12321472026/09/09 10:30:03 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:6141221482026/09/09 10:30:03 http: TLS handshake error from 127.0.0.1:61406: remote error: tls: bad certificate2149--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2150--- PASS: TestScopes_Rules (0.01s)2151--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)2152--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)2153PASS2154Running hook tests...2155=== RUN TestSendPathsEmpty2156=== PAUSE TestSendPathsEmpty2157=== RUN TestQueueEnqueueAndFetch2158=== PAUSE TestQueueEnqueueAndFetch2159=== RUN TestQueueDeduplication2160=== PAUSE TestQueueDeduplication2161=== RUN TestQueueRemove2162=== PAUSE TestQueueRemove2163=== RUN TestQueueFetchBatchLimit2164=== PAUSE TestQueueFetchBatchLimit2165=== RUN TestQueueRetryMovesToBack2166=== PAUSE TestQueueRetryMovesToBack2167=== RUN TestQueueFetchRemoveLifecycle2168=== PAUSE TestQueueFetchRemoveLifecycle2169=== RUN TestQueueConcurrentWriters2170=== PAUSE TestQueueConcurrentWriters2171=== RUN TestQueueRemoveLargeClosure2172=== PAUSE TestQueueRemoveLargeClosure2173=== RUN TestServerClientIntegration2174=== PAUSE TestServerClientIntegration2175=== RUN TestServerQueueError2176=== PAUSE TestServerQueueError2177=== RUN TestGetListenerSocketActivation2178 server_test.go:210: === RUN TestGetListenerSocketActivation2179 --- PASS: TestGetListenerSocketActivation (0.00s)2180 PASS2181 2182--- PASS: TestGetListenerSocketActivation (0.01s)2183=== RUN TestDrainIsolatesPoisonPath2184=== PAUSE TestDrainIsolatesPoisonPath2185=== RUN TestRunNotBlockedByPoisonHead2186=== PAUSE TestRunNotBlockedByPoisonHead2187=== RUN TestDrainGivesUpWhenServerDown2188=== PAUSE TestDrainGivesUpWhenServerDown2189=== RUN TestFailedPathPrunedByLaterClosure2190=== PAUSE TestFailedPathPrunedByLaterClosure2191=== RUN TestWorkerUploadsAndRemoves2192=== PAUSE TestWorkerUploadsAndRemoves2193=== RUN TestWorkerSkipsGCdPaths2194=== PAUSE TestWorkerSkipsGCdPaths2195=== RUN TestWorkerPrunesClosureDeps2196=== PAUSE TestWorkerPrunesClosureDeps2197=== RUN TestDrainTimeout2198=== PAUSE TestDrainTimeout2199=== CONT TestSendPathsEmpty2200=== CONT TestServerQueueError2201--- PASS: TestSendPathsEmpty (0.00s)2202=== CONT TestWorkerUploadsAndRemoves2203=== CONT TestServerClientIntegration2204=== CONT TestQueueRemoveLargeClosure2205=== CONT TestQueueConcurrentWriters2206=== CONT TestQueueFetchRemoveLifecycle2207=== CONT TestQueueRetryMovesToBack2208=== CONT TestQueueFetchBatchLimit2209=== CONT TestQueueRemove2210=== CONT TestQueueDeduplication22112026/09/09 10:30:03 ERROR Failed to queue paths error="permission denied" count=12212--- PASS: TestServerQueueError (0.00s)2213--- PASS: TestServerClientIntegration (0.00s)2214=== CONT TestDrainGivesUpWhenServerDown2215=== CONT TestQueueEnqueueAndFetch22162026/09/09 10:30:03 INFO Upload queue status pending=222172026/09/09 10:30:03 INFO Uploading batch count=22218--- PASS: TestQueueEnqueueAndFetch (0.01s)2219=== CONT TestFailedPathPrunedByLaterClosure22202026/09/09 10:30:03 INFO Uploading batch count=222212026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=222222026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainGivesUpWhenServerDown3625636287/002/a2223--- PASS: TestQueueFetchBatchLimit (0.01s)2224=== CONT TestWorkerPrunesClosureDeps22252026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainGivesUpWhenServerDown3625636287/002/b2226--- PASS: TestQueueRemove (0.01s)2227=== CONT TestDrainTimeout2228--- PASS: TestQueueDeduplication (0.01s)2229=== CONT TestRunNotBlockedByPoisonHead22302026/09/09 10:30:03 INFO Uploading batch count=222312026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=222322026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainGivesUpWhenServerDown3625636287/002/c22332026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainGivesUpWhenServerDown3625636287/002/d2234--- PASS: TestQueueRetryMovesToBack (0.01s)2235=== CONT TestDrainIsolatesPoisonPath2236--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2237=== CONT TestWorkerSkipsGCdPaths22382026/09/09 10:30:03 INFO Uploading batch count=222392026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=222402026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainGivesUpWhenServerDown3625636287/002/e22412026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainGivesUpWhenServerDown3625636287/002/f22422026/09/09 10:30:03 ERROR Drain finished with paths left in queue remaining=1022432026/09/09 10:30:03 INFO Uploading batch count=122442026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=122452026/09/09 10:30:03 INFO Upload queue status pending=222462026/09/09 10:30:03 INFO Uploading batch count=122472026/09/09 10:30:03 INFO Uploading batch count=122482026/09/09 10:30:03 INFO Uploading batch count=222492026/09/09 10:30:03 INFO Uploading batch count=422502026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=422512026/09/09 10:30:03 INFO Uploading batch count=122522026/09/09 10:30:03 INFO Upload queue status pending=322532026/09/09 10:30:03 INFO Uploading batch count=122542026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=122552026/09/09 10:30:03 INFO Upload queue status pending=222562026/09/09 10:30:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-24452-4259264778/TestWorkerSkipsGCdPaths3735631086/002/nonexistent22572026/09/09 10:30:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-24452-4259264778/TestDrainIsolatesPoisonPath1894898658/002/bbb2258--- PASS: TestDrainGivesUpWhenServerDown (0.01s)22592026/09/09 10:30:03 INFO Uploading batch count=122602026/09/09 10:30:03 INFO Uploading batch count=122612026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=122622026/09/09 10:30:03 INFO Uploading batch count=122632026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=122642026/09/09 10:30:03 INFO Uploading batch count=122652026/09/09 10:30:03 ERROR Upload failed error="upload failed" count=122662026/09/09 10:30:03 ERROR Drain finished with paths left in queue remaining=12267--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2268--- PASS: TestDrainIsolatesPoisonPath (0.01s)2269--- PASS: TestWorkerUploadsAndRemoves (0.03s)2270--- PASS: TestWorkerPrunesClosureDeps (0.02s)2271--- PASS: TestWorkerSkipsGCdPaths (0.02s)2272--- PASS: TestQueueRemoveLargeClosure (0.06s)2273--- PASS: TestQueueConcurrentWriters (0.16s)22742026/09/09 10:30:03 ERROR Upload failed error="context deadline exceeded" count=222752026/09/09 10:30:03 ERROR Drain finished with paths left in queue remaining=42276--- PASS: TestDrainTimeout (0.21s)22772026/09/09 10:30:04 INFO Uploading batch count=122782026/09/09 10:30:04 INFO Uploading batch count=122792026/09/09 10:30:04 INFO Uploading batch count=122802026/09/09 10:30:04 ERROR Upload failed error="upload failed" count=122812026/09/09 10:30:04 INFO Uploading batch count=122822026/09/09 10:30:04 ERROR Upload failed error="upload failed" count=122832026/09/09 10:30:04 INFO Uploading batch count=122842026/09/09 10:30:04 ERROR Upload failed error="upload failed" count=122852026/09/09 10:30:04 INFO Uploading batch count=122862026/09/09 10:30:04 ERROR Upload failed error="upload failed" count=122872026/09/09 10:30:04 ERROR Drain finished with paths left in queue remaining=12288--- PASS: TestRunNotBlockedByPoisonHead (1.01s)2289PASS