niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #244
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (2.27s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestSetClientTLS65=== PAUSE TestSetClientTLS66=== RUN TestSetClientTLSDoesNotMutateDefaultTransport67=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport68=== RUN TestSetClientTLSErrors69=== PAUSE TestSetClientTLSErrors70=== RUN TestStaticToken71=== PAUSE TestStaticToken72=== RUN TestFileTokenReadsAndCaches73=== PAUSE TestFileTokenReadsAndCaches74=== RUN TestFileTokenMissing75=== PAUSE TestFileTokenMissing76=== RUN TestFileTokenEmpty77=== PAUSE TestFileTokenEmpty78=== RUN TestScriptTokenNoExpiryRerunsEveryCall79=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall80=== RUN TestScriptTokenCachesUntilRefresh81=== PAUSE TestScriptTokenCachesUntilRefresh82=== RUN TestScriptTokenEmptyToken83=== PAUSE TestScriptTokenEmptyToken84=== RUN TestScriptTokenBadJSON85=== PAUSE TestScriptTokenBadJSON86=== RUN TestScriptTokenScriptFails87=== PAUSE TestScriptTokenScriptFails88=== RUN TestScriptTokenEmptyCommand89=== PAUSE TestScriptTokenEmptyCommand90=== CONT TestDoServerRequestAttachesToken91=== CONT TestDoWithRetry_BodyReplayedViaGetBody92=== CONT TestEncodeNixBase32WithRealHash93=== CONT TestResolveStorePath94=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess95--- PASS: TestEncodeNixBase32WithRealHash (0.00s)96=== CONT TestGetStorePathHash97=== CONT TestRateLimiterFeedback98=== RUN TestRateLimiterFeedback/429_enables_limiter99=== PAUSE TestRateLimiterFeedback/429_enables_limiter100=== RUN TestRateLimiterFeedback/503_enables_limiter101=== PAUSE TestRateLimiterFeedback/503_enables_limiter102=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter103=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter104=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter105=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter106=== CONT TestPathInfoCACompatibility107=== RUN TestPathInfoCACompatibility/null_ca_field108=== CONT TestConvertHashToNix32109=== PAUSE TestPathInfoCACompatibility/null_ca_field110=== CONT TestParsePathInfoJSONMultiplePaths111=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths112=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths113=== CONT TestParsePathInfoJSON114=== CONT TestPathInfoHashCompatibility115=== RUN TestPathInfoCACompatibility/old_string_format_-_text116=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)117=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)118=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text119=== RUN TestGetStorePathHash/valid_store_path120=== PAUSE TestGetStorePathHash/valid_store_path121=== RUN TestGetStorePathHash/basename_without_hyphen_should_error122=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error123=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error124=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error125=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error126=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error127=== CONT TestUploadMultipart_SupersededByPeer128=== RUN TestUploadMultipart_SupersededByPeer/exists129=== PAUSE TestUploadMultipart_SupersededByPeer/exists130=== RUN TestUploadMultipart_SupersededByPeer/missing131=== PAUSE TestUploadMultipart_SupersededByPeer/missing132=== CONT TestEncodeNixBase32133=== RUN TestEncodeNixBase32/test_string_hash134=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon135=== RUN TestConvertHashToNix32/SRI_format_to_Nix32136=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32137=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon138=== RUN TestConvertHashToNix32/already_Nix32_format139=== PAUSE TestConvertHashToNix32/already_Nix32_format140=== RUN TestConvertHashToNix32/invalid_format141=== PAUSE TestConvertHashToNix32/invalid_format142=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI143=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI144=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512145=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512146=== CONT TestDumpPathWriterError147--- PASS: TestResolveStorePath (0.00s)148=== CONT TestDumpPathMatchesNix149=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive150=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive151=== RUN TestPathInfoCACompatibility/new_structured_format_-_text152=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text153=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths154=== CONT TestDumpPathSingleFile155=== PAUSE TestEncodeNixBase32/test_string_hash156=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method157=== RUN TestEncodeNixBase32/empty_input158=== RUN TestParsePathInfoJSON/Nix_format159=== PAUSE TestEncodeNixBase32/empty_input160=== CONT TestCaseHackSuffix161=== PAUSE TestParsePathInfoJSON/Nix_format162=== RUN TestParsePathInfoJSON/Lix_format163=== PAUSE TestParsePathInfoJSON/Lix_format164=== RUN TestParsePathInfoJSON/empty_input165=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths166=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method167=== CONT TestFilterOversizedClosures168=== RUN TestFilterOversizedClosures/no_limit_keeps_everything1692026/09/22 08:15:02 WARN Rate limiter enabled after throttle name=server-test rate=5170=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything171=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped172=== CONT TestStaticToken173=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped174=== RUN TestFilterOversizedClosures/all_closures_skipped175--- PASS: TestStaticToken (0.00s)176=== PAUSE TestFilterOversizedClosures/all_closures_skipped177=== CONT TestPartSizeForNAR178=== RUN TestPartSizeForNAR/zero_stays_at_minimum179=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum180=== RUN TestPartSizeForNAR/small_stays_at_minimum181=== PAUSE TestParsePathInfoJSON/empty_input182=== CONT TestScriptTokenEmptyCommand183--- PASS: TestScriptTokenEmptyCommand (0.00s)184=== CONT TestUploadMultipart_PartsInParallel185=== RUN TestParsePathInfoJSON/whitespace_only186=== PAUSE TestParsePathInfoJSON/whitespace_only187=== RUN TestParsePathInfoJSON/invalid_JSON188=== PAUSE TestParsePathInfoJSON/invalid_JSON189=== PAUSE TestPartSizeForNAR/small_stays_at_minimum190=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum191=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum192=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts193=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts194=== RUN TestPartSizeForNAR/1_TiB195=== PAUSE TestPartSizeForNAR/1_TiB196=== RUN TestPartSizeForNAR/5_TiB_S3_max_object197=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object198=== CONT TestScriptTokenScriptFails199=== RUN TestPartSizeForNAR/capped_at_5_GiB200=== PAUSE TestPartSizeForNAR/capped_at_5_GiB201=== CONT TestScriptTokenBadJSON2022026/09/22 08:15:02 WARN Rate limiter enabled after throttle name=server-test rate=52032026/09/22 08:15:02 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:521762042026/09/22 08:15:02 WARN Rate limiter backed off name=server-test rate=5205--- PASS: TestDoServerRequestAttachesToken (0.01s)2062026/09/22 08:15:02 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52176207=== CONT TestStreamPushGivesUpOnDeadServer2082026/09/22 08:15:02 ERROR Upload failed error="connection refused" count=20209--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)2102026/09/22 08:15:02 ERROR Server seems unavailable, giving up on batch untried=17211=== CONT TestScriptTokenEmptyToken212--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)213=== CONT TestSetClientTLSErrors214--- PASS: TestScriptTokenScriptFails (0.01s)215=== CONT TestScriptTokenCachesUntilRefresh216=== RUN TestSetClientTLSErrors/missing_cert_file217=== PAUSE TestSetClientTLSErrors/missing_cert_file218=== RUN TestSetClientTLSErrors/missing_key_file219=== PAUSE TestSetClientTLSErrors/missing_key_file220=== RUN TestSetClientTLSErrors/missing_ca_file221=== PAUSE TestSetClientTLSErrors/missing_ca_file222=== RUN TestSetClientTLSErrors/invalid_ca_file223=== PAUSE TestSetClientTLSErrors/invalid_ca_file224=== CONT TestSetClientTLSDoesNotMutateDefaultTransport225--- PASS: TestScriptTokenBadJSON (0.01s)226=== CONT TestScriptTokenNoExpiryRerunsEveryCall227--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)228=== CONT TestSetClientTLS229=== RUN TestSetClientTLS/rejects_connection_without_client_cert230=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert231=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA232=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA233=== RUN TestSetClientTLS/preserves_debug_logging_transport234=== PAUSE TestSetClientTLS/preserves_debug_logging_transport235=== CONT TestStreamPushRequestLine2362026/09/22 08:15:02 ERROR Upload failed error=boom count=1237--- PASS: TestScriptTokenEmptyToken (0.01s)238=== CONT TestFileTokenEmpty239--- PASS: TestFileTokenEmpty (0.00s)240=== CONT TestStreamPushReportsEveryPath241--- PASS: TestStreamPushReportsEveryPath (0.00s)242=== CONT TestFileTokenMissing243--- PASS: TestFileTokenMissing (0.00s)244=== CONT TestStreamPushIsolatesFailures2452026/09/22 08:15:02 ERROR Upload failed error="bad path" count=3246--- PASS: TestStreamPushIsolatesFailures (0.00s)247=== CONT TestFileTokenReadsAndCaches248--- PASS: TestFileTokenReadsAndCaches (0.00s)249=== CONT TestStreamPushBatchesUnderLoad250--- PASS: TestStreamPushRequestLine (0.01s)251=== CONT TestShellSplitErrors252--- PASS: TestShellSplitErrors (0.00s)253=== CONT TestShellSplit254--- PASS: TestShellSplit (0.00s)255=== CONT TestRegisterUploadedObjectReusesConnections256--- PASS: TestDumpPathWriterError (0.05s)257=== CONT TestRateLimiterFeedback/429_enables_limiter2582026/09/22 08:15:02 WARN Rate limiter enabled after throttle name=server-test rate=52592026/09/22 08:15:02 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:522512602026/09/22 08:15:02 WARN Rate limiter backed off name=server-test rate=5261=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter262=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter263=== CONT TestRateLimiterFeedback/503_enables_limiter2642026/09/22 08:15:02 WARN Rate limiter enabled after throttle name=server-test rate=52652026/09/22 08:15:02 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:522572662026/09/22 08:15:02 WARN Rate limiter backed off name=server-test rate=5267--- PASS: TestRateLimiterFeedback (0.00s)268 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)269 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)270 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)271 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)272=== CONT TestGetStorePathHash/valid_store_path273=== CONT TestUploadMultipart_SupersededByPeer/exists274=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error275=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error276=== CONT TestGetStorePathHash/basename_without_hyphen_should_error277--- PASS: TestGetStorePathHash (0.00s)278 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)279 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)280 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)281 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)282=== CONT TestUploadMultipart_SupersededByPeer/missing283--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)284=== CONT TestConvertHashToNix32/SRI_format_to_Nix32285=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)286=== CONT TestConvertHashToNix32/invalid_format287=== CONT TestConvertHashToNix32/already_Nix32_format288--- PASS: TestConvertHashToNix32 (0.00s)289 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)290 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)291 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)292=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI293=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512294=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon295--- PASS: TestPathInfoHashCompatibility (0.00s)296 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)297 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)298 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)299 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)300=== CONT TestEncodeNixBase32/test_string_hash301=== CONT TestEncodeNixBase32/empty_input302=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths303=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths304=== CONT TestPathInfoCACompatibility/null_ca_field305=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method306--- PASS: TestEncodeNixBase32 (0.00s)307 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)308 --- PASS: TestEncodeNixBase32/empty_input (0.00s)309=== CONT TestFilterOversizedClosures/no_limit_keeps_everything310--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)311 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)312 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)313=== CONT TestFilterOversizedClosures/all_closures_skipped3142026/09/22 08:15:02 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50315=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive316=== CONT TestPathInfoCACompatibility/new_structured_format_-_text317=== CONT TestPathInfoCACompatibility/old_string_format_-_text318--- PASS: TestPathInfoCACompatibility (0.00s)319 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)320 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)321 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)322 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)323 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)324=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3252026/09/22 08:15:02 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000326--- PASS: TestFilterOversizedClosures (0.00s)327 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)328 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)329 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)330--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)331 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)332 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)333=== CONT TestParsePathInfoJSON/Nix_format334=== CONT TestParsePathInfoJSON/whitespace_only335=== CONT TestParsePathInfoJSON/empty_input336=== CONT TestParsePathInfoJSON/Lix_format337=== CONT TestParsePathInfoJSON/invalid_JSON338--- PASS: TestParsePathInfoJSON (0.00s)339 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)340 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)341 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)342 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)343 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)344=== CONT TestPartSizeForNAR/zero_stays_at_minimum345=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum346=== CONT TestPartSizeForNAR/small_stays_at_minimum347=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts348=== CONT TestPartSizeForNAR/capped_at_5_GiB349=== CONT TestPartSizeForNAR/5_TiB_S3_max_object350=== CONT TestSetClientTLSErrors/missing_cert_file351=== CONT TestPartSizeForNAR/1_TiB352=== CONT TestSetClientTLSErrors/missing_ca_file353--- PASS: TestPartSizeForNAR (0.00s)354 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)355 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)356 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)357 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)358 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)359 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)360 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)361=== CONT TestSetClientTLSErrors/invalid_ca_file362=== CONT TestSetClientTLSErrors/missing_key_file363=== CONT TestSetClientTLS/rejects_connection_without_client_cert364=== CONT TestSetClientTLS/preserves_debug_logging_transport365--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)366=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA367--- PASS: TestSetClientTLSErrors (0.00s)368 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)369 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)370 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)371 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)372--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)373--- PASS: TestDumpPathSingleFile (0.06s)374--- PASS: TestCaseHackSuffix (0.06s)3752026/09/22 08:15:02 http: TLS handshake error from 127.0.0.1:52263: remote error: tls: bad certificate376--- PASS: TestSetClientTLS (0.00s)377 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)378 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)379 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)380--- PASS: TestDumpPathMatchesNix (0.08s)381--- PASS: TestStreamPushBatchesUnderLoad (0.10s)382--- PASS: TestUploadMultipart_PartsInParallel (0.62s)383--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)384PASS385Running server tests...386The files belonging to this database system will be owned by user "_nixbld10".387This user must also own the server process.388389The database cluster will be initialized with locale "C".390The default database encoding has accordingly been set to "SQL_ASCII".391The default text search configuration will be set to "english".392393Data page checksums are enabled.394395creating directory /nix/var/nix/builds/nix-60192-1958902681/postgres2616795086/data ... ok396creating subdirectories ... ok397selecting dynamic shared memory implementation ... posix398selecting default "max_connections" ... 100399selecting default "shared_buffers" ... 128MB400selecting default time zone ... UTC401creating configuration files ... ok402running bootstrap script ... ok403performing post-bootstrap initialization ... ok404syncing data to disk ... ok405406initdb: warning: enabling "trust" authentication for local connections407initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.408409Success. You can now start the database server using:410411 pg_ctl -D /nix/var/nix/builds/nix-60192-1958902681/postgres2616795086/data -l logfile start412413/nix/var/nix/builds/nix-60192-1958902681/postgres2616795086:5432 - no response4142026-09-22 08:15:03.947 UTC [60277] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4152026-09-22 08:15:03.947 UTC [60277] LOG: listening on Unix socket "/nix/var/nix/builds/nix-60192-1958902681/postgres2616795086/.s.PGSQL.5432"4162026-09-22 08:15:03.949 UTC [60284] LOG: database system was shut down at 2026-09-22 08:15:03 UTC4172026-09-22 08:15:03.950 UTC [60277] LOG: database system is ready to accept connections418/nix/var/nix/builds/nix-60192-1958902681/postgres2616795086:5432 - accepting connections419{"timestamp":"2026-09-22T08:15:05.810427Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c718dacc-0e7e-45ae-b85f-eee15fe4bb3e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":2,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}420{"timestamp":"2026-09-22T08:15:05.914797Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c359ac0f-6599-4d04-9e1c-4d643185c571","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}421=== RUN TestService_AuthMiddleware422=== PAUSE TestService_AuthMiddleware423=== RUN TestService_AuthMiddleware_MTLSProxyHeader424=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader425=== RUN TestService_AuthMiddleware_MTLSBoundSubjects426=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects427=== RUN TestService_ReadAuthMiddleware428=== PAUSE TestService_ReadAuthMiddleware429=== RUN TestService_AuthMiddleware_OIDC430=== PAUSE TestService_AuthMiddleware_OIDC431=== RUN TestService_RequireScope_OIDC432=== PAUSE TestService_RequireScope_OIDC433=== RUN TestService_ReadScope_PublicByDefault434=== PAUSE TestService_ReadScope_PublicByDefault435=== RUN TestCacheConfigHandler436=== PAUSE TestCacheConfigHandler437=== RUN TestCacheStatsHandler438=== PAUSE TestCacheStatsHandler439=== RUN TestClientCADerivations440=== PAUSE TestClientCADerivations441=== RUN TestClientErrorHandling442=== PAUSE TestClientErrorHandling443=== RUN TestClientIntegration444=== PAUSE TestClientIntegration445=== RUN TestClientMultipleUploads446=== PAUSE TestClientMultipleUploads447=== RUN TestClientWithDependencies448=== PAUSE TestClientWithDependencies449=== RUN TestClientSharedPathCommittedMidPush450=== PAUSE TestClientSharedPathCommittedMidPush451=== RUN TestPinProtectsFromGC452=== PAUSE TestPinProtectsFromGC453=== RUN TestResolveDBConnectionString454=== PAUSE TestResolveDBConnectionString455=== RUN TestLeadElectsOneAndHandsOver456=== PAUSE TestLeadElectsOneAndHandsOver457=== RUN TestLeadIncumbentWinsAfterRestart4582026-09-22 08:15:06.113 UTC [60314] ERROR: relation "goose_db_version" does not exist at character 364592026-09-22 08:15:06.113 UTC [60314] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4602026/09/22 08:15:06 OK 20241026095416_initial_model.sql (3.52ms)4612026/09/22 08:15:06 OK 20251210153512_drop_unused_gin_index.sql (495.79µs)4622026/09/22 08:15:06 OK 20251218171726_add_pins.sql (872.58µs)4632026/09/22 08:15:06 OK 20260628120000_add_object_size_and_stats.sql (807.88µs)4642026/09/22 08:15:06 OK 20260905000000_add_claims.sql (1.09ms)4652026/09/22 08:15:06 OK 20260920000000_drop_claims.sql (565.04µs)4662026/09/22 08:15:06 goose: successfully migrated database to version: 202609200000004672026/09/22 08:15:06 OK 1_commit_pending_closure.sql (819.79µs)4682026/09/22 08:15:06 OK 2_object_stats_trigger.sql (204.38µs)4692026/09/22 08:15:06 goose: up to current file version: 24702026/09/22 08:15:06 INFO lead: acquired remote=192.0.2.1:12344712026/09/22 08:15:06 INFO lead: released remote=192.0.2.1:12344722026/09/22 08:15:06 INFO lead: acquired remote=192.0.2.1:12344732026/09/22 08:15:06 INFO lead: released remote=192.0.2.1:1234474--- PASS: TestLeadIncumbentWinsAfterRestart (0.81s)475=== RUN TestLeadEndsOnShutdown476=== PAUSE TestLeadEndsOnShutdown477=== RUN TestGCAdvisoryLockBlocksConcurrentRun4782026-09-22 08:15:06.929 UTC [60318] ERROR: relation "goose_db_version" does not exist at character 364792026-09-22 08:15:06.929 UTC [60318] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4802026/09/22 08:15:06 OK 20241026095416_initial_model.sql (4.15ms)4812026/09/22 08:15:06 OK 20251210153512_drop_unused_gin_index.sql (552.67µs)4822026/09/22 08:15:06 OK 20251218171726_add_pins.sql (861.25µs)4832026/09/22 08:15:06 OK 20260628120000_add_object_size_and_stats.sql (941.5µs)4842026/09/22 08:15:06 OK 20260905000000_add_claims.sql (1.19ms)4852026/09/22 08:15:06 OK 20260920000000_drop_claims.sql (653.75µs)4862026/09/22 08:15:06 goose: successfully migrated database to version: 202609200000004872026/09/22 08:15:06 OK 1_commit_pending_closure.sql (895.88µs)4882026/09/22 08:15:06 OK 2_object_stats_trigger.sql (225.67µs)4892026/09/22 08:15:06 goose: up to current file version: 2490--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.17s)491=== RUN TestGCBugBareHashReferences492=== PAUSE TestGCBugBareHashReferences493=== RUN TestGCMetrics494=== PAUSE TestGCMetrics495=== RUN TestGCTaskStore_StartNew496=== PAUSE TestGCTaskStore_StartNew497=== RUN TestGCTaskStore_DeduplicateSameParams498=== PAUSE TestGCTaskStore_DeduplicateSameParams499=== RUN TestGCTaskStore_ConflictDifferentParams500=== PAUSE TestGCTaskStore_ConflictDifferentParams501=== RUN TestGCTaskStore_GetEmpty502=== PAUSE TestGCTaskStore_GetEmpty503=== RUN TestGCTaskStore_GetReturnsLatest504=== PAUSE TestGCTaskStore_GetReturnsLatest505=== RUN TestGCTaskStore_CompletedAllowsNewTask506=== PAUSE TestGCTaskStore_CompletedAllowsNewTask507=== RUN TestGCTaskStore_PhaseUpdates508=== PAUSE TestGCTaskStore_PhaseUpdates509=== RUN TestGCTaskStore_Fail510=== PAUSE TestGCTaskStore_Fail511=== RUN TestGracefulShutdownDrainsInflight512=== PAUSE TestGracefulShutdownDrainsInflight513=== RUN TestService_healthCheckHandler514=== PAUSE TestService_healthCheckHandler515=== RUN TestService_readinessHandler516=== PAUSE TestService_readinessHandler517=== RUN TestGenerateLandingPage518=== PAUSE TestGenerateLandingPage519=== RUN TestCacheConfigHandlerMaxNarSize520=== PAUSE TestCacheConfigHandlerMaxNarSize521=== RUN TestCreatePendingClosureRejectsOversizedNAR522=== PAUSE TestCreatePendingClosureRejectsOversizedNAR523=== RUN TestNARDeduplicationMetadataUploadBug524=== PAUSE TestNARDeduplicationMetadataUploadBug525=== RUN TestMetricsInventory526=== PAUSE TestMetricsInventory527=== RUN TestService_NativeMTLS528=== PAUSE TestService_NativeMTLS529=== RUN TestServerTLSConfig530=== PAUSE TestServerTLSConfig531=== RUN TestMultipartCleanup532=== PAUSE TestMultipartCleanup533=== RUN TestObjectStatsTrigger534=== PAUSE TestObjectStatsTrigger535=== RUN TestOrphanedObjectsGC536=== PAUSE TestOrphanedObjectsGC537=== RUN TestOrphanedObjectsGCStressTest538=== PAUSE TestOrphanedObjectsGCStressTest539=== RUN TestResurrectedObjectNotDeleted540=== PAUSE TestResurrectedObjectNotDeleted541=== RUN TestCreatePin_ReservedPins542=== PAUSE TestCreatePin_ReservedPins543=== RUN TestParseSingleRange544=== PAUSE TestParseSingleRange545=== RUN TestIsValidCachePath546=== PAUSE TestIsValidCachePath547=== RUN TestReadProxyNarinfo548=== PAUSE TestReadProxyNarinfo549=== RUN TestReadProxyNarinfoAlreadyDecompressed550=== PAUSE TestReadProxyNarinfoAlreadyDecompressed551=== RUN TestReadProxyNarStreaming552=== PAUSE TestReadProxyNarStreaming553=== RUN TestReadProxy404554=== PAUSE TestReadProxy404555=== RUN TestReadProxyInvalidPath556=== PAUSE TestReadProxyInvalidPath557=== RUN TestReadProxyHead558=== PAUSE TestReadProxyHead559=== RUN TestReadProxyConditionalGet560=== PAUSE TestReadProxyConditionalGet561=== RUN TestReadProxyRootRedirectsToIndexHTML562=== PAUSE TestReadProxyRootRedirectsToIndexHTML563=== RUN TestReadProxyDisabled564=== PAUSE TestReadProxyDisabled565=== RUN TestReadRedirectNar566=== PAUSE TestReadRedirectNar567=== RUN TestReadRedirectKeepsNarinfoProxied568=== PAUSE TestReadRedirectKeepsNarinfoProxied569=== RUN TestReadProxyRangeRequest570=== PAUSE TestReadProxyRangeRequest571=== RUN TestReadRedirectUsesPublicS3URL572=== PAUSE TestReadRedirectUsesPublicS3URL573=== RUN TestRedundantMultipartUpload574=== PAUSE TestRedundantMultipartUpload575=== RUN TestCompleteMultipartUpload_ErrorButObjectExists576=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists577=== RUN TestCompletedNarNotReofferedAcrossClosures578=== PAUSE TestCompletedNarNotReofferedAcrossClosures579=== RUN TestPresignedUploadRegisteredBeforeCommit580=== PAUSE TestPresignedUploadRegisteredBeforeCommit581=== RUN TestService_Rustfstest582=== PAUSE TestService_Rustfstest583=== RUN TestParseSize584=== PAUSE TestParseSize585=== RUN TestSkippedUploadsHandler586=== PAUSE TestSkippedUploadsHandler587=== RUN TestSystemdListenerNotActivated588--- PASS: TestSystemdListenerNotActivated (0.00s)589=== RUN TestWatchdogBeatsWhenHealthy590--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)591=== RUN TestWatchdogSkipsWhenUnhealthy5922026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5932026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5942026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5952026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5962026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5972026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5982026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5992026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6002026/09/22 08:15:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"601--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)602=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle603=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle604=== RUN TestProxyWriteTimeout605=== PAUSE TestProxyWriteTimeout606=== RUN TestIsValidUploadKey607=== PAUSE TestIsValidUploadKey608=== RUN TestUploadHandlersRejectInvalidKeys609=== PAUSE TestUploadHandlersRejectInvalidKeys610=== RUN TestUploadHandlersRejectOversizedBody611=== PAUSE TestUploadHandlersRejectOversizedBody612=== RUN TestService_cleanupPendingClosuresHandler613=== PAUSE TestService_cleanupPendingClosuresHandler614=== RUN TestService_createPendingClosureHandler615=== PAUSE TestService_createPendingClosureHandler616=== RUN TestService_verifyS3Integrity617=== PAUSE TestService_verifyS3Integrity618=== RUN TestCompleteMultipartUnregistered619=== PAUSE TestCompleteMultipartUnregistered620=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT621=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT622=== CONT TestReadProxyDisabled623=== CONT TestService_AuthMiddleware624=== CONT TestSkippedUploadsHandler625=== CONT TestGCTaskStore_Fail626--- PASS: TestGCTaskStore_Fail (0.00s)627=== CONT TestOrphanedObjectsGCStressTest628=== CONT TestOrphanedObjectsGC629=== CONT TestObjectStatsTrigger630=== CONT TestMultipartCleanup631=== CONT TestServerTLSConfig632=== CONT TestService_NativeMTLS633=== CONT TestMetricsInventory6342026/09/22 08:15:07 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000635=== RUN TestServerTLSConfig/no_client_CA636=== PAUSE TestServerTLSConfig/no_client_CA637=== RUN TestServerTLSConfig/missing_CA_file638=== PAUSE TestServerTLSConfig/missing_CA_file639=== RUN TestServerTLSConfig/not_a_PEM_file640=== PAUSE TestServerTLSConfig/not_a_PEM_file641=== CONT TestNARDeduplicationMetadataUploadBug642--- PASS: TestSkippedUploadsHandler (0.01s)643=== CONT TestCreatePendingClosureRejectsOversizedNAR6442026/09/22 08:15:07 INFO Received uploads request method=POST path=/api/pending_closures645--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)646=== CONT TestCacheConfigHandlerMaxNarSize647--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)648=== CONT TestGenerateLandingPage649--- PASS: TestGenerateLandingPage (0.00s)650=== CONT TestService_readinessHandler6512026-09-22 08:15:07.618 UTC [60340] ERROR: relation "goose_db_version" does not exist at character 366522026-09-22 08:15:07.618 UTC [60340] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6532026-09-22 08:15:07.618 UTC [60341] ERROR: relation "goose_db_version" does not exist at character 366542026-09-22 08:15:07.618 UTC [60341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6552026-09-22 08:15:07.620 UTC [60343] ERROR: relation "goose_db_version" does not exist at character 366562026-09-22 08:15:07.620 UTC [60343] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6572026-09-22 08:15:07.621 UTC [60348] ERROR: relation "goose_db_version" does not exist at character 366582026-09-22 08:15:07.621 UTC [60348] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6592026-09-22 08:15:07.621 UTC [60344] ERROR: relation "goose_db_version" does not exist at character 366602026-09-22 08:15:07.621 UTC [60344] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6612026-09-22 08:15:07.622 UTC [60345] ERROR: relation "goose_db_version" does not exist at character 366622026-09-22 08:15:07.622 UTC [60345] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6632026-09-22 08:15:07.622 UTC [60342] ERROR: relation "goose_db_version" does not exist at character 366642026-09-22 08:15:07.622 UTC [60342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6652026-09-22 08:15:07.622 UTC [60347] ERROR: relation "goose_db_version" does not exist at character 366662026-09-22 08:15:07.622 UTC [60347] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6672026-09-22 08:15:07.622 UTC [60349] ERROR: relation "goose_db_version" does not exist at character 366682026-09-22 08:15:07.622 UTC [60349] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6692026-09-22 08:15:07.623 UTC [60346] ERROR: relation "goose_db_version" does not exist at character 366702026-09-22 08:15:07.623 UTC [60346] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6712026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.93ms)6722026/09/22 08:15:07 OK 20241026095416_initial_model.sql (6.03ms)6732026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.19ms)6742026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (981.67µs)6752026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (863.5µs)6762026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (887.08µs)6772026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.79ms)6782026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (701.79µs)6792026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.93ms)6802026/09/22 08:15:07 OK 20241026095416_initial_model.sql (8.32ms)6812026/09/22 08:15:07 OK 20251218171726_add_pins.sql (2.45ms)6822026/09/22 08:15:07 OK 20251218171726_add_pins.sql (1.99ms)6832026/09/22 08:15:07 OK 20251218171726_add_pins.sql (2.04ms)6842026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (719.88µs)6852026/09/22 08:15:07 OK 20251218171726_add_pins.sql (1.55ms)6862026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (734.38µs)6872026/09/22 08:15:07 OK 20241026095416_initial_model.sql (8.1ms)6882026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.67ms)6892026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.51ms)6902026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.13ms)6912026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.98ms)6922026/09/22 08:15:07 OK 20251218171726_add_pins.sql (1.79ms)6932026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.55ms)6942026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (2.33ms)6952026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (747.5µs)6962026/09/22 08:15:07 OK 20251218171726_add_pins.sql (1.69ms)6972026/09/22 08:15:07 OK 20241026095416_initial_model.sql (7.62ms)6982026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (607.58µs)6992026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)7002026/09/22 08:15:07 OK 20251210153512_drop_unused_gin_index.sql (694.71µs)7012026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.33ms)7022026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.73ms)7032026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.88ms)7042026/09/22 08:15:07 OK 20251218171726_add_pins.sql (1.72ms)7052026/09/22 08:15:07 OK 20260905000000_add_claims.sql (2.39ms)7062026/09/22 08:15:07 OK 20251218171726_add_pins.sql (1.31ms)7072026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (2.14ms)7082026/09/22 08:15:07 OK 20260905000000_add_claims.sql (2.52ms)7092026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.35ms)7102026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007112026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.16ms)7122026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007132026/09/22 08:15:07 OK 20251218171726_add_pins.sql (2.1ms)7142026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.78ms)7152026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.13ms)7162026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007172026/09/22 08:15:07 OK 20251218171726_add_pins.sql (2.6ms)7182026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.53ms)7192026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.59ms)7202026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.37ms)7212026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007222026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.02ms)7232026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007242026/09/22 08:15:07 OK 1_commit_pending_closure.sql (1.31ms)7252026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.19ms)7262026/09/22 08:15:07 OK 1_commit_pending_closure.sql (1.65ms)7272026/09/22 08:15:07 OK 1_commit_pending_closure.sql (1.73ms)7282026/09/22 08:15:07 OK 20260905000000_add_claims.sql (2.38ms)7292026/09/22 08:15:07 OK 20260628120000_add_object_size_and_stats.sql (1.94ms)7302026/09/22 08:15:07 OK 2_object_stats_trigger.sql (398.67µs)7312026/09/22 08:15:07 goose: up to current file version: 27322026/09/22 08:15:07 OK 1_commit_pending_closure.sql (998.75µs)7332026/09/22 08:15:07 OK 2_object_stats_trigger.sql (619.25µs)7342026/09/22 08:15:07 goose: up to current file version: 27352026/09/22 08:15:07 OK 2_object_stats_trigger.sql (591µs)7362026/09/22 08:15:07 goose: up to current file version: 27372026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.83ms)7382026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.56ms)7392026/09/22 08:15:07 OK 1_commit_pending_closure.sql (1.35ms)7402026/09/22 08:15:07 OK 2_object_stats_trigger.sql (403.71µs)7412026/09/22 08:15:07 goose: up to current file version: 27422026/09/22 08:15:07 OK 2_object_stats_trigger.sql (247.17µs)7432026/09/22 08:15:07 goose: up to current file version: 27442026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.38ms)7452026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007462026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.18ms)7472026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (886.96µs)7482026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007492026/09/22 08:15:07 OK 20260905000000_add_claims.sql (1.82ms)7502026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (1.48ms)7512026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007522026/09/22 08:15:07 OK 1_commit_pending_closure.sql (850.75µs)7532026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (794.63µs)7542026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007552026/09/22 08:15:07 OK 1_commit_pending_closure.sql (959.88µs)7562026/09/22 08:15:07 OK 2_object_stats_trigger.sql (340.29µs)7572026/09/22 08:15:07 goose: up to current file version: 27582026/09/22 08:15:07 OK 2_object_stats_trigger.sql (271.21µs)7592026/09/22 08:15:07 goose: up to current file version: 27602026/09/22 08:15:07 OK 1_commit_pending_closure.sql (746.21µs)7612026/09/22 08:15:07 OK 2_object_stats_trigger.sql (200.5µs)7622026/09/22 08:15:07 goose: up to current file version: 27632026/09/22 08:15:07 OK 1_commit_pending_closure.sql (873.29µs)7642026/09/22 08:15:07 OK 2_object_stats_trigger.sql (173.96µs)7652026/09/22 08:15:07 goose: up to current file version: 27662026/09/22 08:15:07 OK 20260920000000_drop_claims.sql (5.63ms)7672026/09/22 08:15:07 goose: successfully migrated database to version: 202609200000007682026/09/22 08:15:07 OK 1_commit_pending_closure.sql (608.88µs)7692026/09/22 08:15:07 OK 2_object_stats_trigger.sql (199.29µs)7702026/09/22 08:15:07 goose: up to current file version: 2771--- PASS: TestReadProxyDisabled (0.47s)772=== CONT TestService_healthCheckHandler7732026/09/22 08:15:07 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"774--- PASS: TestService_AuthMiddleware (0.59s)775=== CONT TestGracefulShutdownDrainsInflight7762026/09/22 08:15:07 INFO Starting HTTP server address=127.0.0.1:523167772026/09/22 08:15:07 INFO Shutdown signal received, draining in-flight requests timeout=10s778--- PASS: TestGracefulShutdownDrainsInflight (0.07s)779=== CONT TestReadProxyNarStreaming7802026/09/22 08:15:08 WARN readiness check failed error="closed pool"781--- PASS: TestService_readinessHandler (0.99s)782=== CONT TestReadProxyRootRedirectsToIndexHTML783=== NAME TestNARDeduplicationMetadataUploadBug784 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-60192-1958902681/TestNARDeduplicationMetadataUploadBug3527292076/001/store/2gbizirjp07vlv4w90d3617jwxsypkmr-file1.txt7852026/09/22 08:15:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"7862026/09/22 08:15:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"787--- PASS: TestService_NativeMTLS (1.17s)788=== CONT TestReadProxyConditionalGet7892026/09/22 08:15:08 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7902026/09/22 08:15:08 INFO Received uploads request method=POST path=/api/pending_closures7912026/09/22 08:15:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7922026/09/22 08:15:08 INFO Uploading 2gbizirjp07vlv4w90d3617jwxsypkmr-file1.txt (160B)7932026-09-22 08:15:08.486 UTC [60366] ERROR: relation "goose_db_version" does not exist at character 367942026-09-22 08:15:08.486 UTC [60366] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026/09/22 08:15:08 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"7962026/09/22 08:15:08 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7972026/09/22 08:15:08 WARN Failed to register uploaded object key=2gbizirjp07vlv4w90d3617jwxsypkmr.ls error="server returned 404: 404 page not found\n"7982026/09/22 08:15:08 INFO Signed narinfos id=1 count=17992026/09/22 08:15:08 INFO Uploading 1 narinfos8002026/09/22 08:15:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8012026/09/22 08:15:08 WARN Failed to register uploaded object key=2gbizirjp07vlv4w90d3617jwxsypkmr.narinfo error="server returned 404: 404 page not found\n"8022026/09/22 08:15:08 INFO Completed upload id=18032026/09/22 08:15:08 INFO Upload complete. (152ms)804=== NAME TestNARDeduplicationMetadataUploadBug805 metadata_upload_test.go:54: Retrieved narinfo from S3:806 StorePath: /nix/var/nix/builds/nix-60192-1958902681/TestNARDeduplicationMetadataUploadBug3527292076/001/store/2gbizirjp07vlv4w90d3617jwxsypkmr-file1.txt807 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst808 Compression: zstd809 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf810 NarSize: 160811 References: 812 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf813 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)814 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):815 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}816=== NAME TestOrphanedObjectsGC817 orphaned_objects_gc_test.go:290: GC Test Summary:818 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A819 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B820 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)821 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)822 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects823--- PASS: TestOrphanedObjectsGC (1.31s)824=== CONT TestReadProxyHead825=== NAME TestNARDeduplicationMetadataUploadBug826 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-60192-1958902681/TestNARDeduplicationMetadataUploadBug3527292076/001/store/7mpdicqr8srk9af3hd079rin57r60fvk-file2.txt8272026/09/22 08:15:08 OK 20241026095416_initial_model.sql (122.74ms)8282026/09/22 08:15:08 OK 20251210153512_drop_unused_gin_index.sql (5.88ms)8292026/09/22 08:15:08 OK 20251218171726_add_pins.sql (25.93ms)8302026/09/22 08:15:08 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8312026/09/22 08:15:08 OK 20260628120000_add_object_size_and_stats.sql (24.64ms)8322026/09/22 08:15:08 INFO Received uploads request method=POST path=/api/pending_closures8332026/09/22 08:15:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)8342026/09/22 08:15:08 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign8352026/09/22 08:15:08 INFO Signed narinfos id=2 count=18362026/09/22 08:15:08 INFO Uploading 1 narinfos8372026/09/22 08:15:08 WARN Failed to register uploaded object key=7mpdicqr8srk9af3hd079rin57r60fvk.ls error="server returned 404: 404 page not found\n"838--- PASS: TestMetricsInventory (1.50s)839=== CONT TestReadProxyInvalidPath8402026/09/22 08:15:08 OK 20260905000000_add_claims.sql (45.48ms)8412026/09/22 08:15:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8422026/09/22 08:15:08 WARN Failed to register uploaded object key=7mpdicqr8srk9af3hd079rin57r60fvk.narinfo error="server returned 404: 404 page not found\n"8432026/09/22 08:15:08 INFO Completed upload id=28442026/09/22 08:15:08 INFO Upload complete. (116ms)845=== NAME TestNARDeduplicationMetadataUploadBug846 metadata_upload_test.go:76: Retrieved narinfo from S3:847 StorePath: /nix/var/nix/builds/nix-60192-1958902681/TestNARDeduplicationMetadataUploadBug3527292076/001/store/7mpdicqr8srk9af3hd079rin57r60fvk-file2.txt848 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst849 Compression: zstd850 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf851 NarSize: 160852 References: 853 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf854 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)855 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):856 {"version":1,"root":{"type":"regular","size":44}}8572026/09/22 08:15:08 OK 20260920000000_drop_claims.sql (24.32ms)8582026/09/22 08:15:08 goose: successfully migrated database to version: 202609200000008592026/09/22 08:15:08 OK 1_commit_pending_closure.sql (1.05ms)8602026/09/22 08:15:08 OK 2_object_stats_trigger.sql (257.75µs)8612026/09/22 08:15:08 goose: up to current file version: 2862--- PASS: TestNARDeduplicationMetadataUploadBug (1.58s)863=== CONT TestReadProxy4048642026-09-22 08:15:08.832 UTC [60379] ERROR: relation "goose_db_version" does not exist at character 368652026-09-22 08:15:08.832 UTC [60379] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC866--- PASS: TestObjectStatsTrigger (1.69s)867=== CONT TestService_cleanupPendingClosuresHandler8682026/09/22 08:15:08 OK 20241026095416_initial_model.sql (73.36ms)8692026/09/22 08:15:08 OK 20251210153512_drop_unused_gin_index.sql (1.14ms)8702026/09/22 08:15:08 OK 20251218171726_add_pins.sql (22.71ms)8712026/09/22 08:15:08 OK 20260628120000_add_object_size_and_stats.sql (31.95ms)8722026/09/22 08:15:09 INFO Received uploads request method=POST path=/api/pending_closures8732026/09/22 08:15:09 OK 20260905000000_add_claims.sql (56.75ms)8742026/09/22 08:15:09 OK 20260920000000_drop_claims.sql (48.79ms)8752026/09/22 08:15:09 goose: successfully migrated database to version: 202609200000008762026/09/22 08:15:09 OK 1_commit_pending_closure.sql (3.86ms)8772026/09/22 08:15:09 OK 2_object_stats_trigger.sql (1.31ms)8782026/09/22 08:15:09 goose: up to current file version: 28792026/09/22 08:15:09 INFO Received cleanup request method=DELETE path=/api/pending_closures8802026/09/22 08:15:09 INFO Aborted multipart uploads count=1881--- PASS: TestMultipartCleanup (1.96s)882=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT883--- PASS: TestService_healthCheckHandler (1.50s)884=== CONT TestCompleteMultipartUnregistered8852026-09-22 08:15:09.379 UTC [60388] ERROR: relation "goose_db_version" does not exist at character 368862026-09-22 08:15:09.379 UTC [60388] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC887--- PASS: TestReadProxyNarStreaming (1.54s)888=== CONT TestService_verifyS3Integrity8892026-09-22 08:15:09.520 UTC [60391] ERROR: relation "goose_db_version" does not exist at character 368902026-09-22 08:15:09.520 UTC [60391] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8912026/09/22 08:15:09 OK 20241026095416_initial_model.sql (91.21ms)8922026/09/22 08:15:09 OK 20251210153512_drop_unused_gin_index.sql (7.69ms)8932026/09/22 08:15:09 OK 20251218171726_add_pins.sql (15.08ms)8942026/09/22 08:15:09 OK 20260628120000_add_object_size_and_stats.sql (52.09ms)8952026/09/22 08:15:09 OK 20260905000000_add_claims.sql (23.05ms)8962026/09/22 08:15:09 OK 20260920000000_drop_claims.sql (17.54ms)8972026/09/22 08:15:09 goose: successfully migrated database to version: 202609200000008982026/09/22 08:15:09 OK 1_commit_pending_closure.sql (4.4ms)8992026/09/22 08:15:09 OK 2_object_stats_trigger.sql (710.67µs)9002026/09/22 08:15:09 goose: up to current file version: 29012026/09/22 08:15:09 OK 20241026095416_initial_model.sql (102.41ms)9022026/09/22 08:15:09 OK 20251210153512_drop_unused_gin_index.sql (10.64ms)9032026/09/22 08:15:09 OK 20251218171726_add_pins.sql (28.14ms)9042026/09/22 08:15:09 OK 20260628120000_add_object_size_and_stats.sql (47.78ms)9052026/09/22 08:15:09 OK 20260905000000_add_claims.sql (74.52ms)9062026/09/22 08:15:09 OK 20260920000000_drop_claims.sql (54.98ms)9072026/09/22 08:15:09 goose: successfully migrated database to version: 202609200000009082026/09/22 08:15:09 OK 1_commit_pending_closure.sql (11.47ms)9092026/09/22 08:15:09 OK 2_object_stats_trigger.sql (991.5µs)9102026/09/22 08:15:09 goose: up to current file version: 2911--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.67s)912=== CONT TestService_createPendingClosureHandler9132026-09-22 08:15:09.973 UTC [60392] ERROR: relation "goose_db_version" does not exist at character 369142026-09-22 08:15:09.973 UTC [60392] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC915--- PASS: TestReadProxyConditionalGet (1.75s)916=== CONT TestCacheConfigHandler917=== RUN TestCacheConfigHandler/full_config,_no_issuer918=== PAUSE TestCacheConfigHandler/full_config,_no_issuer919=== RUN TestCacheConfigHandler/no_cache_url_configured920=== PAUSE TestCacheConfigHandler/no_cache_url_configured921=== RUN TestCacheConfigHandler/no_signing_keys922=== PAUSE TestCacheConfigHandler/no_signing_keys923=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator924=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator925=== CONT TestClientWithDependencies9262026-09-22 08:15:10.195 UTC [60396] ERROR: relation "goose_db_version" does not exist at character 369272026-09-22 08:15:10.195 UTC [60396] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9282026/09/22 08:15:10 OK 20241026095416_initial_model.sql (173.19ms)9292026/09/22 08:15:10 OK 20251210153512_drop_unused_gin_index.sql (2.67ms)9302026-09-22 08:15:10.206 UTC [60399] ERROR: relation "goose_db_version" does not exist at character 369312026-09-22 08:15:10.206 UTC [60399] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9322026/09/22 08:15:10 OK 20251218171726_add_pins.sql (14.53ms)9332026/09/22 08:15:10 OK 20260628120000_add_object_size_and_stats.sql (23.56ms)9342026/09/22 08:15:10 OK 20260905000000_add_claims.sql (20.7ms)9352026/09/22 08:15:10 OK 20260920000000_drop_claims.sql (13.53ms)9362026/09/22 08:15:10 goose: successfully migrated database to version: 202609200000009372026/09/22 08:15:10 OK 1_commit_pending_closure.sql (2.44ms)9382026/09/22 08:15:10 OK 2_object_stats_trigger.sql (512.21µs)9392026/09/22 08:15:10 goose: up to current file version: 29402026/09/22 08:15:10 OK 20241026095416_initial_model.sql (81.8ms)9412026/09/22 08:15:10 OK 20251210153512_drop_unused_gin_index.sql (12.32ms)9422026-09-22 08:15:10.341 UTC [60400] ERROR: relation "goose_db_version" does not exist at character 369432026-09-22 08:15:10.341 UTC [60400] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9442026/09/22 08:15:10 OK 20251218171726_add_pins.sql (23.1ms)9452026/09/22 08:15:10 OK 20241026095416_initial_model.sql (124.2ms)9462026/09/22 08:15:10 OK 20251210153512_drop_unused_gin_index.sql (15.09ms)9472026/09/22 08:15:10 OK 20260628120000_add_object_size_and_stats.sql (36.6ms)9482026/09/22 08:15:10 OK 20251218171726_add_pins.sql (81.12ms)9492026/09/22 08:15:10 OK 20260905000000_add_claims.sql (80.18ms)9502026/09/22 08:15:10 OK 20260920000000_drop_claims.sql (30.24ms)9512026/09/22 08:15:10 goose: successfully migrated database to version: 202609200000009522026/09/22 08:15:10 OK 20260628120000_add_object_size_and_stats.sql (45.21ms)9532026/09/22 08:15:10 OK 1_commit_pending_closure.sql (9.7ms)9542026/09/22 08:15:10 OK 2_object_stats_trigger.sql (1.06ms)9552026/09/22 08:15:10 goose: up to current file version: 2956--- PASS: TestReadProxyHead (1.99s)957=== CONT TestClientMultipleUploads9582026/09/22 08:15:10 OK 20260905000000_add_claims.sql (51.83ms)9592026/09/22 08:15:10 OK 20241026095416_initial_model.sql (146.5ms)9602026/09/22 08:15:10 OK 20251210153512_drop_unused_gin_index.sql (16.34ms)9612026/09/22 08:15:10 OK 20260920000000_drop_claims.sql (30.95ms)9622026/09/22 08:15:10 goose: successfully migrated database to version: 202609200000009632026/09/22 08:15:10 OK 1_commit_pending_closure.sql (2.23ms)9642026/09/22 08:15:10 OK 2_object_stats_trigger.sql (460.54µs)9652026/09/22 08:15:10 goose: up to current file version: 29662026/09/22 08:15:10 OK 20251218171726_add_pins.sql (26.91ms)9672026/09/22 08:15:10 OK 20260628120000_add_object_size_and_stats.sql (20.75ms)9682026-09-22 08:15:10.661 UTC [60403] ERROR: relation "goose_db_version" does not exist at character 369692026-09-22 08:15:10.661 UTC [60403] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9702026/09/22 08:15:10 OK 20260905000000_add_claims.sql (40.76ms)971--- PASS: TestReadProxyInvalidPath (1.95s)972=== CONT TestClientIntegration9732026/09/22 08:15:10 OK 20260920000000_drop_claims.sql (28.64ms)9742026/09/22 08:15:10 goose: successfully migrated database to version: 202609200000009752026-09-22 08:15:10.692 UTC [60404] ERROR: relation "goose_db_version" does not exist at character 369762026-09-22 08:15:10.692 UTC [60404] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9772026/09/22 08:15:10 OK 1_commit_pending_closure.sql (3.56ms)9782026/09/22 08:15:10 OK 2_object_stats_trigger.sql (416.5µs)9792026/09/22 08:15:10 goose: up to current file version: 29802026/09/22 08:15:10 OK 20241026095416_initial_model.sql (133.59ms)9812026/09/22 08:15:10 OK 20251210153512_drop_unused_gin_index.sql (12.67ms)9822026/09/22 08:15:10 OK 20251218171726_add_pins.sql (26.87ms)983--- PASS: TestReadProxy404 (2.08s)984=== CONT TestClientErrorHandling985=== RUN TestClientErrorHandling/InvalidStorePath986=== PAUSE TestClientErrorHandling/InvalidStorePath987=== RUN TestClientErrorHandling/InvalidAuthToken988=== PAUSE TestClientErrorHandling/InvalidAuthToken989=== RUN TestClientErrorHandling/ServerNotAvailable990=== PAUSE TestClientErrorHandling/ServerNotAvailable991=== CONT TestClientCADerivations9922026/09/22 08:15:10 OK 20241026095416_initial_model.sql (158.79ms)9932026/09/22 08:15:10 OK 20251210153512_drop_unused_gin_index.sql (15.14ms)9942026/09/22 08:15:10 OK 20260628120000_add_object_size_and_stats.sql (42.29ms)9952026/09/22 08:15:10 OK 20251218171726_add_pins.sql (37.86ms)9962026/09/22 08:15:10 OK 20260905000000_add_claims.sql (45.21ms)9972026-09-22 08:15:10.987 UTC [60409] ERROR: relation "goose_db_version" does not exist at character 369982026-09-22 08:15:10.987 UTC [60409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9992026/09/22 08:15:10 OK 20260628120000_add_object_size_and_stats.sql (33.72ms)10002026/09/22 08:15:11 OK 20260920000000_drop_claims.sql (29.97ms)10012026/09/22 08:15:11 goose: successfully migrated database to version: 2026092000000010022026/09/22 08:15:11 OK 1_commit_pending_closure.sql (3ms)10032026/09/22 08:15:11 OK 2_object_stats_trigger.sql (612µs)10042026/09/22 08:15:11 goose: up to current file version: 210052026/09/22 08:15:11 OK 20260905000000_add_claims.sql (56.38ms)10062026/09/22 08:15:11 OK 20260920000000_drop_claims.sql (31.22ms)10072026/09/22 08:15:11 goose: successfully migrated database to version: 2026092000000010082026/09/22 08:15:11 OK 1_commit_pending_closure.sql (3.86ms)10092026/09/22 08:15:11 OK 2_object_stats_trigger.sql (1.3ms)10102026/09/22 08:15:11 goose: up to current file version: 210112026/09/22 08:15:11 INFO Received cleanup request method=DELETE path=/api/pending_closures10122026/09/22 08:15:11 INFO Aborted multipart uploads count=010132026/09/22 08:15:11 INFO Received uploads request method=POST path=/api/pending_closures10142026/09/22 08:15:11 INFO Received cleanup request method=DELETE path=/api/pending_closures10152026/09/22 08:15:11 INFO Aborted multipart uploads count=110162026/09/22 08:15:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10172026-09-22 08:15:11.154 UTC [60400] ERROR: Closure does not exist: id=110182026-09-22 08:15:11.154 UTC [60400] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE10192026-09-22 08:15:11.154 UTC [60400] STATEMENT: -- name: CommitPendingClosure :exec1020 SELECT commit_pending_closure($1::bigint)1021 1022--- PASS: TestService_cleanupPendingClosuresHandler (2.23s)1023=== CONT TestCacheStatsHandler10242026/09/22 08:15:11 OK 20241026095416_initial_model.sql (140.61ms)10252026/09/22 08:15:11 OK 20251210153512_drop_unused_gin_index.sql (13.18ms)10262026/09/22 08:15:11 OK 20251218171726_add_pins.sql (25.72ms)10272026/09/22 08:15:11 OK 20260628120000_add_object_size_and_stats.sql (31.58ms)10282026/09/22 08:15:11 INFO Received uploads request method=POST path=/api/pending_closures10292026/09/22 08:15:11 OK 20260905000000_add_claims.sql (47.86ms)1030--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.14s)1031=== CONT TestIsValidCachePath1032=== RUN TestIsValidCachePath/narinfo1033=== PAUSE TestIsValidCachePath/narinfo1034=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1035=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1036=== RUN TestIsValidCachePath/nar_zst1037=== PAUSE TestIsValidCachePath/nar_zst1038=== RUN TestIsValidCachePath/nar_xz1039=== PAUSE TestIsValidCachePath/nar_xz1040=== RUN TestIsValidCachePath/nar_bz21041=== PAUSE TestIsValidCachePath/nar_bz21042=== RUN TestIsValidCachePath/nar_uncompressed1043=== PAUSE TestIsValidCachePath/nar_uncompressed1044=== RUN TestIsValidCachePath/ls1045=== PAUSE TestIsValidCachePath/ls1046=== RUN TestIsValidCachePath/log1047=== PAUSE TestIsValidCachePath/log1048=== RUN TestIsValidCachePath/realisation1049=== PAUSE TestIsValidCachePath/realisation1050=== RUN TestIsValidCachePath/nix-cache-info1051=== PAUSE TestIsValidCachePath/nix-cache-info1052=== RUN TestIsValidCachePath/index.html1053=== PAUSE TestIsValidCachePath/index.html1054=== RUN TestIsValidCachePath/traversal_parent1055=== PAUSE TestIsValidCachePath/traversal_parent1056=== RUN TestIsValidCachePath/traversal_in_middle1057=== PAUSE TestIsValidCachePath/traversal_in_middle1058=== RUN TestIsValidCachePath/invalid_char_e1059=== PAUSE TestIsValidCachePath/invalid_char_e1060=== RUN TestIsValidCachePath/invalid_char_u1061=== PAUSE TestIsValidCachePath/invalid_char_u1062=== RUN TestIsValidCachePath/random_path1063=== PAUSE TestIsValidCachePath/random_path1064=== RUN TestIsValidCachePath/empty1065=== PAUSE TestIsValidCachePath/empty1066=== RUN TestIsValidCachePath/leading_slash1067=== PAUSE TestIsValidCachePath/leading_slash1068=== RUN TestIsValidCachePath/wrong_extension1069=== PAUSE TestIsValidCachePath/wrong_extension1070=== RUN TestIsValidCachePath/short_hash1071=== PAUSE TestIsValidCachePath/short_hash1072=== CONT TestReadProxyNarinfoAlreadyDecompressed10732026/09/22 08:15:11 OK 20260920000000_drop_claims.sql (21.39ms)10742026/09/22 08:15:11 goose: successfully migrated database to version: 2026092000000010752026/09/22 08:15:11 OK 1_commit_pending_closure.sql (4.13ms)10762026/09/22 08:15:11 OK 2_object_stats_trigger.sql (717.83µs)10772026/09/22 08:15:11 goose: up to current file version: 210782026/09/22 08:15:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10792026/09/22 08:15:11 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1080--- PASS: TestCompleteMultipartUnregistered (2.31s)1081=== CONT TestReadProxyNarinfo10822026-09-22 08:15:11.690 UTC [60416] ERROR: relation "goose_db_version" does not exist at character 3610832026-09-22 08:15:11.690 UTC [60416] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10842026/09/22 08:15:11 INFO Received uploads request method=POST path=/api/pending_closures10852026-09-22 08:15:11.777 UTC [60417] ERROR: relation "goose_db_version" does not exist at character 3610862026-09-22 08:15:11.777 UTC [60417] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10872026/09/22 08:15:11 OK 20241026095416_initial_model.sql (133.41ms)10882026/09/22 08:15:11 OK 20251210153512_drop_unused_gin_index.sql (13.15ms)10892026/09/22 08:15:11 OK 20251218171726_add_pins.sql (17.79ms)10902026/09/22 08:15:11 OK 20260628120000_add_object_size_and_stats.sql (31.96ms)10912026/09/22 08:15:11 OK 20241026095416_initial_model.sql (123.03ms)10922026/09/22 08:15:11 OK 20251210153512_drop_unused_gin_index.sql (11.62ms)10932026/09/22 08:15:12 OK 20260905000000_add_claims.sql (59.94ms)10942026/09/22 08:15:12 OK 20251218171726_add_pins.sql (41.28ms)10952026/09/22 08:15:12 OK 20260920000000_drop_claims.sql (10.52ms)10962026/09/22 08:15:12 goose: successfully migrated database to version: 2026092000000010972026/09/22 08:15:12 OK 1_commit_pending_closure.sql (2.95ms)10982026/09/22 08:15:12 OK 2_object_stats_trigger.sql (651.42µs)10992026/09/22 08:15:12 goose: up to current file version: 211002026/09/22 08:15:12 OK 20260628120000_add_object_size_and_stats.sql (28.16ms)11012026/09/22 08:15:12 OK 20260905000000_add_claims.sql (74.24ms)11022026-09-22 08:15:12.145 UTC [60418] ERROR: relation "goose_db_version" does not exist at character 3611032026-09-22 08:15:12.145 UTC [60418] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11042026/09/22 08:15:12 OK 20260920000000_drop_claims.sql (41.13ms)11052026/09/22 08:15:12 goose: successfully migrated database to version: 2026092000000011062026/09/22 08:15:12 OK 1_commit_pending_closure.sql (3.79ms)11072026/09/22 08:15:12 OK 2_object_stats_trigger.sql (866.79µs)11082026/09/22 08:15:12 goose: up to current file version: 211092026/09/22 08:15:12 INFO Received uploads request method=POST path=/api/pending_closures11102026/09/22 08:15:12 INFO Received uploads request method=POST path=/api/pending_closures11112026/09/22 08:15:12 INFO Received uploads request method=POST path=/api/pending_closures11122026/09/22 08:15:12 OK 20241026095416_initial_model.sql (288.13ms)11132026/09/22 08:15:12 OK 20251210153512_drop_unused_gin_index.sql (10.15ms)11142026/09/22 08:15:12 OK 20251218171726_add_pins.sql (46.84ms)11152026/09/22 08:15:12 OK 20260628120000_add_object_size_and_stats.sql (28.28ms)11162026/09/22 08:15:12 OK 20260905000000_add_claims.sql (59.87ms)11172026/09/22 08:15:12 OK 20260920000000_drop_claims.sql (48.31ms)11182026/09/22 08:15:12 goose: successfully migrated database to version: 2026092000000011192026/09/22 08:15:12 OK 1_commit_pending_closure.sql (1.26ms)11202026/09/22 08:15:12 OK 2_object_stats_trigger.sql (303.96µs)11212026/09/22 08:15:12 goose: up to current file version: 211222026-09-22 08:15:12.717 UTC [60421] ERROR: relation "goose_db_version" does not exist at character 3611232026-09-22 08:15:12.717 UTC [60421] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11242026-09-22 08:15:12.944 UTC [60423] ERROR: relation "goose_db_version" does not exist at character 3611252026-09-22 08:15:12.944 UTC [60423] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11262026/09/22 08:15:12 OK 20241026095416_initial_model.sql (154.86ms)11272026/09/22 08:15:12 OK 20251210153512_drop_unused_gin_index.sql (16.63ms)11282026/09/22 08:15:12 OK 20251218171726_add_pins.sql (27.83ms)11292026/09/22 08:15:13 OK 20260628120000_add_object_size_and_stats.sql (34.13ms)11302026/09/22 08:15:13 OK 20260905000000_add_claims.sql (63.13ms)1131=== NAME TestClientWithDependencies1132 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-60192-1958902681/TestClientWithDependencies4108467785/001/store/qx7q1w0jk0sf9hlpw6sba9mf7h87d1v4-test-script11332026/09/22 08:15:13 OK 20260920000000_drop_claims.sql (64.12ms)11342026/09/22 08:15:13 goose: successfully migrated database to version: 2026092000000011352026/09/22 08:15:13 OK 1_commit_pending_closure.sql (936.79µs)11362026/09/22 08:15:13 OK 2_object_stats_trigger.sql (369.67µs)11372026/09/22 08:15:13 goose: up to current file version: 211382026-09-22 08:15:13.179 UTC [60428] ERROR: relation "goose_db_version" does not exist at character 3611392026-09-22 08:15:13.179 UTC [60428] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11402026/09/22 08:15:13 OK 20241026095416_initial_model.sql (183.9ms)1141 client_integration_test.go:615: Found 1 dependencies (including self)11422026/09/22 08:15:13 OK 20251210153512_drop_unused_gin_index.sql (15.82ms)11432026/09/22 08:15:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1144=== NAME TestClientMultipleUploads1145 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-60192-1958902681/TestClientMultipleUploads3541849675/001/store/59cwln8apc63cmjms947cl963pqlyizs-test-file-0.txt11462026/09/22 08:15:13 OK 20251218171726_add_pins.sql (49.1ms)11472026/09/22 08:15:13 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11482026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures11492026/09/22 08:15:13 OK 20260628120000_add_object_size_and_stats.sql (38.5ms)11502026/09/22 08:15:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZGJjYzFmMTAtYWJkNy00MWYxLWFiZTQtODliN2M4ZDFhZmUwLjE5ZjRjOWM5LWRhYWEtNGM4Yy04MWI0LWRiMDI1ODQ5NjA3Y3gxNzkwMDY0OTExNzQ4MDYxMDAw parts=1011512026/09/22 08:15:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11522026/09/22 08:15:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11532026/09/22 08:15:13 INFO Uploading qx7q1w0jk0sf9hlpw6sba9mf7h87d1v4-test-script (136B)11542026/09/22 08:15:13 INFO Completed upload id=111552026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures11562026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures11572026/09/22 08:15:13 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11582026/09/22 08:15:13 WARN Found objects in DB but missing from S3, will re-upload count=11159--- PASS: TestService_verifyS3Integrity (3.88s)1160=== CONT TestClientSharedPathCommittedMidPush11612026/09/22 08:15:13 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"1162=== NAME TestClientMultipleUploads1163 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-60192-1958902681/TestClientMultipleUploads3541849675/001/store/82hld3msqpb5w37h5qljimpcg6cjpwl7-test-file-1.txt11642026/09/22 08:15:13 WARN Failed to register uploaded object key=log/58xfk7w9f9jww21mgn83n8ym291qg7qg-test-script.drv error="server returned 404: 404 page not found\n"11652026/09/22 08:15:13 OK 20260905000000_add_claims.sql (80.03ms)11662026/09/22 08:15:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11672026/09/22 08:15:13 INFO Signed narinfos id=1 count=111682026/09/22 08:15:13 WARN Failed to register uploaded object key=qx7q1w0jk0sf9hlpw6sba9mf7h87d1v4.ls error="server returned 404: 404 page not found\n"11692026/09/22 08:15:13 INFO Uploading 1 narinfos11702026/09/22 08:15:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11712026/09/22 08:15:13 WARN Failed to register uploaded object key=qx7q1w0jk0sf9hlpw6sba9mf7h87d1v4.narinfo error="server returned 404: 404 page not found\n"11722026/09/22 08:15:13 OK 20260920000000_drop_claims.sql (40.43ms)11732026/09/22 08:15:13 goose: successfully migrated database to version: 2026092000000011742026/09/22 08:15:13 OK 1_commit_pending_closure.sql (819.63µs)11752026/09/22 08:15:13 OK 2_object_stats_trigger.sql (241.38µs)11762026/09/22 08:15:13 goose: up to current file version: 211772026/09/22 08:15:13 INFO Completed upload id=111782026/09/22 08:15:13 INFO Upload complete. (191ms)1179=== NAME TestClientWithDependencies1180 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-60192-1958902681/TestClientWithDependencies4108467785/001/store) requires matching store prefix11812026/09/22 08:15:13 OK 20241026095416_initial_model.sql (217.61ms)1182=== NAME TestClientMultipleUploads1183 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-60192-1958902681/TestClientMultipleUploads3541849675/001/store/i2hvv2i3701x02x4pp1rz2rh96dqdpah-test-file-2.txt11842026-09-22 08:15:13.488 UTC [60441] ERROR: relation "goose_db_version" does not exist at character 3611852026-09-22 08:15:13.488 UTC [60441] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11862026/09/22 08:15:13 OK 20251210153512_drop_unused_gin_index.sql (13.99ms)1187--- PASS: TestClientWithDependencies (3.33s)1188=== CONT TestGCTaskStore_StartNew1189--- PASS: TestGCTaskStore_StartNew (0.00s)1190=== CONT TestGCMetrics11912026/09/22 08:15:13 OK 20251218171726_add_pins.sql (24.92ms)11922026/09/22 08:15:13 OK 20260628120000_add_object_size_and_stats.sql (36.21ms)11932026-09-22 08:15:13.556 UTC [60445] ERROR: relation "goose_db_version" does not exist at character 3611942026-09-22 08:15:13.556 UTC [60445] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11952026/09/22 08:15:13 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11962026/09/22 08:15:13 OK 20260905000000_add_claims.sql (51.71ms)11972026/09/22 08:15:13 OK 20260920000000_drop_claims.sql (35.28ms)11982026/09/22 08:15:13 goose: successfully migrated database to version: 2026092000000011992026/09/22 08:15:13 OK 1_commit_pending_closure.sql (1.13ms)12002026/09/22 08:15:13 OK 2_object_stats_trigger.sql (249.25µs)12012026/09/22 08:15:13 goose: up to current file version: 212022026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures12032026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures12042026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures12052026/09/22 08:15:13 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12062026/09/22 08:15:13 INFO Uploading 82hld3msqpb5w37h5qljimpcg6cjpwl7-test-file-1.txt (160B)12072026/09/22 08:15:13 INFO Uploading i2hvv2i3701x02x4pp1rz2rh96dqdpah-test-file-2.txt (160B)12082026/09/22 08:15:13 INFO Uploading 59cwln8apc63cmjms947cl963pqlyizs-test-file-0.txt (160B)12092026/09/22 08:15:13 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"12102026/09/22 08:15:13 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12112026/09/22 08:15:13 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1212=== NAME TestClientIntegration1213 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-60192-1958902681/TestClientIntegration122922411/002/store/9pbmhjy0s0rfbgcpg3yv89qbh998i8vr-test-file.txt12142026/09/22 08:15:13 WARN Failed to register uploaded object key=59cwln8apc63cmjms947cl963pqlyizs.ls error="server returned 404: 404 page not found\n"12152026/09/22 08:15:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12162026/09/22 08:15:13 WARN Failed to register uploaded object key=82hld3msqpb5w37h5qljimpcg6cjpwl7.ls error="server returned 404: 404 page not found\n"12172026/09/22 08:15:13 WARN Failed to register uploaded object key=i2hvv2i3701x02x4pp1rz2rh96dqdpah.ls error="server returned 404: 404 page not found\n"12182026/09/22 08:15:13 INFO Signed narinfos id=2 count=112192026/09/22 08:15:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign12202026/09/22 08:15:13 INFO Signed narinfos id=3 count=112212026/09/22 08:15:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12222026/09/22 08:15:13 INFO Signed narinfos id=1 count=112232026/09/22 08:15:13 INFO Uploading 3 narinfos12242026/09/22 08:15:13 OK 20241026095416_initial_model.sql (205.66ms)12252026/09/22 08:15:13 OK 20251210153512_drop_unused_gin_index.sql (10.56ms)12262026/09/22 08:15:13 WARN Failed to register uploaded object key=i2hvv2i3701x02x4pp1rz2rh96dqdpah.narinfo error="server returned 404: 404 page not found\n"12272026/09/22 08:15:13 WARN Failed to register uploaded object key=59cwln8apc63cmjms947cl963pqlyizs.narinfo error="server returned 404: 404 page not found\n"12282026/09/22 08:15:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12292026/09/22 08:15:13 WARN Failed to register uploaded object key=82hld3msqpb5w37h5qljimpcg6cjpwl7.narinfo error="server returned 404: 404 page not found\n"12302026/09/22 08:15:13 OK 20251218171726_add_pins.sql (20.92ms)12312026/09/22 08:15:13 INFO Completed upload id=112322026/09/22 08:15:13 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12332026/09/22 08:15:13 INFO Completed upload id=212342026/09/22 08:15:13 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete12352026/09/22 08:15:13 INFO Completed upload id=312362026/09/22 08:15:13 INFO Upload complete. (285ms)1237=== NAME TestClientMultipleUploads1238 client_integration_test.go:369: Uploaded 3 paths in 318.629ms12392026/09/22 08:15:13 OK 20260628120000_add_object_size_and_stats.sql (50.46ms)12402026/09/22 08:15:13 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12412026/09/22 08:15:13 OK 20241026095416_initial_model.sql (245.98ms)12422026/09/22 08:15:13 OK 20251210153512_drop_unused_gin_index.sql (14.03ms)12432026/09/22 08:15:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12442026/09/22 08:15:13 OK 20251218171726_add_pins.sql (50.43ms)12452026/09/22 08:15:13 OK 20260905000000_add_claims.sql (107.93ms)1246--- PASS: TestClientMultipleUploads (3.42s)1247=== CONT TestGCTaskStore_PhaseUpdates1248--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1249=== CONT TestGCBugBareHashReferences12502026/09/22 08:15:13 OK 20260920000000_drop_claims.sql (20.97ms)12512026/09/22 08:15:13 goose: successfully migrated database to version: 2026092000000012522026/09/22 08:15:13 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZGJjYzFmMTAtYWJkNy00MWYxLWFiZTQtODliN2M4ZDFhZmUwLjBkNzI2NDJkLWY2NTUtNGNhZC04YmY4LWFiOTZjZjdmNjhhN3gxNzkwMDY0OTEyMzAwNTA4MDAw parts=1012532026/09/22 08:15:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12542026/09/22 08:15:13 OK 20260628120000_add_object_size_and_stats.sql (28.76ms)12552026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures12562026/09/22 08:15:13 OK 1_commit_pending_closure.sql (1.5ms)12572026/09/22 08:15:13 OK 2_object_stats_trigger.sql (249.96µs)12582026/09/22 08:15:13 goose: up to current file version: 212592026/09/22 08:15:13 INFO Completed upload id=112602026/09/22 08:15:13 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012612026/09/22 08:15:13 INFO Received uploads request method=POST path=/api/pending_closures1262--- PASS: TestCacheStatsHandler (2.82s)1263=== CONT TestGCTaskStore_CompletedAllowsNewTask1264--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1265=== CONT TestGCTaskStore_GetReturnsLatest1266--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1267=== CONT TestGCTaskStore_GetEmpty1268--- PASS: TestGCTaskStore_GetEmpty (0.00s)1269=== CONT TestGCTaskStore_ConflictDifferentParams1270--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1271=== CONT TestGCTaskStore_DeduplicateSameParams1272--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1273=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12742026/09/22 08:15:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures12752026/09/22 08:15:13 INFO Aborted multipart uploads count=012762026/09/22 08:15:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12772026/09/22 08:15:13 INFO Uploading 9pbmhjy0s0rfbgcpg3yv89qbh998i8vr-test-file.txt (152B)12782026/09/22 08:15:14 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=012792026/09/22 08:15:14 OK 20260905000000_add_claims.sql (48.04ms)12802026/09/22 08:15:14 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12812026/09/22 08:15:14 INFO Vacuumed table table=pending_closures12822026/09/22 08:15:14 OK 20260920000000_drop_claims.sql (15.88ms)12832026/09/22 08:15:14 goose: successfully migrated database to version: 2026092000000012842026/09/22 08:15:14 INFO Vacuumed table table=pending_objects12852026/09/22 08:15:14 OK 1_commit_pending_closure.sql (1.1ms)12862026/09/22 08:15:14 OK 2_object_stats_trigger.sql (236.54µs)12872026/09/22 08:15:14 goose: up to current file version: 212882026/09/22 08:15:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12892026/09/22 08:15:14 WARN Failed to register uploaded object key=9pbmhjy0s0rfbgcpg3yv89qbh998i8vr.ls error="server returned 404: 404 page not found\n"12902026/09/22 08:15:14 INFO Signed narinfos id=1 count=112912026/09/22 08:15:14 INFO Uploading 1 narinfos12922026/09/22 08:15:14 INFO Vacuumed table table=multipart_uploads12932026/09/22 08:15:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12942026/09/22 08:15:14 WARN Failed to register uploaded object key=9pbmhjy0s0rfbgcpg3yv89qbh998i8vr.narinfo error="server returned 404: 404 page not found\n"12952026/09/22 08:15:14 INFO Completed upload id=112962026/09/22 08:15:14 INFO Upload complete. (301ms)12972026/09/22 08:15:14 INFO Vacuumed table table=closures1298=== NAME TestOrphanedObjectsGCStressTest1299 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains13002026/09/22 08:15:14 INFO Vacuumed table table=objects13012026/09/22 08:15:14 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001302--- PASS: TestService_createPendingClosureHandler (4.16s)1303=== CONT TestParseSize1304--- PASS: TestParseSize (0.00s)1305=== CONT TestService_Rustfstest13062026/09/22 08:15:14 INFO All 1 paths already cached1307=== NAME TestClientIntegration1308 client_integration_test.go:312: Retrieved narinfo from S3:1309 StorePath: /nix/var/nix/builds/nix-60192-1958902681/TestClientIntegration122922411/002/store/9pbmhjy0s0rfbgcpg3yv89qbh998i8vr-test-file.txt1310 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1311 Compression: zstd1312 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11313 NarSize: 1521314 References: 1315 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11316 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1317 client_integration_test.go:313: Decompressed .ls content (64 bytes):1318 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1319 client_integration_test.go:316: Testing garbage collection...1320=== NAME TestOrphanedObjectsGCStressTest1321 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion13222026/09/22 08:15:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures13232026/09/22 08:15:14 INFO Garbage collection started13242026/09/22 08:15:14 INFO Aborted multipart uploads count=013252026/09/22 08:15:14 WARN Force mode enabled - objects will be deleted immediately without grace period1326--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.80s)1327=== CONT TestPresignedUploadRegisteredBeforeCommit1328=== NAME TestClientCADerivations1329 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-60192-1958902681/TestClientCADerivations3854634713/001/store/q9y6sbfkfrmp088v2ziqv9z13wjvj8rg-ca-test1330 client_ca_test.go:139: Found 1 dependencies (including self)1331--- PASS: TestReadProxyNarinfo (2.75s)1332=== CONT TestCompletedNarNotReofferedAcrossClosures13332026/09/22 08:15:14 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13342026/09/22 08:15:14 INFO Received uploads request method=POST path=/api/pending_closures13352026/09/22 08:15:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13362026/09/22 08:15:14 INFO Uploading q9y6sbfkfrmp088v2ziqv9z13wjvj8rg-ca-test (144B)13372026/09/22 08:15:14 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=013382026/09/22 08:15:14 WARN Failed to register uploaded object key=log/f31afd81wc9r09irrbf49q3j72x11j23-ca-test.drv error="server returned 404: 404 page not found\n"13392026/09/22 08:15:14 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13402026/09/22 08:15:14 INFO Vacuumed table table=pending_closures13412026/09/22 08:15:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13422026/09/22 08:15:14 WARN Failed to register uploaded object key=q9y6sbfkfrmp088v2ziqv9z13wjvj8rg.ls error="server returned 404: 404 page not found\n"13432026/09/22 08:15:14 INFO Signed narinfos id=1 count=113442026/09/22 08:15:14 INFO Uploading 1 narinfos13452026/09/22 08:15:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13462026/09/22 08:15:14 WARN Failed to register uploaded object key=q9y6sbfkfrmp088v2ziqv9z13wjvj8rg.narinfo error="server returned 404: 404 page not found\n"13472026/09/22 08:15:14 INFO Vacuumed table table=pending_objects13482026/09/22 08:15:14 INFO Vacuumed table table=multipart_uploads13492026/09/22 08:15:14 INFO Completed upload id=113502026/09/22 08:15:14 INFO Upload complete. (159ms)13512026/09/22 08:15:14 INFO Vacuumed table table=closures1352=== NAME TestClientCADerivations1353 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-60192-1958902681/TestClientCADerivations3854634713/001/store/q9y6sbfkfrmp088v2ziqv9z13wjvj8rg-ca-test1354 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1355 Compression: zstd1356 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1357 NarSize: 1441358 References: 1359 Deriver: /nix/var/nix/builds/nix-60192-1958902681/TestClientCADerivations3854634713/001/store/f31afd81wc9r09irrbf49q3j72x11j23-ca-test.drv1360 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1361 client_ca_test.go:185: Checking for realisation files in S3...1362 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1363 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13642026/09/22 08:15:14 INFO Vacuumed table table=objects1365 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket28?endpoint=http://localhost:52268®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-60192-1958902681/TestClientCADerivations3854634713/001/store'1366 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11367--- PASS: TestClientCADerivations (3.58s)1368=== CONT TestCreatePin_ReservedPins13692026-09-22 08:15:14.473 UTC [60493] ERROR: relation "goose_db_version" does not exist at character 3613702026-09-22 08:15:14.473 UTC [60493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13712026/09/22 08:15:14 OK 20241026095416_initial_model.sql (12.18ms)13722026/09/22 08:15:14 OK 20251210153512_drop_unused_gin_index.sql (449.96µs)13732026/09/22 08:15:14 OK 20251218171726_add_pins.sql (779.21µs)13742026/09/22 08:15:14 OK 20260628120000_add_object_size_and_stats.sql (1.52ms)13752026-09-22 08:15:14.501 UTC [60494] ERROR: relation "goose_db_version" does not exist at character 3613762026-09-22 08:15:14.501 UTC [60494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13772026/09/22 08:15:14 OK 20260905000000_add_claims.sql (10.43ms)13782026/09/22 08:15:14 OK 20260920000000_drop_claims.sql (1.08ms)13792026/09/22 08:15:14 goose: successfully migrated database to version: 2026092000000013802026/09/22 08:15:14 OK 1_commit_pending_closure.sql (1.21ms)13812026/09/22 08:15:14 OK 2_object_stats_trigger.sql (217.29µs)13822026/09/22 08:15:14 goose: up to current file version: 213832026/09/22 08:15:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52398/oidc13842026/09/22 08:15:14 OK 20241026095416_initial_model.sql (51.89ms)13852026/09/22 08:15:14 OK 20251210153512_drop_unused_gin_index.sql (6ms)13862026/09/22 08:15:14 OK 20251218171726_add_pins.sql (13.19ms)13872026/09/22 08:15:14 OK 20260628120000_add_object_size_and_stats.sql (23.34ms)13882026/09/22 08:15:14 OK 20260905000000_add_claims.sql (21.06ms)13892026/09/22 08:15:14 OK 20260920000000_drop_claims.sql (13.3ms)13902026/09/22 08:15:14 goose: successfully migrated database to version: 2026092000000013912026/09/22 08:15:14 OK 1_commit_pending_closure.sql (1.19ms)13922026/09/22 08:15:14 OK 2_object_stats_trigger.sql (221.79µs)13932026/09/22 08:15:14 goose: up to current file version: 213942026/09/22 08:15:14 INFO Aborted multipart uploads count=013952026/09/22 08:15:14 WARN Force mode enabled - objects will be deleted immediately without grace period13962026/09/22 08:15:14 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=013972026/09/22 08:15:14 INFO Vacuumed table table=pending_closures13982026/09/22 08:15:14 INFO Vacuumed table table=pending_objects13992026/09/22 08:15:14 INFO Vacuumed table table=multipart_uploads14002026/09/22 08:15:14 INFO Vacuumed table table=closures14012026/09/22 08:15:14 INFO Vacuumed table table=objects1402--- PASS: TestGCMetrics (1.32s)1403=== CONT TestParseSingleRange1404=== RUN TestParseSingleRange/none1405=== PAUSE TestParseSingleRange/none1406=== RUN TestParseSingleRange/unknown_unit1407=== PAUSE TestParseSingleRange/unknown_unit1408=== RUN TestParseSingleRange/multi-range_ignored1409=== PAUSE TestParseSingleRange/multi-range_ignored1410=== RUN TestParseSingleRange/malformed_no_dash1411=== PAUSE TestParseSingleRange/malformed_no_dash1412=== RUN TestParseSingleRange/malformed_both_empty1413=== PAUSE TestParseSingleRange/malformed_both_empty1414=== RUN TestParseSingleRange/malformed_end_before_start1415=== PAUSE TestParseSingleRange/malformed_end_before_start1416=== RUN TestParseSingleRange/closed1417=== PAUSE TestParseSingleRange/closed1418=== RUN TestParseSingleRange/open-ended1419=== PAUSE TestParseSingleRange/open-ended1420=== RUN TestParseSingleRange/end_clamped_to_size1421=== PAUSE TestParseSingleRange/end_clamped_to_size1422=== RUN TestParseSingleRange/suffix1423=== PAUSE TestParseSingleRange/suffix1424=== RUN TestParseSingleRange/suffix_exceeds_size1425=== PAUSE TestParseSingleRange/suffix_exceeds_size1426=== RUN TestParseSingleRange/single_byte1427=== PAUSE TestParseSingleRange/single_byte1428=== RUN TestParseSingleRange/start_past_EOF1429=== PAUSE TestParseSingleRange/start_past_EOF1430=== RUN TestParseSingleRange/start_far_past_EOF1431=== PAUSE TestParseSingleRange/start_far_past_EOF1432=== CONT TestResolveDBConnectionString1433=== RUN TestResolveDBConnectionString/flag_wins1434=== PAUSE TestResolveDBConnectionString/flag_wins1435=== RUN TestResolveDBConnectionString/file_when_flag_empty1436=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1437=== RUN TestResolveDBConnectionString/missing_file_is_an_error1438=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1439=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1440=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1441=== RUN TestResolveDBConnectionString/nothing_configured1442=== PAUSE TestResolveDBConnectionString/nothing_configured1443=== CONT TestLeadElectsOneAndHandsOver14442026-09-22 08:15:14.865 UTC [60506] ERROR: relation "goose_db_version" does not exist at character 3614452026-09-22 08:15:14.865 UTC [60506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14462026-09-22 08:15:14.880 UTC [60507] ERROR: relation "goose_db_version" does not exist at character 3614472026-09-22 08:15:14.880 UTC [60507] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14482026-09-22 08:15:14.881 UTC [60508] ERROR: relation "goose_db_version" does not exist at character 3614492026-09-22 08:15:14.881 UTC [60508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1450=== NAME TestOrphanedObjectsGCStressTest1451 orphaned_objects_gc_test.go:509: Stress test completed successfully:1452 orphaned_objects_gc_test.go:510: - Active objects preserved: 201453 orphaned_objects_gc_test.go:511: - Objects deleted: 2101454 orphaned_objects_gc_test.go:512: - Total GC'd: 2101455--- PASS: TestOrphanedObjectsGCStressTest (7.66s)1456=== CONT TestIsValidUploadKey1457=== RUN TestIsValidUploadKey/narinfo1458=== PAUSE TestIsValidUploadKey/narinfo1459=== RUN TestIsValidUploadKey/nar_zst1460=== PAUSE TestIsValidUploadKey/nar_zst1461=== RUN TestIsValidUploadKey/nar_xz1462=== PAUSE TestIsValidUploadKey/nar_xz1463=== RUN TestIsValidUploadKey/nar_plain1464=== PAUSE TestIsValidUploadKey/nar_plain1465=== RUN TestIsValidUploadKey/listing1466=== PAUSE TestIsValidUploadKey/listing1467=== RUN TestIsValidUploadKey/build_log1468=== PAUSE TestIsValidUploadKey/build_log1469=== RUN TestIsValidUploadKey/build_log_home-manager_file1470=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1471=== RUN TestIsValidUploadKey/build_log_plus_in_name1472=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1473=== RUN TestIsValidUploadKey/build_log_question_mark1474=== PAUSE TestIsValidUploadKey/build_log_question_mark1475=== RUN TestIsValidUploadKey/build_log_equals1476=== PAUSE TestIsValidUploadKey/build_log_equals1477=== RUN TestIsValidUploadKey/realisation1478=== PAUSE TestIsValidUploadKey/realisation1479=== RUN TestIsValidUploadKey/realisation_plus_in_output1480=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1481=== RUN TestIsValidUploadKey/nix-cache-info1482=== PAUSE TestIsValidUploadKey/nix-cache-info1483=== RUN TestIsValidUploadKey/index.html1484=== PAUSE TestIsValidUploadKey/index.html1485=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1486=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1487=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1488=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1489=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1490=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1491=== RUN TestIsValidUploadKey/traversal1492=== PAUSE TestIsValidUploadKey/traversal1493=== RUN TestIsValidUploadKey/traversal_nar1494=== PAUSE TestIsValidUploadKey/traversal_nar1495=== RUN TestIsValidUploadKey/absolute1496=== PAUSE TestIsValidUploadKey/absolute1497=== RUN TestIsValidUploadKey/empty_key1498=== PAUSE TestIsValidUploadKey/empty_key1499=== RUN TestIsValidUploadKey/unknown_type1500=== PAUSE TestIsValidUploadKey/unknown_type1501=== CONT TestUploadHandlersRejectOversizedBody1502=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1503=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1504=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1505=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1506=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1507=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1508=== CONT TestUploadHandlersRejectInvalidKeys1509=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1510=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1511=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1512=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1513=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1514=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1515=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1516=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1517=== CONT TestProxyWriteTimeout1518=== RUN TestProxyWriteTimeout/narinfo1519=== PAUSE TestProxyWriteTimeout/narinfo1520=== RUN TestProxyWriteTimeout/1_GiB_nar1521=== PAUSE TestProxyWriteTimeout/1_GiB_nar1522=== RUN TestProxyWriteTimeout/10_GiB_nar1523=== PAUSE TestProxyWriteTimeout/10_GiB_nar1524=== RUN TestProxyWriteTimeout/unknown_size1525=== PAUSE TestProxyWriteTimeout/unknown_size1526=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle15272026/09/22 08:15:14 OK 20241026095416_initial_model.sql (48.65ms)15282026-09-22 08:15:14.932 UTC [60513] ERROR: relation "goose_db_version" does not exist at character 3615292026-09-22 08:15:14.932 UTC [60513] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15302026/09/22 08:15:14 OK 20251210153512_drop_unused_gin_index.sql (940.17µs)15312026/09/22 08:15:14 OK 20241026095416_initial_model.sql (21.36ms)15322026/09/22 08:15:14 OK 20251210153512_drop_unused_gin_index.sql (391.5µs)15332026/09/22 08:15:14 OK 20251218171726_add_pins.sql (695.42µs)15342026/09/22 08:15:14 OK 20251218171726_add_pins.sql (3.85ms)15352026/09/22 08:15:14 OK 20241026095416_initial_model.sql (16.61ms)15362026/09/22 08:15:14 OK 20251210153512_drop_unused_gin_index.sql (327.08µs)15372026/09/22 08:15:14 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)15382026/09/22 08:15:14 OK 20251218171726_add_pins.sql (762.96µs)15392026/09/22 08:15:14 OK 20260628120000_add_object_size_and_stats.sql (2.83ms)15402026/09/22 08:15:14 OK 20260905000000_add_claims.sql (2.29ms)15412026/09/22 08:15:14 OK 20260905000000_add_claims.sql (2.62ms)15422026/09/22 08:15:14 OK 20260628120000_add_object_size_and_stats.sql (3.24ms)15432026/09/22 08:15:14 OK 20260920000000_drop_claims.sql (1.24ms)15442026/09/22 08:15:14 goose: successfully migrated database to version: 2026092000000015452026/09/22 08:15:14 OK 20260920000000_drop_claims.sql (986.75µs)15462026/09/22 08:15:14 goose: successfully migrated database to version: 2026092000000015472026/09/22 08:15:14 OK 1_commit_pending_closure.sql (1.01ms)15482026/09/22 08:15:14 OK 1_commit_pending_closure.sql (707µs)15492026/09/22 08:15:14 OK 2_object_stats_trigger.sql (248.33µs)15502026/09/22 08:15:14 goose: up to current file version: 215512026/09/22 08:15:14 OK 2_object_stats_trigger.sql (272.29µs)15522026/09/22 08:15:14 goose: up to current file version: 215532026/09/22 08:15:14 OK 20260905000000_add_claims.sql (12.48ms)15542026/09/22 08:15:14 OK 20260920000000_drop_claims.sql (9.29ms)15552026/09/22 08:15:14 goose: successfully migrated database to version: 2026092000000015562026/09/22 08:15:14 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15572026/09/22 08:15:14 OK 1_commit_pending_closure.sql (1.37ms)15582026/09/22 08:15:14 OK 2_object_stats_trigger.sql (259.38µs)15592026/09/22 08:15:14 goose: up to current file version: 215602026/09/22 08:15:14 OK 20241026095416_initial_model.sql (38.95ms)15612026/09/22 08:15:14 OK 20251210153512_drop_unused_gin_index.sql (774.54µs)15622026/09/22 08:15:14 OK 20251218171726_add_pins.sql (3.04ms)15632026/09/22 08:15:14 OK 20260628120000_add_object_size_and_stats.sql (14.1ms)15642026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures15652026/09/22 08:15:15 OK 20260905000000_add_claims.sql (16.85ms)15662026/09/22 08:15:15 OK 20260920000000_drop_claims.sql (13.66ms)15672026/09/22 08:15:15 goose: successfully migrated database to version: 2026092000000015682026/09/22 08:15:15 OK 1_commit_pending_closure.sql (875.92µs)15692026/09/22 08:15:15 OK 2_object_stats_trigger.sql (234.08µs)15702026/09/22 08:15:15 goose: up to current file version: 215712026-09-22 08:15:15.044 UTC [60518] ERROR: relation "goose_db_version" does not exist at character 3615722026-09-22 08:15:15.044 UTC [60518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15732026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures15742026/09/22 08:15:15 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15752026/09/22 08:15:15 OK 20241026095416_initial_model.sql (70.43ms)15762026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures15772026/09/22 08:15:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15782026/09/22 08:15:15 INFO Uploading w1yfxaw0i0x018m19hqjm36zv5ag02v3-shared-dep (136B)15792026/09/22 08:15:15 OK 20251210153512_drop_unused_gin_index.sql (7.53ms)15802026/09/22 08:15:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15812026/09/22 08:15:15 OK 20251218171726_add_pins.sql (13.42ms)15822026/09/22 08:15:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15832026/09/22 08:15:15 WARN Failed to register uploaded object key=w1yfxaw0i0x018m19hqjm36zv5ag02v3.ls error="server returned 404: 404 page not found\n"15842026/09/22 08:15:15 INFO Signed narinfos id=2 count=115852026/09/22 08:15:15 INFO Uploading 1 narinfos15862026/09/22 08:15:15 OK 20260628120000_add_object_size_and_stats.sql (31.55ms)15872026/09/22 08:15:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15882026/09/22 08:15:15 WARN Failed to register uploaded object key=w1yfxaw0i0x018m19hqjm36zv5ag02v3.narinfo error="server returned 404: 404 page not found\n"15892026/09/22 08:15:15 INFO Completed upload id=215902026/09/22 08:15:15 INFO Upload complete. (155ms)15912026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures15922026/09/22 08:15:15 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15932026/09/22 08:15:15 INFO Uploading la6biz87agj62xpqdag3yy06cxn57cr8-top (256B)15942026/09/22 08:15:15 INFO Uploading w1yfxaw0i0x018m19hqjm36zv5ag02v3-shared-dep (136B)15952026/09/22 08:15:15 WARN Failed to register uploaded object key=nar/111amyvnqadnz7my7pyh8bgj64jz8v4fb617yqx9by2bk9snprqp.nar.zst error="server returned 404: 404 page not found\n"15962026/09/22 08:15:15 OK 20260905000000_add_claims.sql (42.1ms)15972026/09/22 08:15:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15982026/09/22 08:15:15 WARN Failed to register uploaded object key=la6biz87agj62xpqdag3yy06cxn57cr8.ls error="server returned 404: 404 page not found\n"15992026/09/22 08:15:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16002026/09/22 08:15:15 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGJjYzFmMTAtYWJkNy00MWYxLWFiZTQtODliN2M4ZDFhZmUwLmY3YmZlZjcyLWZiMDctNGQ4Yi1hNjI5LWY5YTQ3Y2FjNDNiYXgxNzkwMDY0OTE1MDgwNDkzMDAw16012026/09/22 08:15:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGJjYzFmMTAtYWJkNy00MWYxLWFiZTQtODliN2M4ZDFhZmUwLmY3YmZlZjcyLWZiMDctNGQ4Yi1hNjI5LWY5YTQ3Y2FjNDNiYXgxNzkwMDY0OTE1MDgwNDkzMDAw parts=11602--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.28s)1603=== CONT TestResurrectedObjectNotDeleted16042026/09/22 08:15:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign16052026/09/22 08:15:15 INFO Signed narinfos id=3 count=116062026/09/22 08:15:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16072026/09/22 08:15:15 WARN Failed to register uploaded object key=w1yfxaw0i0x018m19hqjm36zv5ag02v3.ls error="server returned 404: 404 page not found\n"16082026/09/22 08:15:15 INFO Signed narinfos id=1 count=116092026/09/22 08:15:15 INFO Uploading 2 narinfos16102026/09/22 08:15:15 OK 20260920000000_drop_claims.sql (37.72ms)16112026/09/22 08:15:15 goose: successfully migrated database to version: 2026092000000016122026/09/22 08:15:15 OK 1_commit_pending_closure.sql (1.11ms)16132026/09/22 08:15:15 OK 2_object_stats_trigger.sql (267.92µs)16142026/09/22 08:15:15 goose: up to current file version: 216152026/09/22 08:15:15 WARN Failed to register uploaded object key=la6biz87agj62xpqdag3yy06cxn57cr8.narinfo error="server returned 404: 404 page not found\n"16162026/09/22 08:15:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16172026/09/22 08:15:15 WARN Failed to register uploaded object key=w1yfxaw0i0x018m19hqjm36zv5ag02v3.narinfo error="server returned 404: 404 page not found\n"16182026/09/22 08:15:15 INFO Completed upload id=116192026/09/22 08:15:15 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete16202026/09/22 08:15:15 INFO Completed upload id=316212026/09/22 08:15:15 INFO Upload complete. (394ms)1622=== NAME TestClientSharedPathCommittedMidPush1623 client_integration_test.go:680: Retrieved narinfo from S3:1624 StorePath: /nix/var/nix/builds/nix-60192-1958902681/TestClientSharedPathCommittedMidPush2549453061/001/store/w1yfxaw0i0x018m19hqjm36zv5ag02v3-shared-dep1625 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1626 Compression: zstd1627 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821628 NarSize: 1361629 References: 1630 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1631 client_integration_test.go:680: Retrieved narinfo from S3:1632 StorePath: /nix/var/nix/builds/nix-60192-1958902681/TestClientSharedPathCommittedMidPush2549453061/001/store/la6biz87agj62xpqdag3yy06cxn57cr8-top1633 URL: nar/111amyvnqadnz7my7pyh8bgj64jz8v4fb617yqx9by2bk9snprqp.nar.zst1634 Compression: zstd1635 NarHash: sha256:111amyvnqadnz7my7pyh8bgj64jz8v4fb617yqx9by2bk9snprqp1636 NarSize: 2561637 References: /nix/var/nix/builds/nix-60192-1958902681/TestClientSharedPathCommittedMidPush2549453061/001/store/w1yfxaw0i0x018m19hqjm36zv5ag02v3-shared-dep1638 CA: text:sha256:18wy5clfg6vg9vvhj890yraa78n3v4z4qhcqnss5m4262nsibb5l1639--- PASS: TestClientSharedPathCommittedMidPush (2.07s)1640=== CONT TestReadProxyRangeRequest1641--- PASS: TestService_Rustfstest (1.36s)1642=== CONT TestRedundantMultipartUpload1643--- PASS: TestGCBugBareHashReferences (1.57s)1644=== CONT TestReadRedirectUsesPublicS3URL16452026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures16462026/09/22 08:15:15 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst16472026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures1648--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.58s)1649=== CONT TestReadRedirectKeepsNarinfoProxied16502026/09/22 08:15:15 INFO Received uploads request method=POST path=/api/pending_closures16512026-09-22 08:15:16.001 UTC [60534] ERROR: relation "goose_db_version" does not exist at character 3616522026-09-22 08:15:16.001 UTC [60534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16532026-09-22 08:15:16.006 UTC [60535] ERROR: relation "goose_db_version" does not exist at character 3616542026-09-22 08:15:16.006 UTC [60535] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16552026-09-22 08:15:16.052 UTC [60536] ERROR: relation "goose_db_version" does not exist at character 3616562026-09-22 08:15:16.052 UTC [60536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16572026/09/22 08:15:16 OK 20241026095416_initial_model.sql (27.7ms)16582026/09/22 08:15:16 OK 20241026095416_initial_model.sql (34.95ms)16592026/09/22 08:15:16 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)16602026/09/22 08:15:16 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)16612026/09/22 08:15:16 OK 20251218171726_add_pins.sql (3.12ms)16622026/09/22 08:15:16 OK 20251218171726_add_pins.sql (3.46ms)16632026/09/22 08:15:16 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)16642026/09/22 08:15:16 OK 20260628120000_add_object_size_and_stats.sql (5.97ms)16652026/09/22 08:15:16 OK 20241026095416_initial_model.sql (14.72ms)16662026/09/22 08:15:16 OK 20251210153512_drop_unused_gin_index.sql (624.33µs)16672026/09/22 08:15:16 OK 20251218171726_add_pins.sql (1.32ms)16682026/09/22 08:15:16 OK 20260905000000_add_claims.sql (27.61ms)16692026/09/22 08:15:16 OK 20260628120000_add_object_size_and_stats.sql (31.83ms)16702026/09/22 08:15:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=016712026/09/22 08:15:16 OK 20260905000000_add_claims.sql (35.57ms)1672=== NAME TestClientIntegration1673 client_integration_test.go:323: Objects in database after GC:1674 client_integration_test.go:323: Successfully deleted all objects with GC --force16752026/09/22 08:15:16 OK 20260920000000_drop_claims.sql (12.9ms)16762026/09/22 08:15:16 goose: successfully migrated database to version: 2026092000000016772026/09/22 08:15:16 OK 20260920000000_drop_claims.sql (19.72ms)16782026/09/22 08:15:16 goose: successfully migrated database to version: 2026092000000016792026/09/22 08:15:16 OK 1_commit_pending_closure.sql (1.98ms)16802026/09/22 08:15:16 OK 1_commit_pending_closure.sql (1.98ms)16812026/09/22 08:15:16 OK 2_object_stats_trigger.sql (385.54µs)16822026/09/22 08:15:16 goose: up to current file version: 216832026/09/22 08:15:16 OK 2_object_stats_trigger.sql (370.38µs)16842026/09/22 08:15:16 goose: up to current file version: 216852026/09/22 08:15:16 OK 20260905000000_add_claims.sql (32.78ms)1686--- PASS: TestClientIntegration (5.49s)1687=== CONT TestReadRedirectNar16882026/09/22 08:15:16 OK 20260920000000_drop_claims.sql (13.39ms)16892026/09/22 08:15:16 goose: successfully migrated database to version: 2026092000000016902026/09/22 08:15:16 OK 1_commit_pending_closure.sql (3.28ms)16912026/09/22 08:15:16 OK 2_object_stats_trigger.sql (598.5µs)16922026/09/22 08:15:16 goose: up to current file version: 216932026/09/22 08:15:16 INFO lead: acquired remote=192.0.2.1:123416942026/09/22 08:15:16 INFO lead: released remote=192.0.2.1:123416952026/09/22 08:15:16 INFO lead: acquired remote=192.0.2.1:123416962026/09/22 08:15:16 INFO lead: released remote=192.0.2.1:12341697--- PASS: TestLeadElectsOneAndHandsOver (1.67s)1698=== CONT TestService_AuthMiddleware_OIDC16992026/09/22 08:15:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17002026/09/22 08:15:16 WARN Refused reserved pin name=worker-x86_64-linux17012026/09/22 08:15:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17022026/09/22 08:15:16 INFO Received create pin request method=POST path=/api/pins/my-app17032026/09/22 08:15:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1704--- PASS: TestCreatePin_ReservedPins (2.02s)1705=== CONT TestService_ReadScope_PublicByDefault17062026/09/22 08:15:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52421/oidc17072026/09/22 08:15:16 INFO Received uploads request method=POST path=/api/pending_closures17082026/09/22 08:15:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17092026-09-22 08:15:17.214 UTC [60545] ERROR: relation "goose_db_version" does not exist at character 3617102026-09-22 08:15:17.214 UTC [60545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17112026-09-22 08:15:17.273 UTC [60546] ERROR: relation "goose_db_version" does not exist at character 3617122026-09-22 08:15:17.273 UTC [60546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17132026-09-22 08:15:17.289 UTC [60547] ERROR: relation "goose_db_version" does not exist at character 3617142026-09-22 08:15:17.289 UTC [60547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17152026-09-22 08:15:17.300 UTC [60548] ERROR: relation "goose_db_version" does not exist at character 3617162026-09-22 08:15:17.300 UTC [60548] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17172026/09/22 08:15:17 OK 20241026095416_initial_model.sql (90.1ms)17182026-09-22 08:15:17.409 UTC [60549] ERROR: relation "goose_db_version" does not exist at character 3617192026-09-22 08:15:17.409 UTC [60549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17202026/09/22 08:15:17 OK 20251210153512_drop_unused_gin_index.sql (54.38ms)17212026/09/22 08:15:17 OK 20251218171726_add_pins.sql (8.09ms)17222026/09/22 08:15:17 OK 20241026095416_initial_model.sql (116.1ms)17232026/09/22 08:15:17 OK 20241026095416_initial_model.sql (114.07ms)17242026/09/22 08:15:17 OK 20241026095416_initial_model.sql (118.47ms)17252026/09/22 08:15:17 OK 20251210153512_drop_unused_gin_index.sql (4.72ms)17262026/09/22 08:15:17 OK 20251210153512_drop_unused_gin_index.sql (5.21ms)17272026/09/22 08:15:17 OK 20260628120000_add_object_size_and_stats.sql (22.22ms)17282026/09/22 08:15:17 OK 20251210153512_drop_unused_gin_index.sql (10.89ms)17292026/09/22 08:15:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17302026/09/22 08:15:17 OK 20251218171726_add_pins.sql (17.02ms)17312026/09/22 08:15:17 OK 20251218171726_add_pins.sql (20.23ms)17322026/09/22 08:15:17 OK 20251218171726_add_pins.sql (16.32ms)17332026/09/22 08:15:17 OK 20260628120000_add_object_size_and_stats.sql (45.97ms)17342026/09/22 08:15:17 OK 20260628120000_add_object_size_and_stats.sql (54.95ms)17352026/09/22 08:15:17 OK 20260905000000_add_claims.sql (65.15ms)17362026/09/22 08:15:17 OK 20260628120000_add_object_size_and_stats.sql (56.35ms)17372026/09/22 08:15:17 OK 20260920000000_drop_claims.sql (36.17ms)17382026/09/22 08:15:17 goose: successfully migrated database to version: 2026092000000017392026/09/22 08:15:17 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZGJjYzFmMTAtYWJkNy00MWYxLWFiZTQtODliN2M4ZDFhZmUwLmMyYTAyNTk1LWZjODYtNDhlOC1iYzJiLTY4NGZhZTY1YTIyZXgxNzkwMDY0OTE1OTE0NDg4MDAw parts=1217402026/09/22 08:15:17 INFO Received uploads request method=POST path=/api/pending_closures17412026/09/22 08:15:17 OK 1_commit_pending_closure.sql (6.7ms)17422026/09/22 08:15:17 OK 2_object_stats_trigger.sql (1.07ms)17432026/09/22 08:15:17 goose: up to current file version: 21744--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.30s)1745=== CONT TestService_RequireScope_OIDC17462026/09/22 08:15:17 OK 20260905000000_add_claims.sql (66.58ms)17472026/09/22 08:15:17 OK 20260905000000_add_claims.sql (74.81ms)17482026/09/22 08:15:17 OK 20260905000000_add_claims.sql (88.75ms)17492026/09/22 08:15:17 OK 20260920000000_drop_claims.sql (31.12ms)17502026/09/22 08:15:17 goose: successfully migrated database to version: 2026092000000017512026/09/22 08:15:17 OK 20260920000000_drop_claims.sql (25.57ms)17522026/09/22 08:15:17 goose: successfully migrated database to version: 2026092000000017532026/09/22 08:15:17 OK 20260920000000_drop_claims.sql (31.29ms)17542026/09/22 08:15:17 goose: successfully migrated database to version: 2026092000000017552026/09/22 08:15:17 OK 20241026095416_initial_model.sql (179.98ms)17562026/09/22 08:15:17 OK 1_commit_pending_closure.sql (1.19ms)17572026/09/22 08:15:17 OK 1_commit_pending_closure.sql (1.32ms)17582026/09/22 08:15:17 OK 1_commit_pending_closure.sql (1.44ms)17592026/09/22 08:15:17 OK 2_object_stats_trigger.sql (299.96µs)17602026/09/22 08:15:17 goose: up to current file version: 217612026/09/22 08:15:17 OK 2_object_stats_trigger.sql (322.38µs)17622026/09/22 08:15:17 goose: up to current file version: 217632026/09/22 08:15:17 OK 2_object_stats_trigger.sql (317.5µs)17642026/09/22 08:15:17 goose: up to current file version: 217652026/09/22 08:15:17 OK 20251210153512_drop_unused_gin_index.sql (7.1ms)17662026/09/22 08:15:17 OK 20251218171726_add_pins.sql (15.76ms)17672026/09/22 08:15:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52426/oidc17682026/09/22 08:15:17 OK 20260628120000_add_object_size_and_stats.sql (20.64ms)17692026/09/22 08:15:17 OK 20260905000000_add_claims.sql (32.31ms)17702026/09/22 08:15:17 OK 20260920000000_drop_claims.sql (25.71ms)17712026/09/22 08:15:17 goose: successfully migrated database to version: 2026092000000017722026/09/22 08:15:17 OK 1_commit_pending_closure.sql (1.33ms)17732026/09/22 08:15:17 OK 2_object_stats_trigger.sql (225.46µs)17742026/09/22 08:15:17 goose: up to current file version: 21775--- PASS: TestResurrectedObjectNotDeleted (2.64s)1776=== CONT TestLeadEndsOnShutdown1777--- PASS: TestReadRedirectUsesPublicS3URL (2.51s)1778=== CONT TestPinProtectsFromGC1779{"timestamp":"2026-09-22T08:15:18.162058Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":3,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2296,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}17802026-09-22 08:15:18.174 UTC [60556] ERROR: relation "goose_db_version" does not exist at character 3617812026-09-22 08:15:18.174 UTC [60556] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1782--- PASS: TestReadProxyRangeRequest (2.87s)1783=== CONT TestService_AuthMiddleware_MTLSBoundSubjects17842026/09/22 08:15:18 OK 20241026095416_initial_model.sql (203.52ms)17852026/09/22 08:15:18 OK 20251210153512_drop_unused_gin_index.sql (7.97ms)17862026/09/22 08:15:18 INFO Received uploads request method=POST path=/api/pending_closures17872026/09/22 08:15:18 OK 20251218171726_add_pins.sql (32.28ms)17882026-09-22 08:15:18.500 UTC [60559] ERROR: relation "goose_db_version" does not exist at character 3617892026-09-22 08:15:18.500 UTC [60559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17902026/09/22 08:15:18 OK 20260628120000_add_object_size_and_stats.sql (58.64ms)17912026/09/22 08:15:18 INFO Received uploads request method=POST path=/api/pending_closures17922026/09/22 08:15:18 OK 20260905000000_add_claims.sql (66.66ms)17932026/09/22 08:15:18 OK 20260920000000_drop_claims.sql (34.88ms)17942026/09/22 08:15:18 goose: successfully migrated database to version: 2026092000000017952026/09/22 08:15:18 OK 1_commit_pending_closure.sql (5.25ms)17962026/09/22 08:15:18 OK 2_object_stats_trigger.sql (975.92µs)17972026/09/22 08:15:18 goose: up to current file version: 21798--- PASS: TestReadRedirectKeepsNarinfoProxied (3.07s)1799=== CONT TestService_AuthMiddleware_MTLSProxyHeader18002026-09-22 08:15:18.790 UTC [60560] ERROR: relation "goose_db_version" does not exist at character 3618012026-09-22 08:15:18.790 UTC [60560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18022026/09/22 08:15:18 OK 20241026095416_initial_model.sql (192.56ms)18032026/09/22 08:15:18 OK 20251210153512_drop_unused_gin_index.sql (10.75ms)18042026/09/22 08:15:18 OK 20251218171726_add_pins.sql (43.44ms)18052026/09/22 08:15:18 OK 20260628120000_add_object_size_and_stats.sql (30.9ms)18062026/09/22 08:15:19 OK 20260905000000_add_claims.sql (119.6ms)18072026/09/22 08:15:19 OK 20260920000000_drop_claims.sql (42.88ms)18082026/09/22 08:15:19 goose: successfully migrated database to version: 2026092000000018092026/09/22 08:15:19 OK 1_commit_pending_closure.sql (6.55ms)1810--- PASS: TestReadRedirectNar (2.88s)1811=== CONT TestService_ReadAuthMiddleware18122026/09/22 08:15:19 OK 2_object_stats_trigger.sql (2.75ms)18132026/09/22 08:15:19 goose: up to current file version: 218142026/09/22 08:15:19 OK 20241026095416_initial_model.sql (202.34ms)18152026/09/22 08:15:19 OK 20251210153512_drop_unused_gin_index.sql (12.78ms)18162026/09/22 08:15:19 OK 20251218171726_add_pins.sql (30.48ms)18172026/09/22 08:15:19 OK 20260628120000_add_object_size_and_stats.sql (44.5ms)18182026/09/22 08:15:19 OK 20260905000000_add_claims.sql (61.87ms)18192026/09/22 08:15:19 OK 20260920000000_drop_claims.sql (24.74ms)18202026/09/22 08:15:19 goose: successfully migrated database to version: 2026092000000018212026/09/22 08:15:19 OK 1_commit_pending_closure.sql (3.53ms)18222026/09/22 08:15:19 OK 2_object_stats_trigger.sql (917.92µs)18232026/09/22 08:15:19 goose: up to current file version: 21824--- PASS: TestService_ReadScope_PublicByDefault (2.77s)1825=== CONT TestServerTLSConfig/no_client_CA1826=== CONT TestServerTLSConfig/missing_CA_file1827=== CONT TestServerTLSConfig/not_a_PEM_file1828--- PASS: TestServerTLSConfig (0.00s)1829 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1830 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1831 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)1832=== CONT TestCacheConfigHandler/full_config,_no_issuer1833=== CONT TestCacheConfigHandler/no_signing_keys1834=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1835=== CONT TestCacheConfigHandler/no_cache_url_configured1836--- PASS: TestCacheConfigHandler (0.00s)1837 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1838 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1839 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1840 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1841=== CONT TestClientErrorHandling/InvalidStorePath1842=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1843=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1844=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1845=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1846=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1847=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1848=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1849=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1850=== CONT TestClientErrorHandling/ServerNotAvailable18512026/09/22 08:15:19 WARN Rate limiter enabled after throttle name=s3-test rate=518522026/09/22 08:15:19 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1853=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1854 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101855 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001856--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.78s)1857=== CONT TestClientErrorHandling/InvalidAuthToken18582026-09-22 08:15:19.710 UTC [60569] ERROR: relation "goose_db_version" does not exist at character 3618592026-09-22 08:15:19.710 UTC [60569] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18602026/09/22 08:15:19 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18612026-09-22 08:15:19.835 UTC [60574] ERROR: relation "goose_db_version" does not exist at character 3618622026-09-22 08:15:19.835 UTC [60574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18632026/09/22 08:15:19 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.988574ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18642026/09/22 08:15:19 OK 20241026095416_initial_model.sql (133.14ms)18652026/09/22 08:15:19 OK 20251210153512_drop_unused_gin_index.sql (5.97ms)18662026/09/22 08:15:19 OK 20251218171726_add_pins.sql (15.4ms)18672026/09/22 08:15:19 OK 20260628120000_add_object_size_and_stats.sql (26.81ms)18682026/09/22 08:15:19 OK 20260905000000_add_claims.sql (72.49ms)18692026/09/22 08:15:20 OK 20241026095416_initial_model.sql (117.42ms)18702026/09/22 08:15:20 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)18712026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (11.91ms)18722026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000018732026-09-22 08:15:20.009 UTC [60575] ERROR: relation "goose_db_version" does not exist at character 3618742026-09-22 08:15:20.009 UTC [60575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18752026/09/22 08:15:20 OK 1_commit_pending_closure.sql (1.83ms)18762026/09/22 08:15:20 OK 2_object_stats_trigger.sql (356.33µs)18772026/09/22 08:15:20 goose: up to current file version: 218782026/09/22 08:15:20 OK 20251218171726_add_pins.sql (35.07ms)18792026/09/22 08:15:20 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.827779ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18802026/09/22 08:15:20 OK 20260628120000_add_object_size_and_stats.sql (33.62ms)18812026/09/22 08:15:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18822026/09/22 08:15:20 OK 20260905000000_add_claims.sql (66.89ms)18832026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (82.6ms)18842026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000018852026/09/22 08:15:20 OK 1_commit_pending_closure.sql (6.71ms)18862026/09/22 08:15:20 OK 2_object_stats_trigger.sql (885.88µs)18872026/09/22 08:15:20 goose: up to current file version: 218882026/09/22 08:15:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZGJjYzFmMTAtYWJkNy00MWYxLWFiZTQtODliN2M4ZDFhZmUwLjczZDQ1ZDI3LTBkOTAtNGVkNC1hMzA0LTRkNTkzNmMzM2FhZHgxNzkwMDY0OTE4NTIwODYwMDAw parts=121889--- PASS: TestRedundantMultipartUpload (4.82s)1890=== CONT TestIsValidCachePath/narinfo1891=== CONT TestIsValidCachePath/index.html1892=== CONT TestIsValidCachePath/short_hash1893=== CONT TestIsValidCachePath/wrong_extension1894=== CONT TestIsValidCachePath/leading_slash1895=== CONT TestIsValidCachePath/empty1896=== CONT TestIsValidCachePath/random_path1897=== CONT TestIsValidCachePath/invalid_char_u1898=== CONT TestIsValidCachePath/invalid_char_e1899=== CONT TestIsValidCachePath/traversal_in_middle1900=== CONT TestIsValidCachePath/traversal_parent1901=== CONT TestIsValidCachePath/nar_uncompressed1902=== CONT TestIsValidCachePath/nix-cache-info1903=== CONT TestIsValidCachePath/ls1904=== CONT TestIsValidCachePath/nar_xz1905=== CONT TestIsValidCachePath/nar_bz21906=== CONT TestIsValidCachePath/nar_zst1907=== CONT TestIsValidCachePath/realisation1908=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1909=== CONT TestIsValidCachePath/log1910--- PASS: TestIsValidCachePath (0.00s)1911 --- PASS: TestIsValidCachePath/narinfo (0.00s)1912 --- PASS: TestIsValidCachePath/index.html (0.00s)1913 --- PASS: TestIsValidCachePath/short_hash (0.00s)1914 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1915 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1916 --- PASS: TestIsValidCachePath/empty (0.00s)1917 --- PASS: TestIsValidCachePath/random_path (0.00s)1918 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1919 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1920 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1921 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1922 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1923 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1924 --- PASS: TestIsValidCachePath/ls (0.00s)1925 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1926 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1927 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1928 --- PASS: TestIsValidCachePath/realisation (0.00s)1929 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1930 --- PASS: TestIsValidCachePath/log (0.00s)1931=== CONT TestParseSingleRange/none1932=== CONT TestParseSingleRange/open-ended1933=== CONT TestParseSingleRange/start_far_past_EOF1934=== CONT TestParseSingleRange/start_past_EOF1935=== CONT TestParseSingleRange/single_byte1936=== CONT TestParseSingleRange/suffix_exceeds_size1937=== CONT TestParseSingleRange/malformed_both_empty1938=== CONT TestParseSingleRange/closed1939=== CONT TestParseSingleRange/malformed_end_before_start1940=== CONT TestParseSingleRange/multi-range_ignored1941=== CONT TestParseSingleRange/malformed_no_dash1942=== CONT TestParseSingleRange/end_clamped_to_size1943=== CONT TestParseSingleRange/unknown_unit1944=== CONT TestParseSingleRange/suffix1945--- PASS: TestParseSingleRange (0.00s)1946 --- PASS: TestParseSingleRange/none (0.00s)1947 --- PASS: TestParseSingleRange/open-ended (0.00s)1948 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1949 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1950 --- PASS: TestParseSingleRange/single_byte (0.00s)1951 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1952 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1953 --- PASS: TestParseSingleRange/closed (0.00s)1954 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1955 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1956 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1957 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1958 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1959 --- PASS: TestParseSingleRange/suffix (0.00s)1960=== CONT TestResolveDBConnectionString/flag_wins1961=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1962=== CONT TestResolveDBConnectionString/nothing_configured1963=== CONT TestResolveDBConnectionString/missing_file_is_an_error1964=== CONT TestResolveDBConnectionString/file_when_flag_empty1965=== CONT TestIsValidUploadKey/narinfo1966=== CONT TestIsValidUploadKey/realisation_plus_in_output1967=== CONT TestIsValidUploadKey/unknown_type1968=== CONT TestIsValidUploadKey/empty_key1969=== CONT TestIsValidUploadKey/absolute1970=== CONT TestIsValidUploadKey/traversal_nar1971=== CONT TestIsValidUploadKey/traversal1972=== CONT TestIsValidUploadKey/build_log_home-manager_file1973=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1974=== CONT TestIsValidUploadKey/realisation1975=== CONT TestIsValidUploadKey/build_log_equals1976=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1977=== CONT TestIsValidUploadKey/build_log_question_mark1978=== CONT TestIsValidUploadKey/build_log_plus_in_name1979=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1980=== CONT TestIsValidUploadKey/nar_plain1981=== CONT TestIsValidUploadKey/listing1982=== CONT TestIsValidUploadKey/index.html1983=== CONT TestIsValidUploadKey/nar_xz1984=== CONT TestIsValidUploadKey/nar_zst1985=== CONT TestIsValidUploadKey/build_log1986=== CONT TestIsValidUploadKey/nix-cache-info1987--- PASS: TestIsValidUploadKey (0.00s)1988 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1989 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1990 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1991 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1992 --- PASS: TestIsValidUploadKey/absolute (0.00s)1993 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1994 --- PASS: TestIsValidUploadKey/traversal (0.00s)1995 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1996 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1997 --- PASS: TestIsValidUploadKey/realisation (0.00s)1998 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1999 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2000 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2001 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2002 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2003 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2004 --- PASS: TestIsValidUploadKey/listing (0.00s)2005 --- PASS: TestIsValidUploadKey/index.html (0.00s)2006 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2007 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2008 --- PASS: TestIsValidUploadKey/build_log (0.00s)2009 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2010=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20112026/09/22 08:15:20 INFO Received uploads request method=POST path=/2012--- PASS: TestResolveDBConnectionString (0.01s)2013 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2014 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2015 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2016 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2017 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)20182026/09/22 08:15:20 OK 20241026095416_initial_model.sql (222.68ms)2019=== RUN TestService_RequireScope_OIDC/builder_may_write2020=== PAUSE TestService_RequireScope_OIDC/builder_may_write2021=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2022=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2023=== RUN TestService_RequireScope_OIDC/ops_may_admin2024=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2025=== RUN TestService_RequireScope_OIDC/ops_may_not_write2026=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2027=== RUN TestService_RequireScope_OIDC/reader_may_not_write2028=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2029=== RUN TestService_RequireScope_OIDC/static_token_may_admin2030=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2031=== RUN TestService_RequireScope_OIDC/static_token_may_write2032=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2033=== RUN TestService_RequireScope_OIDC/reader_may_read2034=== PAUSE TestService_RequireScope_OIDC/reader_may_read2035=== RUN TestService_RequireScope_OIDC/writer_implies_read2036=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2037=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2038=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2039=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20402026/09/22 08:15:20 INFO Received request for more parts method=POST path=/20412026/09/22 08:15:20 OK 20251210153512_drop_unused_gin_index.sql (17.52ms)2042=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20432026/09/22 08:15:20 INFO Received complete multipart upload request method=POST path=/20442026/09/22 08:15:20 OK 20251218171726_add_pins.sql (32.84ms)2045=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20462026/09/22 08:15:20 INFO Received uploads request method=POST path=/2047=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20482026/09/22 08:15:20 INFO Received complete multipart upload request method=POST path=/2049=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20502026/09/22 08:15:20 INFO Received request for more parts method=POST path=/2051=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20522026/09/22 08:15:20 INFO Received uploads request method=POST path=/2053--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2054 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2055 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2056 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2057 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2058=== CONT TestProxyWriteTimeout/narinfo2059=== CONT TestProxyWriteTimeout/10_GiB_nar2060=== CONT TestProxyWriteTimeout/unknown_size2061=== CONT TestProxyWriteTimeout/1_GiB_nar2062--- PASS: TestProxyWriteTimeout (0.00s)2063 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2064 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2065 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2066 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2067=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2068=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20692026/09/22 08:15:20 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]2070=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2071=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20722026/09/22 08:15:20 WARN Authentication failed token_preview=eyJhbGciOi...6pzWROVifw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2073=== CONT TestService_RequireScope_OIDC/builder_may_write2074=== CONT TestService_RequireScope_OIDC/static_token_may_admin2075=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2076=== CONT TestService_RequireScope_OIDC/writer_implies_read2077=== CONT TestService_RequireScope_OIDC/reader_may_read2078=== CONT TestService_RequireScope_OIDC/static_token_may_write2079=== CONT TestService_RequireScope_OIDC/ops_may_not_write2080=== CONT TestService_RequireScope_OIDC/reader_may_not_write2081=== CONT TestService_RequireScope_OIDC/ops_may_admin2082=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2083--- PASS: TestService_AuthMiddleware_OIDC (3.03s)2084 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2085 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2086 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2087 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2088--- PASS: TestService_RequireScope_OIDC (2.74s)2089 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20992026-09-22 08:15:20.353 UTC [60576] ERROR: relation "goose_db_version" does not exist at character 3621002026-09-22 08:15:20.353 UTC [60576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21012026/09/22 08:15:20 OK 20260628120000_add_object_size_and_stats.sql (20.19ms)21022026/09/22 08:15:20 OK 20260905000000_add_claims.sql (25.16ms)21032026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (12.97ms)21042026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000021052026/09/22 08:15:20 OK 1_commit_pending_closure.sql (986.5µs)21062026/09/22 08:15:20 OK 2_object_stats_trigger.sql (216µs)21072026/09/22 08:15:20 goose: up to current file version: 221082026/09/22 08:15:20 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=816.251058ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21092026/09/22 08:15:20 OK 20241026095416_initial_model.sql (67.55ms)21102026/09/22 08:15:20 INFO lead: acquired remote=192.0.2.1:123421112026/09/22 08:15:20 INFO lead: released remote=192.0.2.1:12342112--- PASS: TestLeadEndsOnShutdown (2.56s)21132026/09/22 08:15:20 OK 20251210153512_drop_unused_gin_index.sql (938.46µs)21142026/09/22 08:15:20 OK 20251218171726_add_pins.sql (28.91ms)21152026/09/22 08:15:20 OK 20260628120000_add_object_size_and_stats.sql (47.08ms)21162026/09/22 08:15:20 OK 20260905000000_add_claims.sql (17.78ms)21172026-09-22 08:15:20.552 UTC [60577] ERROR: relation "goose_db_version" does not exist at character 3621182026-09-22 08:15:20.552 UTC [60577] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2119--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)2120 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)2121 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2122 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)21232026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (13.17ms)21242026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000021252026/09/22 08:15:20 OK 1_commit_pending_closure.sql (1.35ms)21262026/09/22 08:15:20 OK 2_object_stats_trigger.sql (237.38µs)21272026/09/22 08:15:20 goose: up to current file version: 221282026/09/22 08:15:20 OK 20241026095416_initial_model.sql (29.58ms)21292026/09/22 08:15:20 OK 20251210153512_drop_unused_gin_index.sql (7.63ms)21302026/09/22 08:15:20 OK 20251218171726_add_pins.sql (22.58ms)21312026-09-22 08:15:20.627 UTC [60578] ERROR: relation "goose_db_version" does not exist at character 3621322026-09-22 08:15:20.627 UTC [60578] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21332026/09/22 08:15:20 OK 20260628120000_add_object_size_and_stats.sql (23.87ms)21342026/09/22 08:15:20 OK 20260905000000_add_claims.sql (52.98ms)21352026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (22.8ms)21362026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000021372026/09/22 08:15:20 OK 1_commit_pending_closure.sql (1.01ms)21382026/09/22 08:15:20 OK 2_object_stats_trigger.sql (232.17µs)21392026/09/22 08:15:20 goose: up to current file version: 221402026-09-22 08:15:20.734 UTC [60580] ERROR: relation "goose_db_version" does not exist at character 3621412026-09-22 08:15:20.734 UTC [60580] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21422026/09/22 08:15:20 OK 20241026095416_initial_model.sql (56.85ms)21432026/09/22 08:15:20 OK 20251210153512_drop_unused_gin_index.sql (8.77ms)21442026/09/22 08:15:20 OK 20251218171726_add_pins.sql (22.18ms)21452026/09/22 08:15:20 OK 20260628120000_add_object_size_and_stats.sql (14.09ms)21462026/09/22 08:15:20 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21472026/09/22 08:15:20 WARN mTLS auth: bound subjects configured but subject DN unavailable21482026/09/22 08:15:20 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2149--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.58s)21502026/09/22 08:15:20 OK 20260905000000_add_claims.sql (52.5ms)21512026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (50.53ms)21522026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000021532026/09/22 08:15:20 OK 1_commit_pending_closure.sql (1.02ms)21542026/09/22 08:15:20 OK 2_object_stats_trigger.sql (255.88µs)21552026/09/22 08:15:20 goose: up to current file version: 221562026/09/22 08:15:20 OK 20241026095416_initial_model.sql (150.12ms)21572026/09/22 08:15:20 OK 20251210153512_drop_unused_gin_index.sql (6.45ms)21582026/09/22 08:15:20 OK 20251218171726_add_pins.sql (14.25ms)21592026/09/22 08:15:20 OK 20260628120000_add_object_size_and_stats.sql (21.11ms)2160=== NAME TestPinProtectsFromGC2161 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-60192-1958902681/TestPinProtectsFromGC324624405/001/store/h3iwavddyglwdcjzd7c12ydhnm5x3jc4-pinned-file.txt2162 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-60192-1958902681/TestPinProtectsFromGC324624405/001/store/pg6n9zn3l0f66zh5d414rgxibn3nm2py-unpinned-file.txt21632026/09/22 08:15:20 OK 20260905000000_add_claims.sql (21.58ms)21642026/09/22 08:15:20 OK 20260920000000_drop_claims.sql (10.72ms)21652026/09/22 08:15:20 goose: successfully migrated database to version: 2026092000000021662026/09/22 08:15:20 OK 1_commit_pending_closure.sql (875.13µs)21672026/09/22 08:15:20 OK 2_object_stats_trigger.sql (197.38µs)21682026/09/22 08:15:20 goose: up to current file version: 221692026-09-22 08:15:21.000 UTC [60587] ERROR: relation "goose_db_version" does not exist at character 3621702026-09-22 08:15:21.000 UTC [60587] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2171--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.23s)21722026/09/22 08:15:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21732026/09/22 08:15:21 INFO Received uploads request method=POST path=/api/pending_closures21742026/09/22 08:15:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21752026/09/22 08:15:21 INFO Uploading h3iwavddyglwdcjzd7c12ydhnm5x3jc4-pinned-file.txt (128B)21762026/09/22 08:15:21 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21772026/09/22 08:15:21 OK 20241026095416_initial_model.sql (81.54ms)21782026/09/22 08:15:21 WARN Failed to register uploaded object key=h3iwavddyglwdcjzd7c12ydhnm5x3jc4.ls error="server returned 404: 404 page not found\n"21792026/09/22 08:15:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21802026/09/22 08:15:21 INFO Signed narinfos id=1 count=121812026/09/22 08:15:21 INFO Uploading 1 narinfos21822026/09/22 08:15:21 OK 20251210153512_drop_unused_gin_index.sql (16.83ms)21832026/09/22 08:15:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21842026/09/22 08:15:21 WARN Failed to register uploaded object key=h3iwavddyglwdcjzd7c12ydhnm5x3jc4.narinfo error="server returned 404: 404 page not found\n"21852026/09/22 08:15:21 INFO Completed upload id=121862026/09/22 08:15:21 INFO Upload complete. (141ms)21872026/09/22 08:15:21 OK 20251218171726_add_pins.sql (26.98ms)21882026/09/22 08:15:21 OK 20260628120000_add_object_size_and_stats.sql (28.66ms)21892026/09/22 08:15:21 OK 20260905000000_add_claims.sql (37.22ms)21902026/09/22 08:15:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"2191--- PASS: TestService_ReadAuthMiddleware (2.16s)21922026/09/22 08:15:21 OK 20260920000000_drop_claims.sql (16.1ms)21932026/09/22 08:15:21 goose: successfully migrated database to version: 2026092000000021942026/09/22 08:15:21 OK 1_commit_pending_closure.sql (796.33µs)21952026/09/22 08:15:21 OK 2_object_stats_trigger.sql (228.67µs)21962026/09/22 08:15:21 goose: up to current file version: 221972026/09/22 08:15:21 INFO Received uploads request method=POST path=/api/pending_closures21982026/09/22 08:15:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21992026/09/22 08:15:21 INFO Uploading pg6n9zn3l0f66zh5d414rgxibn3nm2py-unpinned-file.txt (128B)22002026/09/22 08:15:21 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.589622104s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22012026/09/22 08:15:21 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"22022026/09/22 08:15:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22032026/09/22 08:15:21 INFO Signed narinfos id=2 count=122042026/09/22 08:15:21 INFO Uploading 1 narinfos22052026/09/22 08:15:21 WARN Failed to register uploaded object key=pg6n9zn3l0f66zh5d414rgxibn3nm2py.ls error="server returned 404: 404 page not found\n"22062026/09/22 08:15:21 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22072026/09/22 08:15:21 WARN Failed to register uploaded object key=pg6n9zn3l0f66zh5d414rgxibn3nm2py.narinfo error="server returned 404: 404 page not found\n"22082026/09/22 08:15:21 INFO Completed upload id=222092026/09/22 08:15:21 INFO Upload complete. (143ms)22102026/09/22 08:15:21 INFO Received create pin request method=POST path=/api/pins/myapp22112026/09/22 08:15:21 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-60192-1958902681/TestPinProtectsFromGC324624405/001/store/h3iwavddyglwdcjzd7c12ydhnm5x3jc4-pinned-file.txt narinfo_key=h3iwavddyglwdcjzd7c12ydhnm5x3jc4.narinfo22122026/09/22 08:15:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures22132026/09/22 08:15:21 INFO Garbage collection started22142026/09/22 08:15:21 INFO Aborted multipart uploads count=022152026/09/22 08:15:21 WARN Force mode enabled - objects will be deleted immediately without grace period22162026/09/22 08:15:21 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=022172026/09/22 08:15:21 INFO Vacuumed table table=pending_closures22182026/09/22 08:15:21 INFO Vacuumed table table=pending_objects22192026/09/22 08:15:21 INFO Vacuumed table table=multipart_uploads22202026/09/22 08:15:21 INFO Vacuumed table table=closures22212026/09/22 08:15:21 INFO Vacuumed table table=objects22222026/09/22 08:15:21 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22232026/09/22 08:15:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22242026/09/22 08:15:21 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2225{"timestamp":"2026-09-22T08:15:22.631184Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":3,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2296,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}22262026/09/22 08:15:22 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22272026/09/22 08:15:23 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.150853ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22282026/09/22 08:15:23 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=410.61939ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/09/22 08:15:23 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02230=== NAME TestPinProtectsFromGC2231 client_integration_test.go:794: Pin successfully protected closure from garbage collection2232--- PASS: TestPinProtectsFromGC (5.34s)22332026/09/22 08:15:23 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=746.090991ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22342026/09/22 08:15:24 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.639467888s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22352026/09/22 08:15:26 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused"22362026/09/22 08:15:26 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2237{"timestamp":"2026-09-22T08:15:26.172656Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":3,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2296,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}22382026/09/22 08:15:26 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.49746ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22392026/09/22 08:15:26 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=374.020584ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22402026/09/22 08:15:26 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=722.392227ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22412026/09/22 08:15:27 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.606975005s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2242--- PASS: TestClientErrorHandling (0.00s)2243 --- PASS: TestClientErrorHandling/InvalidStorePath (2.11s)2244 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.08s)2245 --- PASS: TestClientErrorHandling/ServerNotAvailable (9.64s)2246PASS2247{"timestamp":"2026-09-22T08:15:29.154279Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52366","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2260,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}22482026-09-22 08:15:29.293 UTC [60277] LOG: received smart shutdown request22492026-09-22 08:15:29.294 UTC [60277] LOG: background worker "logical replication launcher" (PID 60287) exited with exit code 122502026-09-22 08:15:29.302 UTC [60282] LOG: shutting down22512026-09-22 08:15:29.302 UTC [60282] LOG: checkpoint starting: shutdown immediate22522026-09-22 08:15:30.410 UTC [60282] LOG: checkpoint complete: wrote 13096 buffers (79.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=0.767 s, sync=0.314 s, total=1.108 s; sync files=19072, longest=0.001 s, average=0.001 s; distance=264768 kB, estimate=264768 kB; lsn=0/11A1D078, redo lsn=0/11A1D07822532026-09-22 08:15:30.414 UTC [60277] LOG: database system is shut down2254Running OIDC tests...2255=== RUN TestAudienceForIssuer2256=== PAUSE TestAudienceForIssuer2257=== RUN TestGlobMatch2258=== PAUSE TestGlobMatch2259=== RUN TestValidateToken_ValidToken2260=== PAUSE TestValidateToken_ValidToken2261=== RUN TestValidateToken_WrongAudience2262=== PAUSE TestValidateToken_WrongAudience2263=== RUN TestValidateToken_Expired2264=== PAUSE TestValidateToken_Expired2265=== RUN TestValidateToken_BoundClaimsMismatch2266=== PAUSE TestValidateToken_BoundClaimsMismatch2267=== RUN TestValidateToken_BoundSubjectMismatch2268=== PAUSE TestValidateToken_BoundSubjectMismatch2269=== RUN TestValidateToken_MultipleProviders2270=== PAUSE TestValidateToken_MultipleProviders2271=== RUN TestValidateToken_NoMatchingProvider2272=== PAUSE TestValidateToken_NoMatchingProvider2273=== RUN TestValidateToken_KubernetesServiceAccount2274=== PAUSE TestValidateToken_KubernetesServiceAccount2275=== RUN TestNewValidator_KubernetesRequiresCA2276=== PAUSE TestNewValidator_KubernetesRequiresCA2277=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2278=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2279=== RUN TestPins_ReservedForMatchingRule2280=== PAUSE TestPins_ReservedForMatchingRule2281=== RUN TestPins_TopLevelShorthand2282=== PAUSE TestPins_TopLevelShorthand2283=== RUN TestPins_ConfigValidation2284=== PAUSE TestPins_ConfigValidation2285=== RUN TestScopes_LegacyProviderDefaultsToWrite2286=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2287=== RUN TestScopes_Rules2288=== PAUSE TestScopes_Rules2289=== RUN TestScopes_ConfigValidation2290=== PAUSE TestScopes_ConfigValidation2291=== CONT TestAudienceForIssuer2292=== CONT TestScopes_LegacyProviderDefaultsToWrite2293--- PASS: TestAudienceForIssuer (0.00s)2294=== CONT TestPins_ConfigValidation2295=== CONT TestPins_TopLevelShorthand2296=== CONT TestPins_ReservedForMatchingRule2297=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2298=== CONT TestNewValidator_KubernetesRequiresCA2299=== CONT TestValidateToken_KubernetesServiceAccount2300=== CONT TestValidateToken_NoMatchingProvider2301=== CONT TestValidateToken_MultipleProviders2302=== CONT TestValidateToken_BoundSubjectMismatch2303--- PASS: TestPins_ConfigValidation (0.00s)2304=== CONT TestValidateToken_BoundClaimsMismatch23052026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52507/oidc23062026/09/22 08:15:31 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323072026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52510/oidc2308--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)2309=== CONT TestValidateToken_Expired2310--- PASS: TestPins_ReservedForMatchingRule (0.04s)2311=== CONT TestValidateToken_WrongAudience2312--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.04s)2313=== CONT TestValidateToken_ValidToken23142026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52515/oidc2315--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)2316=== CONT TestGlobMatch2317=== RUN TestGlobMatch/foo_foo2318=== PAUSE TestGlobMatch/foo_foo2319=== RUN TestGlobMatch/foo_bar2320=== PAUSE TestGlobMatch/foo_bar2321=== RUN TestGlobMatch/*_2322=== PAUSE TestGlobMatch/*_2323=== RUN TestGlobMatch/*_anything2324=== PAUSE TestGlobMatch/*_anything2325=== RUN TestGlobMatch/foo*_foo2326=== PAUSE TestGlobMatch/foo*_foo2327=== RUN TestGlobMatch/foo*_foobar2328=== PAUSE TestGlobMatch/foo*_foobar2329=== RUN TestGlobMatch/foo*_bar2330=== PAUSE TestGlobMatch/foo*_bar2331=== RUN TestGlobMatch/*bar_bar2332=== PAUSE TestGlobMatch/*bar_bar2333=== RUN TestGlobMatch/*bar_foobar2334=== PAUSE TestGlobMatch/*bar_foobar2335=== RUN TestGlobMatch/*bar_foo2336=== PAUSE TestGlobMatch/*bar_foo2337=== RUN TestGlobMatch/foo*bar_foobar2338=== PAUSE TestGlobMatch/foo*bar_foobar2339=== RUN TestGlobMatch/foo*bar_foo123bar2340=== PAUSE TestGlobMatch/foo*bar_foo123bar2341=== RUN TestGlobMatch/foo*bar_foobarbaz2342=== PAUSE TestGlobMatch/foo*bar_foobarbaz2343=== RUN TestGlobMatch/*/*_foo/bar2344=== PAUSE TestGlobMatch/*/*_foo/bar2345=== RUN TestGlobMatch/*/*_foo2346=== PAUSE TestGlobMatch/*/*_foo2347=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2348=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2349=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02350=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02351=== RUN TestGlobMatch/refs/*/main_refs/heads/main2352=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2353=== RUN TestGlobMatch/fo?_foo2354=== PAUSE TestGlobMatch/fo?_foo2355=== RUN TestGlobMatch/fo?_fo2356=== PAUSE TestGlobMatch/fo?_fo2357=== RUN TestGlobMatch/fo?_fooo2358=== PAUSE TestGlobMatch/fo?_fooo2359=== RUN TestGlobMatch/?oo_foo2360=== PAUSE TestGlobMatch/?oo_foo2361=== RUN TestGlobMatch/?oo_boo2362=== PAUSE TestGlobMatch/?oo_boo2363=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2364=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2365=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2366=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2367=== CONT TestScopes_ConfigValidation2368--- PASS: TestScopes_ConfigValidation (0.00s)2369=== CONT TestScopes_Rules23702026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52519/oidc23712026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52523/oidc23722026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52525/oidc23732026/09/22 08:15:31 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:525212374--- PASS: TestValidateToken_WrongAudience (0.03s)2375=== CONT TestGlobMatch/foo_foo2376=== CONT TestGlobMatch/*/*_foo/bar2377=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2378=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2379=== CONT TestGlobMatch/?oo_boo2380=== CONT TestGlobMatch/?oo_foo2381=== CONT TestGlobMatch/fo?_fooo2382=== CONT TestGlobMatch/fo?_fo2383=== CONT TestGlobMatch/fo?_foo2384=== CONT TestGlobMatch/refs/*/main_refs/heads/main2385=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02386=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2387=== CONT TestGlobMatch/*/*_foo2388=== CONT TestGlobMatch/foo*bar_foobarbaz2389=== CONT TestGlobMatch/foo*bar_foo123bar2390=== CONT TestGlobMatch/foo*bar_foobar2391=== CONT TestGlobMatch/*bar_foo2392=== CONT TestGlobMatch/*bar_foobar2393=== CONT TestGlobMatch/*bar_bar2394=== CONT TestGlobMatch/foo*_bar2395=== CONT TestGlobMatch/foo*_foobar2396=== CONT TestGlobMatch/foo*_foo2397=== CONT TestGlobMatch/*_anything2398=== CONT TestGlobMatch/*_2399=== CONT T2026/09/22 08:15:31 http: TLS handshake error from 127.0.0.1:52518: read tcp 127.0.0.1:52517->127.0.0.1:52518: use of closed network connection2400estGlobMatch/foo_bar2401--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)2402--- PASS: TestGlobMatch (0.00s)2403 --- PASS: TestGlobMatch/foo_foo (0.00s)2404 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2405 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2406 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2407 --- PASS: TestGlobMatch/?oo_boo (0.00s)2408 --- PASS: TestGlobMatch/?oo_foo (0.00s)2409 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2410 --- PASS: TestGlobMatch/fo?_fo (0.00s)2411 --- PASS: TestGlobMatch/fo?_foo (0.00s)2412 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2413 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2414 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2415 --- PASS: TestGlobMatch/*/*_foo (0.00s)2416 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2417 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2418 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2419 --- PASS: TestGlobMatch/*bar_foo (0.00s)2420 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2421 --- PASS: TestGlobMatch/*bar_bar (0.00s)2422 --- PASS: TestGlobMatch/foo*_bar (0.00s)2423 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2424 --- PASS: TestGlobMatch/foo*_foo (0.00s)2425 --- PASS: TestGlobMatch/*_anything (0.00s)2426 --- PASS: TestGlobMatch/*_ (0.00s)2427 --- PASS: TestGlobMatch/foo_bar (0.00s)2428--- PASS: TestPins_TopLevelShorthand (0.07s)2429--- PASS: TestScopes_Rules (0.02s)2430--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)24312026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52527/oidc2432--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)24332026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52529/oidc2434--- PASS: TestValidateToken_ValidToken (0.05s)24352026/09/22 08:15:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52514/oidc2436--- PASS: TestValidateToken_NoMatchingProvider (0.09s)24372026/09/22 08:15:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52512/oidc24382026/09/22 08:15:31 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52533/oidc2439--- PASS: TestValidateToken_MultipleProviders (0.10s)24402026/09/22 08:15:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52536/oidc2441--- PASS: TestValidateToken_Expired (0.08s)2442PASS2443Running hook tests...2444=== RUN TestSendPathsEmpty2445=== PAUSE TestSendPathsEmpty2446=== RUN TestQueueEnqueueAndFetch2447=== PAUSE TestQueueEnqueueAndFetch2448=== RUN TestQueueDeduplication2449=== PAUSE TestQueueDeduplication2450=== RUN TestQueueRemove2451=== PAUSE TestQueueRemove2452=== RUN TestQueueFetchBatchLimit2453=== PAUSE TestQueueFetchBatchLimit2454=== RUN TestQueueRetryMovesToBack2455=== PAUSE TestQueueRetryMovesToBack2456=== RUN TestQueueFetchRemoveLifecycle2457=== PAUSE TestQueueFetchRemoveLifecycle2458=== RUN TestQueueConcurrentWriters2459=== PAUSE TestQueueConcurrentWriters2460=== RUN TestQueueRemoveLargeClosure2461=== PAUSE TestQueueRemoveLargeClosure2462=== RUN TestServerClientIntegration2463=== PAUSE TestServerClientIntegration2464=== RUN TestServerQueueError2465=== PAUSE TestServerQueueError2466=== RUN TestGetListenerSocketActivation2467 server_test.go:210: === RUN TestGetListenerSocketActivation2468 --- PASS: TestGetListenerSocketActivation (0.00s)2469 PASS2470 2471--- PASS: TestGetListenerSocketActivation (0.00s)2472=== RUN TestDrainIsolatesPoisonPath2473=== PAUSE TestDrainIsolatesPoisonPath2474=== RUN TestRunNotBlockedByPoisonHead2475=== PAUSE TestRunNotBlockedByPoisonHead2476=== RUN TestDrainGivesUpWhenServerDown2477=== PAUSE TestDrainGivesUpWhenServerDown2478=== RUN TestFailedPathPrunedByLaterClosure2479=== PAUSE TestFailedPathPrunedByLaterClosure2480=== RUN TestWorkerUploadsAndRemoves2481=== PAUSE TestWorkerUploadsAndRemoves2482=== RUN TestWorkerSkipsGCdPaths2483=== PAUSE TestWorkerSkipsGCdPaths2484=== RUN TestWorkerPrunesClosureDeps2485=== PAUSE TestWorkerPrunesClosureDeps2486=== RUN TestDrainTimeout2487=== PAUSE TestDrainTimeout2488=== CONT TestSendPathsEmpty2489=== CONT TestServerQueueError2490=== CONT TestQueueRetryMovesToBack2491=== CONT TestQueueFetchBatchLimit2492=== CONT TestQueueRemove2493=== CONT TestWorkerUploadsAndRemoves2494=== CONT TestQueueDeduplication2495=== CONT TestServerClientIntegration2496=== CONT TestQueueRemoveLargeClosure24972026/09/22 08:15:31 ERROR Failed to queue paths error="permission denied" count=12498=== CONT TestQueueConcurrentWriters2499=== CONT TestQueueFetchRemoveLifecycle2500--- PASS: TestSendPathsEmpty (0.00s)2501--- PASS: TestServerQueueError (0.00s)2502=== CONT TestQueueEnqueueAndFetch2503--- PASS: TestServerClientIntegration (0.00s)2504=== CONT TestRunNotBlockedByPoisonHead2505--- PASS: TestQueueFetchBatchLimit (0.00s)2506=== CONT TestFailedPathPrunedByLaterClosure2507--- PASS: TestQueueEnqueueAndFetch (0.00s)2508=== CONT TestDrainGivesUpWhenServerDown2509--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2510=== CONT TestWorkerPrunesClosureDeps25112026/09/22 08:15:31 INFO Upload queue status pending=225122026/09/22 08:15:31 INFO Upload queue status pending=325132026/09/22 08:15:31 INFO Uploading batch count=125142026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=125152026/09/22 08:15:31 INFO Uploading batch count=22516--- PASS: TestQueueRetryMovesToBack (0.00s)2517=== CONT TestDrainTimeout2518--- PASS: TestQueueDeduplication (0.01s)2519=== CONT TestWorkerSkipsGCdPaths2520--- PASS: TestQueueRemove (0.01s)2521=== CONT TestDrainIsolatesPoisonPath25222026/09/22 08:15:31 INFO Uploading batch count=125232026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=125242026/09/22 08:15:31 INFO Uploading batch count=125252026/09/22 08:15:31 INFO Uploading batch count=125262026/09/22 08:15:31 INFO Upload queue status pending=225272026/09/22 08:15:31 INFO Uploading batch count=125282026/09/22 08:15:31 INFO Uploading batch count=225292026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=225302026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainGivesUpWhenServerDown2393991475/002/a25312026/09/22 08:15:31 INFO Upload queue status pending=225322026/09/22 08:15:31 INFO Uploading batch count=225332026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainGivesUpWhenServerDown2393991475/002/b25342026/09/22 08:15:31 INFO Uploading batch count=425352026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=42536--- PASS: TestFailedPathPrunedByLaterClosure (0.00s)25372026/09/22 08:15:31 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-60192-1958902681/TestWorkerSkipsGCdPaths3372549533/002/nonexistent25382026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainIsolatesPoisonPath3657320319/002/bbb25392026/09/22 08:15:31 INFO Uploading batch count=125402026/09/22 08:15:31 INFO Uploading batch count=225412026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=225422026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainGivesUpWhenServerDown2393991475/002/c25432026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainGivesUpWhenServerDown2393991475/002/d25442026/09/22 08:15:31 INFO Uploading batch count=225452026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=225462026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainGivesUpWhenServerDown2393991475/002/e25472026/09/22 08:15:31 INFO Uploading batch count=125482026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=125492026/09/22 08:15:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-60192-1958902681/TestDrainGivesUpWhenServerDown2393991475/002/f25502026/09/22 08:15:31 INFO Uploading batch count=125512026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=125522026/09/22 08:15:31 ERROR Drain finished with paths left in queue remaining=1025532026/09/22 08:15:31 INFO Uploading batch count=125542026/09/22 08:15:31 ERROR Upload failed error="upload failed" count=125552026/09/22 08:15:31 ERROR Drain finished with paths left in queue remaining=12556--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2557--- PASS: TestDrainIsolatesPoisonPath (0.00s)2558--- PASS: TestWorkerUploadsAndRemoves (0.03s)2559--- PASS: TestWorkerPrunesClosureDeps (0.02s)2560--- PASS: TestWorkerSkipsGCdPaths (0.02s)2561--- PASS: TestQueueRemoveLargeClosure (0.04s)2562--- PASS: TestQueueConcurrentWriters (0.15s)25632026/09/22 08:15:31 ERROR Upload failed error="context deadline exceeded" count=225642026/09/22 08:15:31 ERROR Drain finished with paths left in queue remaining=42565--- PASS: TestDrainTimeout (0.21s)25662026/09/22 08:15:32 INFO Uploading batch count=125672026/09/22 08:15:32 INFO Uploading batch count=125682026/09/22 08:15:32 INFO Uploading batch count=125692026/09/22 08:15:32 ERROR Upload failed error="upload failed" count=125702026/09/22 08:15:32 INFO Uploading batch count=125712026/09/22 08:15:32 ERROR Upload failed error="upload failed" count=125722026/09/22 08:15:32 INFO Uploading batch count=125732026/09/22 08:15:32 ERROR Upload failed error="upload failed" count=125742026/09/22 08:15:32 INFO Uploading batch count=125752026/09/22 08:15:32 ERROR Upload failed error="upload failed" count=125762026/09/22 08:15:32 ERROR Drain finished with paths left in queue remaining=12577--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2578PASS