niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #242
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.18s)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 TestPathInfoCACompatibility93=== RUN TestPathInfoCACompatibility/null_ca_field94=== PAUSE TestPathInfoCACompatibility/null_ca_field95=== RUN TestPathInfoCACompatibility/old_string_format_-_text96=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text97=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive98=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive99=== RUN TestPathInfoCACompatibility/new_structured_format_-_text100=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text101=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method102=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method103=== CONT TestEncodeNixBase32WithRealHash104--- PASS: TestEncodeNixBase32WithRealHash (0.00s)105=== CONT TestParsePathInfoJSONMultiplePaths106=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths107=== CONT TestParsePathInfoJSON108=== RUN TestParsePathInfoJSON/Nix_format109=== PAUSE TestParsePathInfoJSON/Nix_format110=== RUN TestParsePathInfoJSON/Lix_format111=== PAUSE TestParsePathInfoJSON/Lix_format112=== RUN TestParsePathInfoJSON/empty_input113=== PAUSE TestParsePathInfoJSON/empty_input114=== RUN TestParsePathInfoJSON/whitespace_only115=== PAUSE TestParsePathInfoJSON/whitespace_only116=== RUN TestParsePathInfoJSON/invalid_JSON117=== PAUSE TestParsePathInfoJSON/invalid_JSON118=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths119=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths120=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths121=== CONT TestUploadMultipart_SupersededByPeer122=== RUN TestUploadMultipart_SupersededByPeer/exists123=== PAUSE TestUploadMultipart_SupersededByPeer/exists124=== RUN TestUploadMultipart_SupersededByPeer/missing125=== PAUSE TestUploadMultipart_SupersededByPeer/missing126=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess127=== CONT TestDumpPathWriterError128=== CONT TestRateLimiterFeedback1292026/09/21 21:30:23 WARN Rate limiter enabled after throttle name=server-test rate=5130=== RUN TestRateLimiterFeedback/429_enables_limiter131=== CONT TestPathInfoHashCompatibility132=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)133=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)134=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon135=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon136=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI137=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI138=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512139=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512140=== CONT TestGetStorePathHash141=== RUN TestGetStorePathHash/valid_store_path142=== PAUSE TestGetStorePathHash/valid_store_path143=== RUN TestGetStorePathHash/basename_without_hyphen_should_error144=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error145=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error146=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error147=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error148=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error149=== CONT TestDumpPathSingleFile150=== CONT TestDumpPathMatchesNix151=== CONT TestResolveStorePath152=== CONT TestConvertHashToNix32153=== RUN TestConvertHashToNix32/SRI_format_to_Nix32154=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32155=== PAUSE TestRateLimiterFeedback/429_enables_limiter156=== CONT TestEncodeNixBase32157=== RUN TestEncodeNixBase32/test_string_hash158=== RUN TestConvertHashToNix32/already_Nix32_format159=== PAUSE TestEncodeNixBase32/test_string_hash160=== RUN TestEncodeNixBase32/empty_input161=== PAUSE TestEncodeNixBase32/empty_input162=== CONT TestFilterOversizedClosures163=== RUN TestFilterOversizedClosures/no_limit_keeps_everything164=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything165=== PAUSE TestConvertHashToNix32/already_Nix32_format166=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped167=== RUN TestRateLimiterFeedback/503_enables_limiter168=== RUN TestConvertHashToNix32/invalid_format169=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped170=== PAUSE TestConvertHashToNix32/invalid_format171=== RUN TestFilterOversizedClosures/all_closures_skipped172=== PAUSE TestRateLimiterFeedback/503_enables_limiter173=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter174=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter175=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter176=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter177=== PAUSE TestFilterOversizedClosures/all_closures_skipped178=== CONT TestPartSizeForNAR179=== CONT TestUploadMultipart_PartsInParallel180=== RUN TestPartSizeForNAR/zero_stays_at_minimum181=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum182=== RUN TestPartSizeForNAR/small_stays_at_minimum183=== PAUSE TestPartSizeForNAR/small_stays_at_minimum184=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum185=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum186=== CONT TestCaseHackSuffix187=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts188=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts189=== RUN TestPartSizeForNAR/1_TiB190=== PAUSE TestPartSizeForNAR/1_TiB191=== RUN TestPartSizeForNAR/5_TiB_S3_max_object192=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object193=== RUN TestPartSizeForNAR/capped_at_5_GiB1942026/09/21 21:30:23 WARN Rate limiter enabled after throttle name=server-test rate=51952026/09/21 21:30:23 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:51979196=== PAUSE TestPartSizeForNAR/capped_at_5_GiB197=== CONT TestRegisterUploadedObjectReusesConnections198--- PASS: TestResolveStorePath (0.00s)1992026/09/21 21:30:23 WARN Rate limiter backed off name=server-test rate=52002026/09/21 21:30:23 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:51979201--- PASS: TestDoServerRequestAttachesToken (0.01s)202=== CONT TestScriptTokenEmptyCommand203--- PASS: TestScriptTokenEmptyCommand (0.00s)204=== CONT TestScriptTokenScriptFails205=== CONT TestStaticToken206--- PASS: TestStaticToken (0.00s)207=== CONT TestScriptTokenBadJSON208--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)209=== CONT TestScriptTokenEmptyToken210--- PASS: TestScriptTokenScriptFails (0.01s)211=== CONT TestScriptTokenCachesUntilRefresh212--- PASS: TestScriptTokenEmptyToken (0.02s)213=== CONT TestScriptTokenNoExpiryRerunsEveryCall214--- PASS: TestScriptTokenBadJSON (0.03s)215=== CONT TestFileTokenReadsAndCaches216--- PASS: TestFileTokenReadsAndCaches (0.00s)217=== CONT TestStreamPushGivesUpOnDeadServer2182026/09/21 21:30:23 ERROR Upload failed error="connection refused" count=202192026/09/21 21:30:23 ERROR Server seems unavailable, giving up on batch untried=17220--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)221=== CONT TestSetClientTLSErrors222=== RUN TestSetClientTLSErrors/missing_cert_file223=== PAUSE TestSetClientTLSErrors/missing_cert_file224=== RUN TestSetClientTLSErrors/missing_key_file225=== PAUSE TestSetClientTLSErrors/missing_key_file226=== RUN TestSetClientTLSErrors/missing_ca_file227=== PAUSE TestSetClientTLSErrors/missing_ca_file228=== RUN TestSetClientTLSErrors/invalid_ca_file229=== PAUSE TestSetClientTLSErrors/invalid_ca_file230=== CONT TestSetClientTLSDoesNotMutateDefaultTransport231--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)232=== CONT TestSetClientTLS233=== RUN TestSetClientTLS/rejects_connection_without_client_cert234=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert235=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA236=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA237=== RUN TestSetClientTLS/preserves_debug_logging_transport238=== PAUSE TestSetClientTLS/preserves_debug_logging_transport239=== CONT TestStreamPushRequestLine2402026/09/21 21:30:23 ERROR Upload failed error=boom count=1241--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)242=== CONT TestStreamPushReportsEveryPath243--- PASS: TestStreamPushReportsEveryPath (0.00s)244=== CONT TestStreamPushIsolatesFailures2452026/09/21 21:30:23 ERROR Upload failed error="bad path" count=3246--- PASS: TestStreamPushIsolatesFailures (0.00s)247=== CONT TestStreamPushBatchesUnderLoad248--- PASS: TestDumpPathWriterError (0.05s)249=== CONT TestFileTokenEmpty250--- PASS: TestFileTokenEmpty (0.00s)251=== CONT TestShellSplitErrors252--- PASS: TestShellSplitErrors (0.00s)253=== CONT TestShellSplit254--- PASS: TestShellSplit (0.00s)255=== CONT TestFileTokenMissing256--- PASS: TestFileTokenMissing (0.00s)257=== CONT TestPathInfoCACompatibility/null_ca_field258=== CONT TestPathInfoCACompatibility/new_structured_format_-_text259=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive260=== CONT TestPathInfoCACompatibility/old_string_format_-_text261=== CONT TestParsePathInfoJSON/Nix_format262=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths263=== CONT TestUploadMultipart_SupersededByPeer/exists264=== CONT TestParsePathInfoJSON/invalid_JSON265=== CONT TestParsePathInfoJSON/whitespace_only266=== CONT TestParsePathInfoJSON/empty_input267=== CONT TestParsePathInfoJSON/Lix_format268--- PASS: TestParsePathInfoJSON (0.00s)269 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)270 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)271 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)272 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)273 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)274=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method275--- PASS: TestPathInfoCACompatibility (0.00s)276 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)277 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)278 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)279 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)280 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)281=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths282--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)283 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)284 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)285=== CONT TestUploadMultipart_SupersededByPeer/missing286--- PASS: TestStreamPushRequestLine (0.01s)287=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)288=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI289=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512290=== CONT TestGetStorePathHash/valid_store_path291=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error292=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error293=== CONT TestGetStorePathHash/basename_without_hyphen_should_error294--- PASS: TestGetStorePathHash (0.00s)295 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)296 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)297 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)298 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)299=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon300--- PASS: TestPathInfoHashCompatibility (0.00s)301 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)302 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)303 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)304 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)305=== CONT TestEncodeNixBase32/test_string_hash306=== CONT TestEncodeNixBase32/empty_input307--- PASS: TestEncodeNixBase32 (0.00s)308 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)309 --- PASS: TestEncodeNixBase32/empty_input (0.00s)310=== CONT TestConvertHashToNix32/SRI_format_to_Nix32311=== CONT TestConvertHashToNix32/invalid_format312=== CONT TestConvertHashToNix32/already_Nix32_format313--- PASS: TestConvertHashToNix32 (0.00s)314 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)315 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)316 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)317=== CONT TestFilterOversizedClosures/no_limit_keeps_everything318=== CONT TestRateLimiterFeedback/429_enables_limiter319--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)320 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)321 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)322=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3232026/09/21 21:30:23 WARN Rate limiter enabled after throttle name=server-test rate=53242026/09/21 21:30:23 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:52059325=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3262026/09/21 21:30:23 WARN Rate limiter backed off name=server-test rate=5327=== CONT TestRateLimiterFeedback/503_enables_limiter3282026/09/21 21:30:23 WARN Rate limiter enabled after throttle name=server-test rate=53292026/09/21 21:30:23 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:52065330=== CONT TestFilterOversizedClosures/all_closures_skipped3312026/09/21 21:30:23 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50332=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3332026/09/21 21:30:23 WARN Rate limiter backed off name=server-test rate=53342026/09/21 21:30:23 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000335=== CONT TestPartSizeForNAR/zero_stays_at_minimum336=== CONT TestPartSizeForNAR/capped_at_5_GiB337--- PASS: TestRateLimiterFeedback (0.00s)338 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)339 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)340 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)341 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)342--- PASS: TestFilterOversizedClosures (0.00s)343 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)344 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)345 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)346=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts347=== CONT TestPartSizeForNAR/small_stays_at_minimum348=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum349=== CONT TestPartSizeForNAR/5_TiB_S3_max_object350=== CONT TestSetClientTLSErrors/missing_cert_file351=== CONT TestPartSizeForNAR/1_TiB352=== CONT TestSetClientTLSErrors/invalid_ca_file353=== CONT TestSetClientTLSErrors/missing_ca_file354--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)355--- PASS: TestPartSizeForNAR (0.00s)356 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)357 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)358 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)359 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)360 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)361 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)362 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)363=== CONT TestSetClientTLSErrors/missing_key_file364=== CONT TestSetClientTLS/rejects_connection_without_client_cert365=== CONT TestSetClientTLS/preserves_debug_logging_transport366=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA367--- PASS: TestSetClientTLSErrors (0.00s)368 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)369 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)370 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)371 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)372--- PASS: TestDumpPathSingleFile (0.06s)373--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)374--- PASS: TestCaseHackSuffix (0.07s)3752026/09/21 21:30:23 http: TLS handshake error from 127.0.0.1:52067: remote error: tls: bad certificate376--- PASS: TestSetClientTLS (0.01s)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.00s)384PASS385Running server tests...386The files belonging to this database system will be owned by user "_nixbld1".387This user must also own the server process.388389The database cluster will be initialized with locale "C".390The default database encoding has accordingly been set to "SQL_ASCII".391The default text search configuration will be set to "english".392393Data page checksums are enabled.394395creating directory /nix/var/nix/builds/nix-38627-3659511840/postgres2259547496/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-38627-3659511840/postgres2259547496/data -l logfile start4124132026-09-21 21:30:25.188 UTC [38665] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4142026-09-21 21:30:25.188 UTC [38665] LOG: listening on Unix socket "/nix/var/nix/builds/nix-38627-3659511840/postgres2259547496/.s.PGSQL.5432"4152026-09-21 21:30:25.191 UTC [38672] LOG: database system was shut down at 2026-09-21 21:30:25 UTC4162026-09-21 21:30:25.191 UTC [38673] FATAL: the database system is starting up417/nix/var/nix/builds/nix-38627-3659511840/postgres2259547496:5432 - rejecting connections4182026-09-21 21:30:25.191 UTC [38665] LOG: database system is ready to accept connections419/nix/var/nix/builds/nix-38627-3659511840/postgres2259547496:5432 - accepting connections420{"timestamp":"2026-09-21T21:30:25.438599Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"1566794b-5ee3-4fd6-828c-109ff0a2ea9b","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":8,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}421{"timestamp":"2026-09-21T21:30:25.546469Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7ece63b9-8aac-46c9-bc29-11363f5d4d45","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}422{"timestamp":"2026-09-21T21:30:25.649943Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"68ccdd4d-0884-4c4a-aa9c-cecef03c3493","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}423=== RUN TestService_AuthMiddleware424=== PAUSE TestService_AuthMiddleware425=== RUN TestService_AuthMiddleware_MTLSProxyHeader426=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader427=== RUN TestService_AuthMiddleware_MTLSBoundSubjects428=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects429=== RUN TestService_ReadAuthMiddleware430=== PAUSE TestService_ReadAuthMiddleware431=== RUN TestService_AuthMiddleware_OIDC432=== PAUSE TestService_AuthMiddleware_OIDC433=== RUN TestService_RequireScope_OIDC434=== PAUSE TestService_RequireScope_OIDC435=== RUN TestService_ReadScope_PublicByDefault436=== PAUSE TestService_ReadScope_PublicByDefault437=== RUN TestCacheConfigHandler438=== PAUSE TestCacheConfigHandler439=== RUN TestCacheStatsHandler440=== PAUSE TestCacheStatsHandler441=== RUN TestClientCADerivations442=== PAUSE TestClientCADerivations443=== RUN TestClientErrorHandling444=== PAUSE TestClientErrorHandling445=== RUN TestClientIntegration446=== PAUSE TestClientIntegration447=== RUN TestClientMultipleUploads448=== PAUSE TestClientMultipleUploads449=== RUN TestClientWithDependencies450=== PAUSE TestClientWithDependencies451=== RUN TestClientSharedPathCommittedMidPush452=== PAUSE TestClientSharedPathCommittedMidPush453=== RUN TestPinProtectsFromGC454=== PAUSE TestPinProtectsFromGC455=== RUN TestResolveDBConnectionString456=== PAUSE TestResolveDBConnectionString457=== RUN TestLeadElectsOneAndHandsOver458=== PAUSE TestLeadElectsOneAndHandsOver459=== RUN TestLeadIncumbentWinsAfterRestart4602026-09-21 21:30:25.875 UTC [38745] ERROR: relation "goose_db_version" does not exist at character 364612026-09-21 21:30:25.875 UTC [38745] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4622026/09/21 21:30:25 OK 20241026095416_initial_model.sql (4.75ms)4632026/09/21 21:30:25 OK 20251210153512_drop_unused_gin_index.sql (643.58µs)4642026/09/21 21:30:25 OK 20251218171726_add_pins.sql (1.18ms)4652026/09/21 21:30:25 OK 20260628120000_add_object_size_and_stats.sql (1.06ms)4662026/09/21 21:30:25 OK 20260905000000_add_claims.sql (1.13ms)4672026/09/21 21:30:25 OK 20260920000000_drop_claims.sql (691.71µs)4682026/09/21 21:30:25 goose: successfully migrated database to version: 202609200000004692026/09/21 21:30:25 OK 1_commit_pending_closure.sql (1.97ms)4702026/09/21 21:30:25 OK 2_object_stats_trigger.sql (228.21µs)4712026/09/21 21:30:25 goose: up to current file version: 24722026/09/21 21:30:25 INFO lead: acquired remote=192.0.2.1:12344732026/09/21 21:30:26 INFO lead: released remote=192.0.2.1:12344742026/09/21 21:30:26 INFO lead: acquired remote=192.0.2.1:12344752026/09/21 21:30:26 INFO lead: released remote=192.0.2.1:1234476--- PASS: TestLeadIncumbentWinsAfterRestart (0.86s)477=== RUN TestLeadEndsOnShutdown478=== PAUSE TestLeadEndsOnShutdown479=== RUN TestGCAdvisoryLockBlocksConcurrentRun4802026-09-21 21:30:26.704 UTC [38749] ERROR: relation "goose_db_version" does not exist at character 364812026-09-21 21:30:26.704 UTC [38749] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4822026/09/21 21:30:26 OK 20241026095416_initial_model.sql (3.82ms)4832026/09/21 21:30:26 OK 20251210153512_drop_unused_gin_index.sql (394.17µs)4842026/09/21 21:30:26 OK 20251218171726_add_pins.sql (853.79µs)4852026/09/21 21:30:26 OK 20260628120000_add_object_size_and_stats.sql (872.46µs)4862026/09/21 21:30:26 OK 20260905000000_add_claims.sql (1.06ms)4872026/09/21 21:30:26 OK 20260920000000_drop_claims.sql (671.25µs)4882026/09/21 21:30:26 goose: successfully migrated database to version: 202609200000004892026/09/21 21:30:26 OK 1_commit_pending_closure.sql (856.04µs)4902026/09/21 21:30:26 OK 2_object_stats_trigger.sql (208.58µs)4912026/09/21 21:30:26 goose: up to current file version: 2492--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.17s)493=== RUN TestGCBugBareHashReferences494=== PAUSE TestGCBugBareHashReferences495=== RUN TestGCMetrics496=== PAUSE TestGCMetrics497=== RUN TestGCTaskStore_StartNew498=== PAUSE TestGCTaskStore_StartNew499=== RUN TestGCTaskStore_DeduplicateSameParams500=== PAUSE TestGCTaskStore_DeduplicateSameParams501=== RUN TestGCTaskStore_ConflictDifferentParams502=== PAUSE TestGCTaskStore_ConflictDifferentParams503=== RUN TestGCTaskStore_GetEmpty504=== PAUSE TestGCTaskStore_GetEmpty505=== RUN TestGCTaskStore_GetReturnsLatest506=== PAUSE TestGCTaskStore_GetReturnsLatest507=== RUN TestGCTaskStore_CompletedAllowsNewTask508=== PAUSE TestGCTaskStore_CompletedAllowsNewTask509=== RUN TestGCTaskStore_PhaseUpdates510=== PAUSE TestGCTaskStore_PhaseUpdates511=== RUN TestGCTaskStore_Fail512=== PAUSE TestGCTaskStore_Fail513=== RUN TestGracefulShutdownDrainsInflight514=== PAUSE TestGracefulShutdownDrainsInflight515=== RUN TestService_healthCheckHandler516=== PAUSE TestService_healthCheckHandler517=== RUN TestService_readinessHandler518=== PAUSE TestService_readinessHandler519=== RUN TestGenerateLandingPage520=== PAUSE TestGenerateLandingPage521=== RUN TestCacheConfigHandlerMaxNarSize522=== PAUSE TestCacheConfigHandlerMaxNarSize523=== RUN TestCreatePendingClosureRejectsOversizedNAR524=== PAUSE TestCreatePendingClosureRejectsOversizedNAR525=== RUN TestNARDeduplicationMetadataUploadBug526=== PAUSE TestNARDeduplicationMetadataUploadBug527=== RUN TestMetricsInventory528=== PAUSE TestMetricsInventory529=== RUN TestService_NativeMTLS530=== PAUSE TestService_NativeMTLS531=== RUN TestServerTLSConfig532=== PAUSE TestServerTLSConfig533=== RUN TestMultipartCleanup534=== PAUSE TestMultipartCleanup535=== RUN TestObjectStatsTrigger536=== PAUSE TestObjectStatsTrigger537=== RUN TestOrphanedObjectsGC538=== PAUSE TestOrphanedObjectsGC539=== RUN TestOrphanedObjectsGCStressTest540=== PAUSE TestOrphanedObjectsGCStressTest541=== RUN TestResurrectedObjectNotDeleted542=== PAUSE TestResurrectedObjectNotDeleted543=== RUN TestCreatePin_ReservedPins544=== PAUSE TestCreatePin_ReservedPins545=== RUN TestParseSingleRange546=== PAUSE TestParseSingleRange547=== RUN TestIsValidCachePath548=== PAUSE TestIsValidCachePath549=== RUN TestReadProxyNarinfo550=== PAUSE TestReadProxyNarinfo551=== RUN TestReadProxyNarinfoAlreadyDecompressed552=== PAUSE TestReadProxyNarinfoAlreadyDecompressed553=== RUN TestReadProxyNarStreaming554=== PAUSE TestReadProxyNarStreaming555=== RUN TestReadProxy404556=== PAUSE TestReadProxy404557=== RUN TestReadProxyInvalidPath558=== PAUSE TestReadProxyInvalidPath559=== RUN TestReadProxyHead560=== PAUSE TestReadProxyHead561=== RUN TestReadProxyConditionalGet562=== PAUSE TestReadProxyConditionalGet563=== RUN TestReadProxyRootRedirectsToIndexHTML564=== PAUSE TestReadProxyRootRedirectsToIndexHTML565=== RUN TestReadProxyDisabled566=== PAUSE TestReadProxyDisabled567=== RUN TestReadRedirectNar568=== PAUSE TestReadRedirectNar569=== RUN TestReadRedirectKeepsNarinfoProxied570=== PAUSE TestReadRedirectKeepsNarinfoProxied571=== RUN TestReadProxyRangeRequest572=== PAUSE TestReadProxyRangeRequest573=== RUN TestReadRedirectUsesPublicS3URL574=== PAUSE TestReadRedirectUsesPublicS3URL575=== RUN TestRedundantMultipartUpload576=== PAUSE TestRedundantMultipartUpload577=== RUN TestCompleteMultipartUpload_ErrorButObjectExists578=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists579=== RUN TestCompletedNarNotReofferedAcrossClosures580=== PAUSE TestCompletedNarNotReofferedAcrossClosures581=== RUN TestPresignedUploadRegisteredBeforeCommit582=== PAUSE TestPresignedUploadRegisteredBeforeCommit583=== RUN TestService_Rustfstest584=== PAUSE TestService_Rustfstest585=== RUN TestParseSize586=== PAUSE TestParseSize587=== RUN TestSkippedUploadsHandler588=== PAUSE TestSkippedUploadsHandler589=== RUN TestSystemdListenerNotActivated590--- PASS: TestSystemdListenerNotActivated (0.00s)591=== RUN TestWatchdogBeatsWhenHealthy592--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)593=== RUN TestWatchdogSkipsWhenUnhealthy5942026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5952026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5962026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5972026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5982026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5992026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6002026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6012026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6022026/09/21 21:30:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6032026/09/21 21:30:27 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"604--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)605=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle606=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle607=== RUN TestProxyWriteTimeout608=== PAUSE TestProxyWriteTimeout609=== RUN TestIsValidUploadKey610=== PAUSE TestIsValidUploadKey611=== RUN TestUploadHandlersRejectInvalidKeys612=== PAUSE TestUploadHandlersRejectInvalidKeys613=== RUN TestUploadHandlersRejectOversizedBody614=== PAUSE TestUploadHandlersRejectOversizedBody615=== RUN TestService_cleanupPendingClosuresHandler616=== PAUSE TestService_cleanupPendingClosuresHandler617=== RUN TestService_createPendingClosureHandler618=== PAUSE TestService_createPendingClosureHandler619=== RUN TestService_verifyS3Integrity620=== PAUSE TestService_verifyS3Integrity621=== RUN TestCompleteMultipartUnregistered622=== PAUSE TestCompleteMultipartUnregistered623=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT624=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT625=== CONT TestMultipartCleanup626=== CONT TestService_AuthMiddleware627=== CONT TestReadProxyRangeRequest628=== CONT TestGCMetrics629=== CONT TestProxyWriteTimeout630=== CONT TestService_healthCheckHandler631=== RUN TestProxyWriteTimeout/narinfo632=== CONT TestReadProxyNarinfo633=== PAUSE TestProxyWriteTimeout/narinfo634=== CONT TestIsValidCachePath635=== CONT TestParseSingleRange636=== CONT TestReadProxyNarinfoAlreadyDecompressed637=== RUN TestParseSingleRange/none638=== RUN TestProxyWriteTimeout/1_GiB_nar639=== PAUSE TestProxyWriteTimeout/1_GiB_nar640=== RUN TestProxyWriteTimeout/10_GiB_nar641=== PAUSE TestProxyWriteTimeout/10_GiB_nar642=== RUN TestProxyWriteTimeout/unknown_size643=== PAUSE TestProxyWriteTimeout/unknown_size644=== PAUSE TestParseSingleRange/none645=== CONT TestCreatePin_ReservedPins646=== RUN TestIsValidCachePath/narinfo647=== RUN TestParseSingleRange/unknown_unit648=== PAUSE TestParseSingleRange/unknown_unit649=== RUN TestParseSingleRange/multi-range_ignored650=== PAUSE TestIsValidCachePath/narinfo651=== PAUSE TestParseSingleRange/multi-range_ignored652=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars653=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars654=== RUN TestIsValidCachePath/nar_zst655=== RUN TestParseSingleRange/malformed_no_dash656=== PAUSE TestIsValidCachePath/nar_zst657=== PAUSE TestParseSingleRange/malformed_no_dash658=== RUN TestIsValidCachePath/nar_xz659=== RUN TestParseSingleRange/malformed_both_empty660=== PAUSE TestParseSingleRange/malformed_both_empty661=== RUN TestParseSingleRange/malformed_end_before_start662=== PAUSE TestIsValidCachePath/nar_xz663=== PAUSE TestParseSingleRange/malformed_end_before_start664=== RUN TestIsValidCachePath/nar_bz2665=== RUN TestParseSingleRange/closed666=== PAUSE TestIsValidCachePath/nar_bz2667=== PAUSE TestParseSingleRange/closed668=== RUN TestParseSingleRange/open-ended669=== PAUSE TestParseSingleRange/open-ended670=== RUN TestIsValidCachePath/nar_uncompressed671=== PAUSE TestIsValidCachePath/nar_uncompressed672=== RUN TestParseSingleRange/end_clamped_to_size673=== RUN TestIsValidCachePath/ls674=== PAUSE TestIsValidCachePath/ls675=== RUN TestIsValidCachePath/log676=== PAUSE TestParseSingleRange/end_clamped_to_size677=== PAUSE TestIsValidCachePath/log678=== RUN TestIsValidCachePath/realisation679=== PAUSE TestIsValidCachePath/realisation680=== RUN TestParseSingleRange/suffix681=== RUN TestIsValidCachePath/nix-cache-info682=== PAUSE TestIsValidCachePath/nix-cache-info683=== PAUSE TestParseSingleRange/suffix684=== RUN TestIsValidCachePath/index.html685=== PAUSE TestIsValidCachePath/index.html686=== RUN TestParseSingleRange/suffix_exceeds_size687=== RUN TestIsValidCachePath/traversal_parent688=== PAUSE TestParseSingleRange/suffix_exceeds_size689=== PAUSE TestIsValidCachePath/traversal_parent690=== RUN TestParseSingleRange/single_byte691=== PAUSE TestParseSingleRange/single_byte692=== RUN TestIsValidCachePath/traversal_in_middle693=== RUN TestParseSingleRange/start_past_EOF694=== PAUSE TestIsValidCachePath/traversal_in_middle695=== PAUSE TestParseSingleRange/start_past_EOF696=== RUN TestIsValidCachePath/invalid_char_e697=== PAUSE TestIsValidCachePath/invalid_char_e698=== RUN TestIsValidCachePath/invalid_char_u699=== RUN TestParseSingleRange/start_far_past_EOF700=== PAUSE TestIsValidCachePath/invalid_char_u701=== PAUSE TestParseSingleRange/start_far_past_EOF702=== CONT TestResurrectedObjectNotDeleted703=== RUN TestIsValidCachePath/random_path704=== PAUSE TestIsValidCachePath/random_path705=== RUN TestIsValidCachePath/empty706=== PAUSE TestIsValidCachePath/empty707=== RUN TestIsValidCachePath/leading_slash708=== PAUSE TestIsValidCachePath/leading_slash709=== RUN TestIsValidCachePath/wrong_extension710=== PAUSE TestIsValidCachePath/wrong_extension711=== RUN TestIsValidCachePath/short_hash712=== PAUSE TestIsValidCachePath/short_hash713=== CONT TestOrphanedObjectsGCStressTest7142026/09/21 21:30:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52085/oidc7152026-09-21 21:30:27.289 UTC [38771] ERROR: relation "goose_db_version" does not exist at character 367162026-09-21 21:30:27.289 UTC [38771] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7172026-09-21 21:30:27.290 UTC [38772] ERROR: relation "goose_db_version" does not exist at character 367182026-09-21 21:30:27.290 UTC [38772] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026-09-21 21:30:27.296 UTC [38773] ERROR: relation "goose_db_version" does not exist at character 367202026-09-21 21:30:27.296 UTC [38773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026-09-21 21:30:27.298 UTC [38775] ERROR: relation "goose_db_version" does not exist at character 367222026-09-21 21:30:27.298 UTC [38775] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7232026-09-21 21:30:27.300 UTC [38774] ERROR: relation "goose_db_version" does not exist at character 367242026-09-21 21:30:27.300 UTC [38774] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026-09-21 21:30:27.301 UTC [38776] ERROR: relation "goose_db_version" does not exist at character 367262026-09-21 21:30:27.301 UTC [38776] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7272026-09-21 21:30:27.301 UTC [38778] ERROR: relation "goose_db_version" does not exist at character 367282026-09-21 21:30:27.301 UTC [38778] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026-09-21 21:30:27.302 UTC [38779] ERROR: relation "goose_db_version" does not exist at character 367302026-09-21 21:30:27.302 UTC [38779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7312026-09-21 21:30:27.302 UTC [38777] ERROR: relation "goose_db_version" does not exist at character 367322026-09-21 21:30:27.302 UTC [38777] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7332026/09/21 21:30:27 OK 20241026095416_initial_model.sql (8.93ms)7342026/09/21 21:30:27 OK 20241026095416_initial_model.sql (10.83ms)7352026/09/21 21:30:27 OK 20241026095416_initial_model.sql (6.79ms)7362026/09/21 21:30:27 OK 20241026095416_initial_model.sql (6.83ms)7372026/09/21 21:30:27 OK 20241026095416_initial_model.sql (6.45ms)7382026/09/21 21:30:27 OK 20241026095416_initial_model.sql (14.05ms)7392026/09/21 21:30:27 OK 20241026095416_initial_model.sql (15.29ms)7402026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)7412026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (631.58µs)7422026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (1.12ms)7432026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)7442026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)7452026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)7462026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (950.5µs)7472026/09/21 21:30:27 OK 20251218171726_add_pins.sql (1.84ms)7482026/09/21 21:30:27 OK 20251218171726_add_pins.sql (1.86ms)7492026/09/21 21:30:27 OK 20251218171726_add_pins.sql (1.43ms)7502026/09/21 21:30:27 OK 20251218171726_add_pins.sql (2.06ms)7512026/09/21 21:30:27 OK 20251218171726_add_pins.sql (2.2ms)7522026-09-21 21:30:27.316 UTC [38780] ERROR: relation "goose_db_version" does not exist at character 367532026-09-21 21:30:27.316 UTC [38780] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7542026/09/21 21:30:27 OK 20251218171726_add_pins.sql (1.91ms)7552026/09/21 21:30:27 OK 20251218171726_add_pins.sql (2.18ms)7562026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)7572026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (1.57ms)7582026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (1.83ms)7592026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)7602026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)7612026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (2.14ms)7622026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (2.21ms)7632026/09/21 21:30:27 OK 20241026095416_initial_model.sql (6.55ms)7642026/09/21 21:30:27 OK 20260905000000_add_claims.sql (2.27ms)7652026/09/21 21:30:27 OK 20260905000000_add_claims.sql (2.96ms)7662026/09/21 21:30:27 OK 20260905000000_add_claims.sql (2.46ms)7672026/09/21 21:30:27 OK 20260905000000_add_claims.sql (2.11ms)7682026/09/21 21:30:27 OK 20241026095416_initial_model.sql (7.4ms)7692026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (836.25µs)7702026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (1.09ms)7712026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007722026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (1.27ms)7732026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007742026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (1.36ms)7752026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007762026/09/21 21:30:27 OK 20260905000000_add_claims.sql (2.71ms)7772026/09/21 21:30:27 OK 20260905000000_add_claims.sql (3.52ms)7782026/09/21 21:30:27 OK 20260905000000_add_claims.sql (3.09ms)7792026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (1.54ms)7802026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007812026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)7822026/09/21 21:30:27 OK 20251218171726_add_pins.sql (1.2ms)7832026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (901.21µs)7842026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007852026/09/21 21:30:27 OK 1_commit_pending_closure.sql (1.59ms)7862026/09/21 21:30:27 OK 1_commit_pending_closure.sql (1.7ms)7872026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (1.32ms)7882026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007892026/09/21 21:30:27 OK 1_commit_pending_closure.sql (1.63ms)7902026/09/21 21:30:27 OK 20251218171726_add_pins.sql (1.38ms)7912026/09/21 21:30:27 OK 2_object_stats_trigger.sql (487.75µs)7922026/09/21 21:30:27 goose: up to current file version: 27932026/09/21 21:30:27 OK 2_object_stats_trigger.sql (523.71µs)7942026/09/21 21:30:27 goose: up to current file version: 27952026/09/21 21:30:27 OK 1_commit_pending_closure.sql (1.4ms)7962026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (1.51ms)7972026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000007982026/09/21 21:30:27 OK 1_commit_pending_closure.sql (1.26ms)7992026/09/21 21:30:27 OK 2_object_stats_trigger.sql (353.42µs)8002026/09/21 21:30:27 goose: up to current file version: 28012026/09/21 21:30:27 OK 2_object_stats_trigger.sql (296.92µs)8022026/09/21 21:30:27 goose: up to current file version: 28032026/09/21 21:30:27 OK 2_object_stats_trigger.sql (339.25µs)8042026/09/21 21:30:27 goose: up to current file version: 28052026/09/21 21:30:27 OK 1_commit_pending_closure.sql (1.02ms)8062026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (1.85ms)8072026/09/21 21:30:27 OK 2_object_stats_trigger.sql (246.92µs)8082026/09/21 21:30:27 goose: up to current file version: 28092026/09/21 21:30:27 OK 1_commit_pending_closure.sql (854.71µs)8102026/09/21 21:30:27 OK 2_object_stats_trigger.sql (287.08µs)8112026/09/21 21:30:27 goose: up to current file version: 28122026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (1.44ms)8132026/09/21 21:30:27 OK 20241026095416_initial_model.sql (4.94ms)8142026/09/21 21:30:27 OK 20260905000000_add_claims.sql (1.13ms)8152026/09/21 21:30:27 OK 20251210153512_drop_unused_gin_index.sql (372.83µs)8162026/09/21 21:30:27 OK 20260905000000_add_claims.sql (965.88µs)8172026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (5.88ms)8182026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000008192026/09/21 21:30:27 OK 1_commit_pending_closure.sql (2.23ms)8202026/09/21 21:30:27 OK 2_object_stats_trigger.sql (197.42µs)8212026/09/21 21:30:27 goose: up to current file version: 28222026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (7.87ms)8232026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000008242026/09/21 21:30:27 OK 20251218171726_add_pins.sql (8.18ms)8252026/09/21 21:30:27 OK 1_commit_pending_closure.sql (653.63µs)8262026/09/21 21:30:27 OK 2_object_stats_trigger.sql (187.96µs)8272026/09/21 21:30:27 goose: up to current file version: 28282026/09/21 21:30:27 OK 20260628120000_add_object_size_and_stats.sql (31.54ms)8292026/09/21 21:30:27 OK 20260905000000_add_claims.sql (5.43ms)8302026/09/21 21:30:27 OK 20260920000000_drop_claims.sql (913.5µs)8312026/09/21 21:30:27 goose: successfully migrated database to version: 202609200000008322026/09/21 21:30:27 OK 1_commit_pending_closure.sql (663.29µs)8332026/09/21 21:30:27 OK 2_object_stats_trigger.sql (174.67µs)8342026/09/21 21:30:27 goose: up to current file version: 2835--- PASS: TestReadProxyRangeRequest (0.46s)836=== CONT TestOrphanedObjectsGC837--- PASS: TestService_healthCheckHandler (0.54s)838=== CONT TestObjectStatsTrigger839--- PASS: TestReadProxyNarinfo (0.89s)840=== CONT TestGCTaskStore_GetReturnsLatest841--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)842=== CONT TestGracefulShutdownDrainsInflight8432026/09/21 21:30:27 INFO Starting HTTP server address=127.0.0.1:520968442026/09/21 21:30:27 INFO Shutdown signal received, draining in-flight requests timeout=10s845--- PASS: TestGracefulShutdownDrainsInflight (0.07s)846=== CONT TestGCTaskStore_Fail847--- PASS: TestGCTaskStore_Fail (0.00s)848=== CONT TestGCTaskStore_PhaseUpdates849--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)850=== CONT TestGCTaskStore_CompletedAllowsNewTask851--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)852=== CONT TestClientErrorHandling853=== RUN TestClientErrorHandling/InvalidStorePath854=== PAUSE TestClientErrorHandling/InvalidStorePath855=== RUN TestClientErrorHandling/InvalidAuthToken856=== PAUSE TestClientErrorHandling/InvalidAuthToken857=== RUN TestClientErrorHandling/ServerNotAvailable858=== PAUSE TestClientErrorHandling/ServerNotAvailable859=== CONT TestGCBugBareHashReferences8602026/09/21 21:30:28 INFO Aborted multipart uploads count=08612026/09/21 21:30:28 WARN Force mode enabled - objects will be deleted immediately without grace period8622026/09/21 21:30:28 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=08632026/09/21 21:30:28 INFO Vacuumed table table=pending_closures8642026/09/21 21:30:28 INFO Vacuumed table table=pending_objects8652026/09/21 21:30:28 INFO Vacuumed table table=multipart_uploads8662026/09/21 21:30:28 INFO Vacuumed table table=closures8672026/09/21 21:30:28 INFO Vacuumed table table=objects868--- PASS: TestGCMetrics (1.03s)869=== CONT TestLeadEndsOnShutdown8702026-09-21 21:30:28.082 UTC [38790] ERROR: relation "goose_db_version" does not exist at character 368712026-09-21 21:30:28.082 UTC [38790] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8722026-09-21 21:30:28.109 UTC [38791] ERROR: relation "goose_db_version" does not exist at character 368732026-09-21 21:30:28.109 UTC [38791] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8742026/09/21 21:30:28 INFO Received uploads request method=POST path=/api/pending_closures8752026/09/21 21:30:28 OK 20241026095416_initial_model.sql (60.26ms)8762026/09/21 21:30:28 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)8772026/09/21 21:30:28 OK 20251218171726_add_pins.sql (16.67ms)8782026/09/21 21:30:28 OK 20260628120000_add_object_size_and_stats.sql (20.19ms)8792026/09/21 21:30:28 OK 20241026095416_initial_model.sql (60.85ms)8802026/09/21 21:30:28 OK 20251210153512_drop_unused_gin_index.sql (3.81ms)8812026/09/21 21:30:28 OK 20260905000000_add_claims.sql (5.93ms)8822026/09/21 21:30:28 OK 20260920000000_drop_claims.sql (9.22ms)8832026/09/21 21:30:28 goose: successfully migrated database to version: 202609200000008842026/09/21 21:30:28 OK 1_commit_pending_closure.sql (2.75ms)8852026/09/21 21:30:28 OK 2_object_stats_trigger.sql (794.46µs)8862026/09/21 21:30:28 goose: up to current file version: 28872026/09/21 21:30:28 OK 20251218171726_add_pins.sql (14.74ms)8882026/09/21 21:30:28 OK 20260628120000_add_object_size_and_stats.sql (14.09ms)8892026/09/21 21:30:28 OK 20260905000000_add_claims.sql (26.11ms)8902026/09/21 21:30:28 OK 20260920000000_drop_claims.sql (7.13ms)8912026/09/21 21:30:28 goose: successfully migrated database to version: 202609200000008922026/09/21 21:30:28 OK 1_commit_pending_closure.sql (3.4ms)8932026/09/21 21:30:28 OK 2_object_stats_trigger.sql (737.58µs)8942026/09/21 21:30:28 goose: up to current file version: 28952026/09/21 21:30:28 INFO Received cleanup request method=DELETE path=/api/pending_closures8962026/09/21 21:30:28 INFO Aborted multipart uploads count=18972026/09/21 21:30:28 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"898--- PASS: TestService_AuthMiddleware (1.31s)899=== CONT TestLeadElectsOneAndHandsOver900--- PASS: TestMultipartCleanup (1.32s)901=== CONT TestResolveDBConnectionString902=== RUN TestResolveDBConnectionString/flag_wins903=== PAUSE TestResolveDBConnectionString/flag_wins904=== RUN TestResolveDBConnectionString/file_when_flag_empty905=== PAUSE TestResolveDBConnectionString/file_when_flag_empty906=== RUN TestResolveDBConnectionString/missing_file_is_an_error907=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error908=== RUN TestResolveDBConnectionString/PGHOST_allows_empty909=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty910=== RUN TestResolveDBConnectionString/nothing_configured911=== PAUSE TestResolveDBConnectionString/nothing_configured912=== CONT TestPinProtectsFromGC9132026-09-21 21:30:28.384 UTC [38796] ERROR: relation "goose_db_version" does not exist at character 369142026-09-21 21:30:28.384 UTC [38796] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC915--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.48s)916=== CONT TestClientSharedPathCommittedMidPush9172026/09/21 21:30:28 OK 20241026095416_initial_model.sql (72.87ms)9182026/09/21 21:30:28 OK 20251210153512_drop_unused_gin_index.sql (13.91ms)9192026/09/21 21:30:28 OK 20251218171726_add_pins.sql (9.23ms)9202026/09/21 21:30:28 OK 20260628120000_add_object_size_and_stats.sql (17.33ms)9212026-09-21 21:30:28.546 UTC [38799] ERROR: relation "goose_db_version" does not exist at character 369222026-09-21 21:30:28.546 UTC [38799] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9232026/09/21 21:30:28 OK 20260905000000_add_claims.sql (13.69ms)9242026/09/21 21:30:28 OK 20260920000000_drop_claims.sql (17.27ms)9252026/09/21 21:30:28 goose: successfully migrated database to version: 202609200000009262026/09/21 21:30:28 OK 1_commit_pending_closure.sql (3.44ms)9272026/09/21 21:30:28 OK 2_object_stats_trigger.sql (815.33µs)9282026/09/21 21:30:28 goose: up to current file version: 29292026/09/21 21:30:28 OK 20241026095416_initial_model.sql (69.1ms)9302026/09/21 21:30:28 OK 20251210153512_drop_unused_gin_index.sql (10.67ms)9312026/09/21 21:30:28 OK 20251218171726_add_pins.sql (10.59ms)9322026/09/21 21:30:28 OK 20260628120000_add_object_size_and_stats.sql (17.06ms)9332026/09/21 21:30:28 OK 20260905000000_add_claims.sql (14.94ms)934--- PASS: TestResurrectedObjectNotDeleted (1.68s)935=== CONT TestClientWithDependencies9362026/09/21 21:30:28 OK 20260920000000_drop_claims.sql (13.9ms)9372026/09/21 21:30:28 goose: successfully migrated database to version: 202609200000009382026/09/21 21:30:28 OK 1_commit_pending_closure.sql (2.42ms)9392026/09/21 21:30:28 OK 2_object_stats_trigger.sql (500.75µs)9402026/09/21 21:30:28 goose: up to current file version: 29412026/09/21 21:30:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9422026/09/21 21:30:28 WARN Refused reserved pin name=worker-x86_64-linux9432026/09/21 21:30:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9442026/09/21 21:30:28 INFO Received create pin request method=POST path=/api/pins/my-app9452026/09/21 21:30:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux946--- PASS: TestCreatePin_ReservedPins (1.79s)947=== CONT TestClientMultipleUploads948--- PASS: TestObjectStatsTrigger (1.60s)949=== CONT TestClientIntegration9502026-09-21 21:30:29.186 UTC [38805] ERROR: relation "goose_db_version" does not exist at character 369512026-09-21 21:30:29.186 UTC [38805] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9522026-09-21 21:30:29.187 UTC [38806] ERROR: relation "goose_db_version" does not exist at character 369532026-09-21 21:30:29.187 UTC [38806] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9542026/09/21 21:30:29 OK 20241026095416_initial_model.sql (81.9ms)9552026/09/21 21:30:29 OK 20241026095416_initial_model.sql (81.98ms)9562026/09/21 21:30:29 OK 20251210153512_drop_unused_gin_index.sql (3.49ms)9572026/09/21 21:30:29 OK 20251210153512_drop_unused_gin_index.sql (3.22ms)9582026/09/21 21:30:29 OK 20251218171726_add_pins.sql (11.81ms)9592026/09/21 21:30:29 OK 20251218171726_add_pins.sql (12.49ms)9602026-09-21 21:30:29.323 UTC [38808] ERROR: relation "goose_db_version" does not exist at character 369612026-09-21 21:30:29.323 UTC [38808] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9622026/09/21 21:30:29 OK 20260628120000_add_object_size_and_stats.sql (18.16ms)9632026/09/21 21:30:29 OK 20260628120000_add_object_size_and_stats.sql (17.67ms)9642026/09/21 21:30:29 OK 20260905000000_add_claims.sql (19.79ms)9652026/09/21 21:30:29 OK 20260905000000_add_claims.sql (27.86ms)9662026/09/21 21:30:29 OK 20260920000000_drop_claims.sql (16.29ms)9672026/09/21 21:30:29 goose: successfully migrated database to version: 202609200000009682026/09/21 21:30:29 OK 20260920000000_drop_claims.sql (9.99ms)9692026/09/21 21:30:29 goose: successfully migrated database to version: 202609200000009702026/09/21 21:30:29 OK 1_commit_pending_closure.sql (4.6ms)9712026/09/21 21:30:29 OK 1_commit_pending_closure.sql (3.17ms)9722026/09/21 21:30:29 OK 2_object_stats_trigger.sql (632.5µs)9732026/09/21 21:30:29 goose: up to current file version: 29742026/09/21 21:30:29 OK 2_object_stats_trigger.sql (608.04µs)9752026/09/21 21:30:29 goose: up to current file version: 2976=== NAME TestOrphanedObjectsGC977 orphaned_objects_gc_test.go:290: GC Test Summary:978 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A979 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B980 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)981 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)982 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects983--- PASS: TestOrphanedObjectsGC (1.94s)984=== CONT TestPresignedUploadRegisteredBeforeCommit9852026/09/21 21:30:29 OK 20241026095416_initial_model.sql (66.98ms)9862026/09/21 21:30:29 OK 20251210153512_drop_unused_gin_index.sql (7.06ms)9872026/09/21 21:30:29 OK 20251218171726_add_pins.sql (13.71ms)9882026/09/21 21:30:29 OK 20260628120000_add_object_size_and_stats.sql (23.05ms)9892026/09/21 21:30:29 INFO lead: acquired remote=192.0.2.1:12349902026/09/21 21:30:29 INFO lead: released remote=192.0.2.1:1234991--- PASS: TestLeadEndsOnShutdown (1.43s)992=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9932026/09/21 21:30:29 OK 20260905000000_add_claims.sql (5.56ms)9942026/09/21 21:30:29 OK 20260920000000_drop_claims.sql (21.51ms)9952026/09/21 21:30:29 goose: successfully migrated database to version: 202609200000009962026/09/21 21:30:29 OK 1_commit_pending_closure.sql (2.01ms)9972026/09/21 21:30:29 OK 2_object_stats_trigger.sql (397.13µs)9982026/09/21 21:30:29 goose: up to current file version: 2999--- PASS: TestGCBugBareHashReferences (1.56s)1000=== CONT TestSkippedUploadsHandler10012026/09/21 21:30:29 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001002--- PASS: TestSkippedUploadsHandler (0.00s)1003=== CONT TestParseSize1004--- PASS: TestParseSize (0.00s)1005=== CONT TestService_Rustfstest10062026-09-21 21:30:29.566 UTC [38815] ERROR: relation "goose_db_version" does not exist at character 3610072026-09-21 21:30:29.566 UTC [38815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10082026/09/21 21:30:29 OK 20241026095416_initial_model.sql (73.88ms)10092026/09/21 21:30:29 OK 20251210153512_drop_unused_gin_index.sql (7.74ms)10102026-09-21 21:30:29.682 UTC [38817] ERROR: relation "goose_db_version" does not exist at character 3610112026-09-21 21:30:29.682 UTC [38817] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10122026/09/21 21:30:29 OK 20251218171726_add_pins.sql (12.11ms)10132026/09/21 21:30:29 OK 20260628120000_add_object_size_and_stats.sql (15.78ms)10142026/09/21 21:30:29 OK 20260905000000_add_claims.sql (17.81ms)10152026/09/21 21:30:29 OK 20260920000000_drop_claims.sql (21.72ms)10162026/09/21 21:30:29 goose: successfully migrated database to version: 2026092000000010172026/09/21 21:30:29 OK 1_commit_pending_closure.sql (1.2ms)10182026/09/21 21:30:29 OK 2_object_stats_trigger.sql (272.96µs)10192026/09/21 21:30:29 goose: up to current file version: 210202026/09/21 21:30:29 INFO lead: acquired remote=192.0.2.1:123410212026/09/21 21:30:29 OK 20241026095416_initial_model.sql (83.08ms)10222026/09/21 21:30:29 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)10232026/09/21 21:30:29 OK 20251218171726_add_pins.sql (12.05ms)10242026/09/21 21:30:29 OK 20260628120000_add_object_size_and_stats.sql (10.64ms)10252026/09/21 21:30:29 OK 20260905000000_add_claims.sql (30.09ms)1026=== NAME TestPinProtectsFromGC1027 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-38627-3659511840/TestPinProtectsFromGC4041070408/001/store/r268pjzgqsgj236hqar76lx3i8xk8ydx-pinned-file.txt1028 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-38627-3659511840/TestPinProtectsFromGC4041070408/001/store/mapypa78yd2lf96694c699b1y2cq6pbv-unpinned-file.txt10292026/09/21 21:30:29 OK 20260920000000_drop_claims.sql (21.33ms)10302026/09/21 21:30:29 goose: successfully migrated database to version: 2026092000000010312026/09/21 21:30:29 OK 1_commit_pending_closure.sql (1.2ms)10322026/09/21 21:30:29 OK 2_object_stats_trigger.sql (286.54µs)10332026/09/21 21:30:29 goose: up to current file version: 210342026/09/21 21:30:29 INFO lead: released remote=192.0.2.1:123410352026/09/21 21:30:29 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10362026-09-21 21:30:29.988 UTC [38829] ERROR: relation "goose_db_version" does not exist at character 3610372026-09-21 21:30:29.988 UTC [38829] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10382026/09/21 21:30:29 INFO lead: acquired remote=192.0.2.1:123410392026/09/21 21:30:29 INFO lead: released remote=192.0.2.1:12341040--- PASS: TestLeadElectsOneAndHandsOver (1.68s)1041=== CONT TestGCTaskStore_ConflictDifferentParams1042--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1043=== CONT TestGCTaskStore_GetEmpty1044--- PASS: TestGCTaskStore_GetEmpty (0.00s)1045=== CONT TestReadProxyRootRedirectsToIndexHTML10462026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures10472026/09/21 21:30:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10482026/09/21 21:30:30 INFO Uploading r268pjzgqsgj236hqar76lx3i8xk8ydx-pinned-file.txt (128B)10492026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"10502026/09/21 21:30:30 WARN Failed to register uploaded object key=r268pjzgqsgj236hqar76lx3i8xk8ydx.ls error="server returned 404: 404 page not found\n"10512026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10522026/09/21 21:30:30 INFO Signed narinfos id=1 count=110532026/09/21 21:30:30 INFO Uploading 1 narinfos10542026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10552026/09/21 21:30:30 WARN Failed to register uploaded object key=r268pjzgqsgj236hqar76lx3i8xk8ydx.narinfo error="server returned 404: 404 page not found\n"10562026/09/21 21:30:30 INFO Completed upload id=110572026/09/21 21:30:30 INFO Upload complete. (170ms)10582026/09/21 21:30:30 OK 20241026095416_initial_model.sql (75.07ms)10592026/09/21 21:30:30 OK 20251210153512_drop_unused_gin_index.sql (1.26ms)10602026/09/21 21:30:30 OK 20251218171726_add_pins.sql (15.58ms)10612026/09/21 21:30:30 OK 20260628120000_add_object_size_and_stats.sql (8.27ms)10622026/09/21 21:30:30 OK 20260905000000_add_claims.sql (9.51ms)10632026/09/21 21:30:30 OK 20260920000000_drop_claims.sql (2.36ms)10642026/09/21 21:30:30 goose: successfully migrated database to version: 2026092000000010652026/09/21 21:30:30 OK 1_commit_pending_closure.sql (1.18ms)10662026/09/21 21:30:30 OK 2_object_stats_trigger.sql (301.83µs)10672026/09/21 21:30:30 goose: up to current file version: 210682026-09-21 21:30:30.154 UTC [38842] ERROR: relation "goose_db_version" does not exist at character 3610692026-09-21 21:30:30.154 UTC [38842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10702026/09/21 21:30:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10712026/09/21 21:30:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10722026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures10732026/09/21 21:30:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10742026/09/21 21:30:30 INFO Uploading mapypa78yd2lf96694c699b1y2cq6pbv-unpinned-file.txt (128B)10752026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"10762026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10772026/09/21 21:30:30 INFO Signed narinfos id=2 count=110782026/09/21 21:30:30 INFO Uploading 1 narinfos10792026/09/21 21:30:30 WARN Failed to register uploaded object key=mapypa78yd2lf96694c699b1y2cq6pbv.ls error="server returned 404: 404 page not found\n"10802026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures10812026-09-21 21:30:30.244 UTC [38852] ERROR: relation "goose_db_version" does not exist at character 3610822026-09-21 21:30:30.244 UTC [38852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10832026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10842026/09/21 21:30:30 WARN Failed to register uploaded object key=mapypa78yd2lf96694c699b1y2cq6pbv.narinfo error="server returned 404: 404 page not found\n"10852026/09/21 21:30:30 INFO Completed upload id=210862026/09/21 21:30:30 INFO Upload complete. (131ms)10872026/09/21 21:30:30 OK 20241026095416_initial_model.sql (72.06ms)10882026/09/21 21:30:30 OK 20251210153512_drop_unused_gin_index.sql (6.82ms)10892026/09/21 21:30:30 INFO Received create pin request method=POST path=/api/pins/myapp10902026/09/21 21:30:30 OK 20251218171726_add_pins.sql (18.98ms)10912026/09/21 21:30:30 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-38627-3659511840/TestPinProtectsFromGC4041070408/001/store/r268pjzgqsgj236hqar76lx3i8xk8ydx-pinned-file.txt narinfo_key=r268pjzgqsgj236hqar76lx3i8xk8ydx.narinfo10922026/09/21 21:30:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures10932026/09/21 21:30:30 INFO Garbage collection started10942026/09/21 21:30:30 INFO Aborted multipart uploads count=010952026/09/21 21:30:30 WARN Force mode enabled - objects will be deleted immediately without grace period10962026/09/21 21:30:30 OK 20260628120000_add_object_size_and_stats.sql (11.92ms)10972026/09/21 21:30:30 OK 20260905000000_add_claims.sql (8.4ms)10982026/09/21 21:30:30 OK 20260920000000_drop_claims.sql (9.09ms)10992026/09/21 21:30:30 goose: successfully migrated database to version: 2026092000000011002026/09/21 21:30:30 OK 1_commit_pending_closure.sql (1.86ms)11012026/09/21 21:30:30 OK 2_object_stats_trigger.sql (485.88µs)11022026/09/21 21:30:30 goose: up to current file version: 211032026-09-21 21:30:30.323 UTC [38862] ERROR: relation "goose_db_version" does not exist at character 3611042026-09-21 21:30:30.323 UTC [38862] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11052026/09/21 21:30:30 OK 20241026095416_initial_model.sql (51.17ms)11062026/09/21 21:30:30 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)11072026/09/21 21:30:30 OK 20251218171726_add_pins.sql (7.95ms)11082026/09/21 21:30:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11092026/09/21 21:30:30 OK 20260628120000_add_object_size_and_stats.sql (23.18ms)11102026/09/21 21:30:30 OK 20260905000000_add_claims.sql (21.02ms)11112026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures11122026/09/21 21:30:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11132026/09/21 21:30:30 INFO Uploading fgjvg5gw6ycc9yafx7gm19b4r8aqjvir-shared-dep (136B)1114=== NAME TestClientMultipleUploads1115 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-38627-3659511840/TestClientMultipleUploads118115236/001/store/n9ki188r05rlpdmsagky8192alz92hh9-test-file-0.txt11162026/09/21 21:30:30 OK 20260920000000_drop_claims.sql (8.06ms)11172026/09/21 21:30:30 goose: successfully migrated database to version: 2026092000000011182026/09/21 21:30:30 OK 1_commit_pending_closure.sql (1.08ms)11192026/09/21 21:30:30 OK 2_object_stats_trigger.sql (252.88µs)11202026/09/21 21:30:30 goose: up to current file version: 211212026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1122=== NAME TestClientWithDependencies1123 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-38627-3659511840/TestClientWithDependencies314809369/001/store/fxdqyfmsifkkqzghjiw7ipb3v203ylv0-test-script11242026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11252026/09/21 21:30:30 WARN Failed to register uploaded object key=fgjvg5gw6ycc9yafx7gm19b4r8aqjvir.ls error="server returned 404: 404 page not found\n"11262026/09/21 21:30:30 INFO Signed narinfos id=2 count=111272026/09/21 21:30:30 INFO Uploading 1 narinfos11282026/09/21 21:30:30 OK 20241026095416_initial_model.sql (65.43ms)11292026/09/21 21:30:30 OK 20251210153512_drop_unused_gin_index.sql (5.5ms)11302026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11312026/09/21 21:30:30 WARN Failed to register uploaded object key=fgjvg5gw6ycc9yafx7gm19b4r8aqjvir.narinfo error="server returned 404: 404 page not found\n"11322026/09/21 21:30:30 INFO Completed upload id=211332026/09/21 21:30:30 INFO Upload complete. (128ms)11342026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures11352026/09/21 21:30:30 OK 20251218171726_add_pins.sql (10.74ms)11362026/09/21 21:30:30 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11372026/09/21 21:30:30 INFO Uploading cx3wgnv8vqnvgfikf1nwqibgw3pifklk-top (256B)11382026/09/21 21:30:30 INFO Uploading fgjvg5gw6ycc9yafx7gm19b4r8aqjvir-shared-dep (136B)1139 client_integration_test.go:615: Found 1 dependencies (including self)11402026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/0zbqd6p4il47imrvwd850sk6szxnrcyxmnhb79bjcd0jk4k91vaj.nar.zst error="server returned 404: 404 page not found\n"11412026/09/21 21:30:30 OK 20260628120000_add_object_size_and_stats.sql (20.3ms)11422026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11432026/09/21 21:30:30 WARN Failed to register uploaded object key=cx3wgnv8vqnvgfikf1nwqibgw3pifklk.ls error="server returned 404: 404 page not found\n"1144=== NAME TestClientMultipleUploads1145 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-38627-3659511840/TestClientMultipleUploads118115236/001/store/g4dcfp0w7b486vzadhni85jk1r5zxx3g-test-file-1.txt11462026/09/21 21:30:30 OK 20260905000000_add_claims.sql (12.27ms)11472026/09/21 21:30:30 OK 20260920000000_drop_claims.sql (1.44ms)11482026/09/21 21:30:30 goose: successfully migrated database to version: 2026092000000011492026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11502026/09/21 21:30:30 INFO Signed narinfos id=1 count=111512026/09/21 21:30:30 WARN Failed to register uploaded object key=fgjvg5gw6ycc9yafx7gm19b4r8aqjvir.ls error="server returned 404: 404 page not found\n"11522026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign11532026/09/21 21:30:30 INFO Signed narinfos id=3 count=111542026/09/21 21:30:30 INFO Uploading 2 narinfos11552026/09/21 21:30:30 OK 1_commit_pending_closure.sql (1.76ms)11562026/09/21 21:30:30 OK 2_object_stats_trigger.sql (395.92µs)11572026/09/21 21:30:30 goose: up to current file version: 211582026/09/21 21:30:30 WARN Failed to register uploaded object key=cx3wgnv8vqnvgfikf1nwqibgw3pifklk.narinfo error="server returned 404: 404 page not found\n"11592026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete11602026/09/21 21:30:30 WARN Failed to register uploaded object key=fgjvg5gw6ycc9yafx7gm19b4r8aqjvir.narinfo error="server returned 404: 404 page not found\n"11612026/09/21 21:30:30 INFO Completed upload id=311622026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11632026/09/21 21:30:30 INFO Completed upload id=111642026/09/21 21:30:30 INFO Upload complete. (336ms)1165=== NAME TestClientSharedPathCommittedMidPush1166 client_integration_test.go:680: Retrieved narinfo from S3:1167 StorePath: /nix/var/nix/builds/nix-38627-3659511840/TestClientSharedPathCommittedMidPush1358792983/001/store/fgjvg5gw6ycc9yafx7gm19b4r8aqjvir-shared-dep1168 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1169 Compression: zstd1170 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821171 NarSize: 1361172 References: 1173 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1174 client_integration_test.go:680: Retrieved narinfo from S3:1175 StorePath: /nix/var/nix/builds/nix-38627-3659511840/TestClientSharedPathCommittedMidPush1358792983/001/store/cx3wgnv8vqnvgfikf1nwqibgw3pifklk-top1176 URL: nar/0zbqd6p4il47imrvwd850sk6szxnrcyxmnhb79bjcd0jk4k91vaj.nar.zst1177 Compression: zstd1178 NarHash: sha256:0zbqd6p4il47imrvwd850sk6szxnrcyxmnhb79bjcd0jk4k91vaj1179 NarSize: 2561180 References: /nix/var/nix/builds/nix-38627-3659511840/TestClientSharedPathCommittedMidPush1358792983/001/store/fgjvg5gw6ycc9yafx7gm19b4r8aqjvir-shared-dep1181 CA: text:sha256:195akajq6pw3cxc6wl5ws3gs56l4pkxrkm1xhc3369l8pll6zcqd1182--- PASS: TestClientSharedPathCommittedMidPush (2.01s)1183=== CONT TestReadRedirectKeepsNarinfoProxied1184=== NAME TestClientMultipleUploads1185 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-38627-3659511840/TestClientMultipleUploads118115236/001/store/ww5yx93n0bahyilap72b4zbpkpyndfpx-test-file-2.txt11862026/09/21 21:30:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11872026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures11882026/09/21 21:30:30 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=011892026/09/21 21:30:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11902026/09/21 21:30:30 INFO Uploading fxdqyfmsifkkqzghjiw7ipb3v203ylv0-test-script (136B)11912026/09/21 21:30:30 INFO Vacuumed table table=pending_closures11922026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"11932026/09/21 21:30:30 WARN Failed to register uploaded object key=log/hjy2fw3jydggrm3w8309h6prkpm6l85i-test-script.drv error="server returned 404: 404 page not found\n"11942026/09/21 21:30:30 INFO Vacuumed table table=pending_objects11952026/09/21 21:30:30 INFO Vacuumed table table=multipart_uploads11962026/09/21 21:30:30 INFO Vacuumed table table=closures11972026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign1198=== NAME TestClientIntegration1199 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-38627-3659511840/TestClientIntegration1548106483/002/store/i2m081vhq1r61lbidn26abw39acwp8rw-test-file.txt12002026/09/21 21:30:30 WARN Failed to register uploaded object key=fxdqyfmsifkkqzghjiw7ipb3v203ylv0.ls error="server returned 404: 404 page not found\n"12012026/09/21 21:30:30 INFO Signed narinfos id=1 count=112022026/09/21 21:30:30 INFO Uploading 1 narinfos12032026/09/21 21:30:30 INFO Vacuumed table table=objects12042026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12052026/09/21 21:30:30 WARN Failed to register uploaded object key=fxdqyfmsifkkqzghjiw7ipb3v203ylv0.narinfo error="server returned 404: 404 page not found\n"12062026/09/21 21:30:30 INFO Completed upload id=112072026/09/21 21:30:30 INFO Upload complete. (97ms)1208=== NAME TestClientWithDependencies1209 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-38627-3659511840/TestClientWithDependencies314809369/001/store) requires matching store prefix1210--- PASS: TestClientWithDependencies (1.89s)1211=== CONT TestReadRedirectNar1212=== NAME TestOrphanedObjectsGCStressTest1213 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains12142026/09/21 21:30:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12152026-09-21 21:30:30.604 UTC [38892] ERROR: relation "goose_db_version" does not exist at character 3612162026-09-21 21:30:30.604 UTC [38892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12172026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures1218 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion12192026/09/21 21:30:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12202026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures12212026/09/21 21:30:30 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12222026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures1223--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.23s)1224=== CONT TestReadProxyDisabled12252026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures12262026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures12272026/09/21 21:30:30 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12282026/09/21 21:30:30 INFO Uploading ww5yx93n0bahyilap72b4zbpkpyndfpx-test-file-2.txt (160B)12292026/09/21 21:30:30 INFO Uploading n9ki188r05rlpdmsagky8192alz92hh9-test-file-0.txt (160B)12302026/09/21 21:30:30 INFO Uploading g4dcfp0w7b486vzadhni85jk1r5zxx3g-test-file-1.txt (160B)12312026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"12322026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"12332026/09/21 21:30:30 OK 20241026095416_initial_model.sql (39.71ms)12342026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12352026/09/21 21:30:30 WARN Failed to register uploaded object key=ww5yx93n0bahyilap72b4zbpkpyndfpx.ls error="server returned 404: 404 page not found\n"12362026/09/21 21:30:30 WARN Failed to register uploaded object key=g4dcfp0w7b486vzadhni85jk1r5zxx3g.ls error="server returned 404: 404 page not found\n"12372026/09/21 21:30:30 OK 20251210153512_drop_unused_gin_index.sql (1.49ms)12382026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign12392026/09/21 21:30:30 WARN Failed to register uploaded object key=n9ki188r05rlpdmsagky8192alz92hh9.ls error="server returned 404: 404 page not found\n"12402026/09/21 21:30:30 INFO Signed narinfos id=3 count=112412026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12422026/09/21 21:30:30 INFO Signed narinfos id=1 count=112432026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12442026/09/21 21:30:30 INFO Signed narinfos id=2 count=112452026/09/21 21:30:30 INFO Uploading 3 narinfos12462026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures12472026/09/21 21:30:30 WARN Failed to register uploaded object key=ww5yx93n0bahyilap72b4zbpkpyndfpx.narinfo error="server returned 404: 404 page not found\n"12482026/09/21 21:30:30 WARN Failed to register uploaded object key=n9ki188r05rlpdmsagky8192alz92hh9.narinfo error="server returned 404: 404 page not found\n"12492026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12502026/09/21 21:30:30 WARN Failed to register uploaded object key=g4dcfp0w7b486vzadhni85jk1r5zxx3g.narinfo error="server returned 404: 404 page not found\n"12512026/09/21 21:30:30 OK 20251218171726_add_pins.sql (32.71ms)12522026/09/21 21:30:30 INFO Completed upload id=112532026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12542026/09/21 21:30:30 INFO Completed upload id=212552026/09/21 21:30:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12562026/09/21 21:30:30 INFO Uploading i2m081vhq1r61lbidn26abw39acwp8rw-test-file.txt (152B)12572026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete12582026/09/21 21:30:30 INFO Completed upload id=312592026/09/21 21:30:30 INFO Upload complete. (147ms)1260=== NAME TestClientMultipleUploads1261 client_integration_test.go:369: Uploaded 3 paths in 188.804708ms12622026/09/21 21:30:30 OK 20260628120000_add_object_size_and_stats.sql (16.64ms)12632026/09/21 21:30:30 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12642026/09/21 21:30:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12652026/09/21 21:30:30 WARN Failed to register uploaded object key=i2m081vhq1r61lbidn26abw39acwp8rw.ls error="server returned 404: 404 page not found\n"12662026/09/21 21:30:30 INFO Signed narinfos id=1 count=112672026/09/21 21:30:30 INFO Uploading 1 narinfos12682026/09/21 21:30:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12692026/09/21 21:30:30 WARN Failed to register uploaded object key=i2m081vhq1r61lbidn26abw39acwp8rw.narinfo error="server returned 404: 404 page not found\n"12702026/09/21 21:30:30 OK 20260905000000_add_claims.sql (23.59ms)1271--- PASS: TestClientMultipleUploads (1.94s)1272=== CONT TestService_RequireScope_OIDC12732026/09/21 21:30:30 INFO Completed upload id=112742026/09/21 21:30:30 INFO Upload complete. (152ms)12752026/09/21 21:30:30 OK 20260920000000_drop_claims.sql (12.06ms)12762026/09/21 21:30:30 goose: successfully migrated database to version: 2026092000000012772026/09/21 21:30:30 OK 1_commit_pending_closure.sql (1.12ms)12782026/09/21 21:30:30 OK 2_object_stats_trigger.sql (219.54µs)12792026/09/21 21:30:30 goose: up to current file version: 212802026/09/21 21:30:30 INFO Received uploads request method=POST path=/api/pending_closures12812026/09/21 21:30:30 INFO All 1 paths already cached1282=== NAME TestClientIntegration1283 client_integration_test.go:312: Retrieved narinfo from S3:1284 StorePath: /nix/var/nix/builds/nix-38627-3659511840/TestClientIntegration1548106483/002/store/i2m081vhq1r61lbidn26abw39acwp8rw-test-file.txt1285 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1286 Compression: zstd1287 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11288 NarSize: 1521289 References: 1290 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11291 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1292 client_integration_test.go:313: Decompressed .ls content (64 bytes):1293 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1294 client_integration_test.go:316: Testing garbage collection...12952026/09/21 21:30:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52155/oidc12962026/09/21 21:30:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures12972026/09/21 21:30:30 INFO Garbage collection started12982026/09/21 21:30:30 INFO Aborted multipart uploads count=012992026/09/21 21:30:30 WARN Force mode enabled - objects will be deleted immediately without grace period1300--- PASS: TestService_Rustfstest (1.41s)1301=== CONT TestClientCADerivations13022026/09/21 21:30:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13032026/09/21 21:30:31 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=013042026/09/21 21:30:31 INFO Vacuumed table table=pending_closures13052026/09/21 21:30:31 INFO Vacuumed table table=pending_objects13062026/09/21 21:30:31 INFO Vacuumed table table=multipart_uploads1307--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.09s)1308=== CONT TestCacheStatsHandler13092026/09/21 21:30:31 INFO Vacuumed table table=closures13102026/09/21 21:30:31 INFO Vacuumed table table=objects13112026-09-21 21:30:31.116 UTC [38911] ERROR: relation "goose_db_version" does not exist at character 3613122026-09-21 21:30:31.116 UTC [38911] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13132026/09/21 21:30:31 OK 20241026095416_initial_model.sql (6.35ms)13142026/09/21 21:30:31 OK 20251210153512_drop_unused_gin_index.sql (816.75µs)13152026/09/21 21:30:31 OK 20251218171726_add_pins.sql (831.08µs)13162026-09-21 21:30:31.134 UTC [38912] ERROR: relation "goose_db_version" does not exist at character 3613172026-09-21 21:30:31.134 UTC [38912] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13182026/09/21 21:30:31 OK 20260628120000_add_object_size_and_stats.sql (10.45ms)13192026/09/21 21:30:31 OK 20260905000000_add_claims.sql (3.22ms)13202026/09/21 21:30:31 OK 20260920000000_drop_claims.sql (6.6ms)13212026/09/21 21:30:31 goose: successfully migrated database to version: 2026092000000013222026/09/21 21:30:31 OK 1_commit_pending_closure.sql (9.2ms)13232026/09/21 21:30:31 OK 2_object_stats_trigger.sql (8.1ms)13242026/09/21 21:30:31 goose: up to current file version: 213252026/09/21 21:30:31 OK 20241026095416_initial_model.sql (46.62ms)13262026/09/21 21:30:31 OK 20251210153512_drop_unused_gin_index.sql (676.46µs)13272026/09/21 21:30:31 OK 20251218171726_add_pins.sql (18.11ms)13282026/09/21 21:30:31 OK 20260628120000_add_object_size_and_stats.sql (18.54ms)13292026/09/21 21:30:31 OK 20260905000000_add_claims.sql (5.5ms)13302026/09/21 21:30:31 OK 20260920000000_drop_claims.sql (13.55ms)13312026/09/21 21:30:31 goose: successfully migrated database to version: 2026092000000013322026/09/21 21:30:31 OK 1_commit_pending_closure.sql (1.75ms)13332026/09/21 21:30:31 OK 2_object_stats_trigger.sql (225.25µs)13342026/09/21 21:30:31 goose: up to current file version: 21335=== NAME TestOrphanedObjectsGCStressTest1336 orphaned_objects_gc_test.go:509: Stress test completed successfully:1337 orphaned_objects_gc_test.go:510: - Active objects preserved: 201338 orphaned_objects_gc_test.go:511: - Objects deleted: 2101339 orphaned_objects_gc_test.go:512: - Total GC'd: 2101340--- PASS: TestOrphanedObjectsGCStressTest (4.28s)1341=== CONT TestCacheConfigHandler1342=== RUN TestCacheConfigHandler/full_config,_no_issuer1343=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1344=== RUN TestCacheConfigHandler/no_cache_url_configured1345=== PAUSE TestCacheConfigHandler/no_cache_url_configured1346=== RUN TestCacheConfigHandler/no_signing_keys1347=== PAUSE TestCacheConfigHandler/no_signing_keys1348=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1349=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1350=== CONT TestService_ReadScope_PublicByDefault13512026-09-21 21:30:31.333 UTC [38915] ERROR: relation "goose_db_version" does not exist at character 3613522026-09-21 21:30:31.333 UTC [38915] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1353--- PASS: TestReadRedirectKeepsNarinfoProxied (0.86s)1354=== CONT TestService_ReadAuthMiddleware13552026/09/21 21:30:31 OK 20241026095416_initial_model.sql (40.14ms)13562026/09/21 21:30:31 OK 20251210153512_drop_unused_gin_index.sql (7.51ms)13572026/09/21 21:30:31 OK 20251218171726_add_pins.sql (7.42ms)13582026/09/21 21:30:31 OK 20260628120000_add_object_size_and_stats.sql (14.18ms)13592026/09/21 21:30:31 OK 20260905000000_add_claims.sql (14.05ms)13602026/09/21 21:30:31 OK 20260920000000_drop_claims.sql (1.9ms)13612026/09/21 21:30:31 goose: successfully migrated database to version: 2026092000000013622026/09/21 21:30:31 OK 1_commit_pending_closure.sql (1.14ms)13632026/09/21 21:30:31 OK 2_object_stats_trigger.sql (269.5µs)13642026/09/21 21:30:31 goose: up to current file version: 21365--- PASS: TestReadRedirectNar (0.92s)1366=== CONT TestService_AuthMiddleware_OIDC13672026/09/21 21:30:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52170/oidc13682026-09-21 21:30:31.547 UTC [38919] ERROR: relation "goose_db_version" does not exist at character 3613692026-09-21 21:30:31.547 UTC [38919] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13702026-09-21 21:30:31.547 UTC [38918] ERROR: relation "goose_db_version" does not exist at character 3613712026-09-21 21:30:31.547 UTC [38918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13722026/09/21 21:30:31 OK 20241026095416_initial_model.sql (67.87ms)1373--- PASS: TestReadProxyDisabled (0.99s)1374=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13752026/09/21 21:30:31 OK 20241026095416_initial_model.sql (58.37ms)13762026/09/21 21:30:31 OK 20251210153512_drop_unused_gin_index.sql (1.08ms)13772026/09/21 21:30:31 OK 20251210153512_drop_unused_gin_index.sql (1.7ms)13782026/09/21 21:30:31 OK 20251218171726_add_pins.sql (1.68ms)13792026/09/21 21:30:31 OK 20251218171726_add_pins.sql (2.59ms)13802026/09/21 21:30:31 OK 20260628120000_add_object_size_and_stats.sql (9.93ms)13812026-09-21 21:30:31.647 UTC [38924] ERROR: relation "goose_db_version" does not exist at character 3613822026-09-21 21:30:31.647 UTC [38924] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13832026/09/21 21:30:31 OK 20260628120000_add_object_size_and_stats.sql (15.35ms)13842026/09/21 21:30:31 OK 20260905000000_add_claims.sql (7.67ms)13852026/09/21 21:30:31 OK 20260905000000_add_claims.sql (1.55ms)13862026/09/21 21:30:31 OK 20260920000000_drop_claims.sql (916.75µs)13872026/09/21 21:30:31 goose: successfully migrated database to version: 2026092000000013882026/09/21 21:30:31 OK 20260920000000_drop_claims.sql (794.63µs)13892026/09/21 21:30:31 goose: successfully migrated database to version: 2026092000000013902026/09/21 21:30:31 OK 1_commit_pending_closure.sql (1.1ms)13912026/09/21 21:30:31 OK 1_commit_pending_closure.sql (1.16ms)13922026/09/21 21:30:31 OK 2_object_stats_trigger.sql (235.79µs)13932026/09/21 21:30:31 goose: up to current file version: 213942026/09/21 21:30:31 OK 2_object_stats_trigger.sql (263.96µs)13952026/09/21 21:30:31 goose: up to current file version: 213962026/09/21 21:30:31 OK 20241026095416_initial_model.sql (40.03ms)13972026/09/21 21:30:31 OK 20251210153512_drop_unused_gin_index.sql (13.17ms)13982026/09/21 21:30:31 OK 20251218171726_add_pins.sql (9.8ms)13992026/09/21 21:30:31 OK 20260628120000_add_object_size_and_stats.sql (6.25ms)14002026/09/21 21:30:31 OK 20260905000000_add_claims.sql (16.03ms)14012026/09/21 21:30:31 OK 20260920000000_drop_claims.sql (12.65ms)14022026/09/21 21:30:31 goose: successfully migrated database to version: 2026092000000014032026/09/21 21:30:31 OK 1_commit_pending_closure.sql (1.53ms)14042026/09/21 21:30:31 OK 2_object_stats_trigger.sql (324.21µs)14052026/09/21 21:30:31 goose: up to current file version: 21406=== RUN TestService_RequireScope_OIDC/builder_may_write1407=== PAUSE TestService_RequireScope_OIDC/builder_may_write1408=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1409=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1410=== RUN TestService_RequireScope_OIDC/ops_may_admin1411=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1412=== RUN TestService_RequireScope_OIDC/ops_may_not_write1413=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1414=== RUN TestService_RequireScope_OIDC/reader_may_not_write1415=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1416=== RUN TestService_RequireScope_OIDC/static_token_may_admin1417=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1418=== RUN TestService_RequireScope_OIDC/static_token_may_write1419=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1420=== RUN TestService_RequireScope_OIDC/reader_may_read1421=== PAUSE TestService_RequireScope_OIDC/reader_may_read1422=== RUN TestService_RequireScope_OIDC/writer_implies_read1423=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1424=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1425=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1426=== CONT TestService_createPendingClosureHandler14272026-09-21 21:30:31.997 UTC [38928] ERROR: relation "goose_db_version" does not exist at character 3614282026-09-21 21:30:31.997 UTC [38928] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14292026-09-21 21:30:31.999 UTC [38929] ERROR: relation "goose_db_version" does not exist at character 3614302026-09-21 21:30:31.999 UTC [38929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14312026/09/21 21:30:32 OK 20241026095416_initial_model.sql (64.46ms)14322026/09/21 21:30:32 OK 20251210153512_drop_unused_gin_index.sql (989.5µs)14332026/09/21 21:30:32 OK 20241026095416_initial_model.sql (58.39ms)14342026/09/21 21:30:32 OK 20251210153512_drop_unused_gin_index.sql (809.08µs)14352026/09/21 21:30:32 OK 20251218171726_add_pins.sql (1.58ms)14362026/09/21 21:30:32 OK 20251218171726_add_pins.sql (1.23ms)14372026/09/21 21:30:32 OK 20260628120000_add_object_size_and_stats.sql (1.76ms)1438--- PASS: TestCacheStatsHandler (1.00s)1439=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT14402026/09/21 21:30:32 OK 20260905000000_add_claims.sql (2.84ms)14412026/09/21 21:30:32 OK 20260920000000_drop_claims.sql (1.55ms)14422026/09/21 21:30:32 goose: successfully migrated database to version: 2026092000000014432026/09/21 21:30:32 OK 20260628120000_add_object_size_and_stats.sql (5.51ms)14442026/09/21 21:30:32 OK 1_commit_pending_closure.sql (1.16ms)14452026/09/21 21:30:32 OK 2_object_stats_trigger.sql (657.33µs)14462026/09/21 21:30:32 goose: up to current file version: 214472026/09/21 21:30:32 OK 20260905000000_add_claims.sql (2.13ms)14482026/09/21 21:30:32 OK 20260920000000_drop_claims.sql (904.38µs)14492026/09/21 21:30:32 goose: successfully migrated database to version: 2026092000000014502026/09/21 21:30:32 OK 1_commit_pending_closure.sql (1.65ms)14512026/09/21 21:30:32 OK 2_object_stats_trigger.sql (391.08µs)14522026/09/21 21:30:32 goose: up to current file version: 214532026-09-21 21:30:32.108 UTC [38933] ERROR: relation "goose_db_version" does not exist at character 3614542026-09-21 21:30:32.108 UTC [38933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14552026/09/21 21:30:32 OK 20241026095416_initial_model.sql (34.17ms)14562026/09/21 21:30:32 OK 20251210153512_drop_unused_gin_index.sql (838.67µs)14572026/09/21 21:30:32 OK 20251218171726_add_pins.sql (7.08ms)14582026/09/21 21:30:32 OK 20260628120000_add_object_size_and_stats.sql (14.6ms)14592026/09/21 21:30:32 OK 20260905000000_add_claims.sql (13.54ms)14602026/09/21 21:30:32 OK 20260920000000_drop_claims.sql (11.91ms)14612026/09/21 21:30:32 goose: successfully migrated database to version: 2026092000000014622026/09/21 21:30:32 OK 1_commit_pending_closure.sql (1.05ms)14632026/09/21 21:30:32 OK 2_object_stats_trigger.sql (223.83µs)14642026/09/21 21:30:32 goose: up to current file version: 21465--- PASS: TestService_ReadAuthMiddleware (0.89s)1466=== CONT TestCompleteMultipartUnregistered14672026-09-21 21:30:32.248 UTC [38937] ERROR: relation "goose_db_version" does not exist at character 3614682026-09-21 21:30:32.248 UTC [38937] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1469=== NAME TestClientCADerivations1470 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-38627-3659511840/TestClientCADerivations1854891221/001/store/f9nb9j51fgq8jjj4vc05a249dggxdv0w-ca-test1471 client_ca_test.go:139: Found 1 dependencies (including self)14722026/09/21 21:30:32 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01473=== NAME TestPinProtectsFromGC1474 client_integration_test.go:794: Pin successfully protected closure from garbage collection14752026/09/21 21:30:32 OK 20241026095416_initial_model.sql (23.84ms)14762026/09/21 21:30:32 OK 20251210153512_drop_unused_gin_index.sql (7.45ms)14772026/09/21 21:30:32 OK 20251218171726_add_pins.sql (5.25ms)1478--- PASS: TestPinProtectsFromGC (3.99s)1479=== CONT TestService_verifyS3Integrity14802026/09/21 21:30:32 OK 20260628120000_add_object_size_and_stats.sql (16.36ms)14812026/09/21 21:30:32 OK 20260905000000_add_claims.sql (3.35ms)14822026/09/21 21:30:32 OK 20260920000000_drop_claims.sql (8.27ms)14832026/09/21 21:30:32 goose: successfully migrated database to version: 2026092000000014842026/09/21 21:30:32 OK 1_commit_pending_closure.sql (841.88µs)14852026/09/21 21:30:32 OK 2_object_stats_trigger.sql (226.67µs)14862026/09/21 21:30:32 goose: up to current file version: 214872026/09/21 21:30:32 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14882026-09-21 21:30:32.399 UTC [38949] ERROR: relation "goose_db_version" does not exist at character 3614892026-09-21 21:30:32.399 UTC [38949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14902026/09/21 21:30:32 INFO Received uploads request method=POST path=/api/pending_closures1491--- PASS: TestService_ReadScope_PublicByDefault (1.12s)1492=== CONT TestGCTaskStore_DeduplicateSameParams1493--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1494=== CONT TestGCTaskStore_StartNew1495--- PASS: TestGCTaskStore_StartNew (0.00s)1496=== CONT TestReadProxyHead14972026/09/21 21:30:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14982026/09/21 21:30:32 INFO Uploading f9nb9j51fgq8jjj4vc05a249dggxdv0w-ca-test (144B)14992026/09/21 21:30:32 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15002026/09/21 21:30:32 WARN Failed to register uploaded object key=log/mxg16s5yax64gyc69h57sd86jd3brmib-ca-test.drv error="server returned 404: 404 page not found\n"15012026/09/21 21:30:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15022026/09/21 21:30:32 WARN Failed to register uploaded object key=f9nb9j51fgq8jjj4vc05a249dggxdv0w.ls error="server returned 404: 404 page not found\n"15032026/09/21 21:30:32 INFO Signed narinfos id=1 count=115042026/09/21 21:30:32 INFO Uploading 1 narinfos15052026/09/21 21:30:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15062026/09/21 21:30:32 WARN Failed to register uploaded object key=f9nb9j51fgq8jjj4vc05a249dggxdv0w.narinfo error="server returned 404: 404 page not found\n"15072026/09/21 21:30:32 INFO Completed upload id=115082026/09/21 21:30:32 INFO Upload complete. (123ms)1509=== NAME TestClientCADerivations1510 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-38627-3659511840/TestClientCADerivations1854891221/001/store/f9nb9j51fgq8jjj4vc05a249dggxdv0w-ca-test1511 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1512 Compression: zstd1513 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1514 NarSize: 1441515 References: 1516 Deriver: /nix/var/nix/builds/nix-38627-3659511840/TestClientCADerivations1854891221/001/store/mxg16s5yax64gyc69h57sd86jd3brmib-ca-test.drv1517 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1518 client_ca_test.go:185: Checking for realisation files in S3...1519 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1520 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15212026/09/21 21:30:32 OK 20241026095416_initial_model.sql (45.93ms)15222026/09/21 21:30:32 OK 20251210153512_drop_unused_gin_index.sql (5.61ms)15232026/09/21 21:30:32 OK 20251218171726_add_pins.sql (13.02ms)15242026/09/21 21:30:32 OK 20260628120000_add_object_size_and_stats.sql (14.09ms)15252026/09/21 21:30:32 OK 20260905000000_add_claims.sql (23.57ms)15262026/09/21 21:30:32 OK 20260920000000_drop_claims.sql (6.76ms)15272026/09/21 21:30:32 goose: successfully migrated database to version: 2026092000000015282026/09/21 21:30:32 OK 1_commit_pending_closure.sql (976.79µs)15292026/09/21 21:30:32 OK 2_object_stats_trigger.sql (231.5µs)15302026/09/21 21:30:32 goose: up to current file version: 21531=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1532=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1533=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1534=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1535=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1536=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1537=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1538=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1539=== CONT TestReadProxyConditionalGet1540=== NAME TestClientCADerivations1541 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket31?endpoint=http://localhost:52072®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-38627-3659511840/TestClientCADerivations1854891221/001/store'1542 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11543--- PASS: TestClientCADerivations (1.62s)1544=== CONT TestCompleteMultipartUpload_ErrorButObjectExists15452026-09-21 21:30:32.737 UTC [38959] ERROR: relation "goose_db_version" does not exist at character 3615462026-09-21 21:30:32.737 UTC [38959] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15472026/09/21 21:30:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15482026/09/21 21:30:32 WARN mTLS auth: bound subjects configured but subject DN unavailable15492026/09/21 21:30:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1550--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.12s)1551=== CONT TestCompletedNarNotReofferedAcrossClosures15522026/09/21 21:30:32 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01553=== NAME TestClientIntegration1554 client_integration_test.go:323: Objects in database after GC:1555 client_integration_test.go:323: Successfully deleted all objects with GC --force1556=== CONT TestNARDeduplicationMetadataUploadBug1557--- PASS: TestClientIntegration (3.74s)15582026/09/21 21:30:32 OK 20241026095416_initial_model.sql (173.72ms)15592026/09/21 21:30:32 OK 20251210153512_drop_unused_gin_index.sql (8.31ms)15602026/09/21 21:30:32 INFO Received uploads request method=POST path=/api/pending_closures15612026/09/21 21:30:32 INFO Received uploads request method=POST path=/api/pending_closures15622026/09/21 21:30:32 INFO Received uploads request method=POST path=/api/pending_closures15632026/09/21 21:30:32 OK 20251218171726_add_pins.sql (20.02ms)15642026/09/21 21:30:33 OK 20260628120000_add_object_size_and_stats.sql (44.9ms)15652026/09/21 21:30:33 OK 20260905000000_add_claims.sql (29.82ms)15662026/09/21 21:30:33 OK 20260920000000_drop_claims.sql (4.04ms)15672026/09/21 21:30:33 goose: successfully migrated database to version: 2026092000000015682026/09/21 21:30:33 OK 1_commit_pending_closure.sql (4.37ms)15692026/09/21 21:30:33 OK 2_object_stats_trigger.sql (1.58ms)15702026/09/21 21:30:33 goose: up to current file version: 215712026-09-21 21:30:33.199 UTC [38964] ERROR: relation "goose_db_version" does not exist at character 3615722026-09-21 21:30:33.199 UTC [38964] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15732026/09/21 21:30:33 INFO Received uploads request method=POST path=/api/pending_closures1574--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.33s)1575=== CONT TestServerTLSConfig1576=== RUN TestServerTLSConfig/no_client_CA1577=== PAUSE TestServerTLSConfig/no_client_CA1578=== RUN TestServerTLSConfig/missing_CA_file1579=== PAUSE TestServerTLSConfig/missing_CA_file1580=== RUN TestServerTLSConfig/not_a_PEM_file1581=== PAUSE TestServerTLSConfig/not_a_PEM_file1582=== CONT TestService_NativeMTLS15832026-09-21 21:30:33.434 UTC [38965] ERROR: relation "goose_db_version" does not exist at character 3615842026-09-21 21:30:33.434 UTC [38965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15852026/09/21 21:30:33 OK 20241026095416_initial_model.sql (194ms)15862026/09/21 21:30:33 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)15872026/09/21 21:30:33 OK 20251218171726_add_pins.sql (39.98ms)15882026/09/21 21:30:33 OK 20260628120000_add_object_size_and_stats.sql (36.28ms)15892026/09/21 21:30:33 OK 20260905000000_add_claims.sql (23.8ms)15902026/09/21 21:30:33 OK 20260920000000_drop_claims.sql (12.65ms)15912026/09/21 21:30:33 goose: successfully migrated database to version: 2026092000000015922026/09/21 21:30:33 OK 1_commit_pending_closure.sql (3.47ms)15932026/09/21 21:30:33 OK 2_object_stats_trigger.sql (495.83µs)15942026/09/21 21:30:33 goose: up to current file version: 215952026/09/21 21:30:33 OK 20241026095416_initial_model.sql (158.28ms)15962026/09/21 21:30:33 OK 20251210153512_drop_unused_gin_index.sql (13.17ms)15972026/09/21 21:30:33 OK 20251218171726_add_pins.sql (25.06ms)15982026/09/21 21:30:33 OK 20260628120000_add_object_size_and_stats.sql (35.74ms)15992026-09-21 21:30:33.744 UTC [38968] ERROR: relation "goose_db_version" does not exist at character 3616002026-09-21 21:30:33.744 UTC [38968] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16012026/09/21 21:30:33 OK 20260905000000_add_claims.sql (62.34ms)16022026/09/21 21:30:33 OK 20260920000000_drop_claims.sql (67.9ms)16032026/09/21 21:30:33 goose: successfully migrated database to version: 2026092000000016042026/09/21 21:30:33 OK 1_commit_pending_closure.sql (4.78ms)16052026/09/21 21:30:33 OK 2_object_stats_trigger.sql (1.25ms)16062026/09/21 21:30:33 goose: up to current file version: 216072026/09/21 21:30:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16082026/09/21 21:30:33 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1609--- PASS: TestCompleteMultipartUnregistered (1.68s)1610=== CONT TestMetricsInventory16112026/09/21 21:30:34 OK 20241026095416_initial_model.sql (206.75ms)16122026/09/21 21:30:34 OK 20251210153512_drop_unused_gin_index.sql (12.7ms)16132026/09/21 21:30:34 OK 20251218171726_add_pins.sql (29.97ms)16142026/09/21 21:30:34 OK 20260628120000_add_object_size_and_stats.sql (55.06ms)16152026/09/21 21:30:34 OK 20260905000000_add_claims.sql (74.2ms)16162026/09/21 21:30:34 OK 20260920000000_drop_claims.sql (38.44ms)16172026/09/21 21:30:34 goose: successfully migrated database to version: 2026092000000016182026/09/21 21:30:34 OK 1_commit_pending_closure.sql (3.62ms)16192026/09/21 21:30:34 OK 2_object_stats_trigger.sql (781.38µs)16202026/09/21 21:30:34 goose: up to current file version: 216212026/09/21 21:30:34 INFO Received uploads request method=POST path=/api/pending_closures16222026/09/21 21:30:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16232026/09/21 21:30:34 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZWM2MmQ5MWMtNzQwMi00ZGY1LWJmZjctYzhhOWZiMjMzZTRjLjdkYTI4OWRhLTBlNWYtNDlkMi04MjE4LTkwZTU2NTFmYzliOXgxNzkwMDI2MjMzMDAxNjU5MDAw parts=1016242026/09/21 21:30:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16252026/09/21 21:30:34 INFO Completed upload id=116262026/09/21 21:30:34 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016272026/09/21 21:30:34 INFO Received uploads request method=POST path=/api/pending_closures16282026/09/21 21:30:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures16292026/09/21 21:30:34 INFO Aborted multipart uploads count=016302026/09/21 21:30:34 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=01631--- PASS: TestReadProxyHead (2.26s)1632=== CONT TestUploadHandlersRejectOversizedBody16332026-09-21 21:30:34.686 UTC [38971] ERROR: relation "goose_db_version" does not exist at character 3616342026-09-21 21:30:34.686 UTC [38971] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16352026/09/21 21:30:34 INFO Vacuumed table table=pending_closures16362026/09/21 21:30:34 INFO Vacuumed table table=pending_objects16372026/09/21 21:30:34 INFO Vacuumed table table=multipart_uploads16382026-09-21 21:30:34.704 UTC [38973] ERROR: relation "goose_db_version" does not exist at character 3616392026-09-21 21:30:34.704 UTC [38973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16402026-09-21 21:30:34.710 UTC [38974] ERROR: relation "goose_db_version" does not exist at character 3616412026-09-21 21:30:34.710 UTC [38974] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16422026-09-21 21:30:34.712 UTC [38975] ERROR: relation "goose_db_version" does not exist at character 3616432026-09-21 21:30:34.712 UTC [38975] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1644=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1645=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1646=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1647=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1648=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1649=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1650=== CONT TestService_cleanupPendingClosuresHandler16512026/09/21 21:30:34 INFO Vacuumed table table=closures16522026/09/21 21:30:34 WARN Rate limiter enabled after throttle name=s3-test rate=516532026/09/21 21:30:34 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1654=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1655 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101656 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001657--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.28s)1658=== CONT TestUploadHandlersRejectInvalidKeys1659=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1660=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1661=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1662=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1663=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1664=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1665=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1666=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1667=== CONT TestIsValidUploadKey1668=== RUN TestIsValidUploadKey/narinfo1669=== PAUSE TestIsValidUploadKey/narinfo1670=== RUN TestIsValidUploadKey/nar_zst1671=== PAUSE TestIsValidUploadKey/nar_zst1672=== RUN TestIsValidUploadKey/nar_xz1673=== PAUSE TestIsValidUploadKey/nar_xz1674=== RUN TestIsValidUploadKey/nar_plain1675=== PAUSE TestIsValidUploadKey/nar_plain1676=== RUN TestIsValidUploadKey/listing1677=== PAUSE TestIsValidUploadKey/listing1678=== RUN TestIsValidUploadKey/build_log1679=== PAUSE TestIsValidUploadKey/build_log1680=== RUN TestIsValidUploadKey/build_log_home-manager_file1681=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1682=== RUN TestIsValidUploadKey/build_log_plus_in_name1683=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1684=== RUN TestIsValidUploadKey/build_log_question_mark1685=== PAUSE TestIsValidUploadKey/build_log_question_mark1686=== RUN TestIsValidUploadKey/build_log_equals1687=== PAUSE TestIsValidUploadKey/build_log_equals1688=== RUN TestIsValidUploadKey/realisation1689=== PAUSE TestIsValidUploadKey/realisation1690=== RUN TestIsValidUploadKey/realisation_plus_in_output1691=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1692=== RUN TestIsValidUploadKey/nix-cache-info1693=== PAUSE TestIsValidUploadKey/nix-cache-info1694=== RUN TestIsValidUploadKey/index.html1695=== PAUSE TestIsValidUploadKey/index.html1696=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1697=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1698=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1699=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1700=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1701=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1702=== RUN TestIsValidUploadKey/traversal1703=== PAUSE TestIsValidUploadKey/traversal1704=== RUN TestIsValidUploadKey/traversal_nar1705=== PAUSE TestIsValidUploadKey/traversal_nar1706=== RUN TestIsValidUploadKey/absolute1707=== PAUSE TestIsValidUploadKey/absolute1708=== RUN TestIsValidUploadKey/empty_key1709=== PAUSE TestIsValidUploadKey/empty_key1710=== RUN TestIsValidUploadKey/unknown_type1711=== PAUSE TestIsValidUploadKey/unknown_type1712=== CONT TestRedundantMultipartUpload17132026/09/21 21:30:34 INFO Vacuumed table table=objects17142026/09/21 21:30:34 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001715--- PASS: TestService_createPendingClosureHandler (3.00s)1716=== CONT TestReadRedirectUsesPublicS3URL17172026/09/21 21:30:34 OK 20241026095416_initial_model.sql (101.23ms)17182026/09/21 21:30:34 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)17192026/09/21 21:30:34 OK 20251218171726_add_pins.sql (3.79ms)17202026/09/21 21:30:34 OK 20241026095416_initial_model.sql (46.93ms)17212026/09/21 21:30:34 OK 20241026095416_initial_model.sql (86.73ms)17222026/09/21 21:30:34 OK 20241026095416_initial_model.sql (47.2ms)17232026/09/21 21:30:34 OK 20251210153512_drop_unused_gin_index.sql (830.38µs)17242026/09/21 21:30:34 OK 20251210153512_drop_unused_gin_index.sql (995.88µs)17252026/09/21 21:30:34 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)17262026/09/21 21:30:34 OK 20260628120000_add_object_size_and_stats.sql (12.11ms)17272026/09/21 21:30:34 OK 20251218171726_add_pins.sql (9.89ms)17282026/09/21 21:30:34 OK 20251218171726_add_pins.sql (16.94ms)17292026/09/21 21:30:34 OK 20251218171726_add_pins.sql (15.2ms)17302026/09/21 21:30:34 OK 20260628120000_add_object_size_and_stats.sql (27.3ms)17312026/09/21 21:30:34 OK 20260628120000_add_object_size_and_stats.sql (30.21ms)17322026/09/21 21:30:34 OK 20260905000000_add_claims.sql (43.64ms)17332026/09/21 21:30:34 OK 20260628120000_add_object_size_and_stats.sql (35.94ms)17342026/09/21 21:30:34 OK 20260920000000_drop_claims.sql (36.5ms)17352026/09/21 21:30:34 goose: successfully migrated database to version: 2026092000000017362026/09/21 21:30:34 OK 1_commit_pending_closure.sql (1.99ms)17372026/09/21 21:30:34 OK 2_object_stats_trigger.sql (390.25µs)17382026/09/21 21:30:34 goose: up to current file version: 217392026/09/21 21:30:34 OK 20260905000000_add_claims.sql (61.66ms)17402026/09/21 21:30:34 OK 20260905000000_add_claims.sql (52.25ms)17412026/09/21 21:30:34 OK 20260905000000_add_claims.sql (46.9ms)17422026/09/21 21:30:34 OK 20260920000000_drop_claims.sql (22.35ms)17432026/09/21 21:30:34 goose: successfully migrated database to version: 2026092000000017442026/09/21 21:30:34 OK 1_commit_pending_closure.sql (1.66ms)17452026/09/21 21:30:34 OK 2_object_stats_trigger.sql (336.42µs)17462026/09/21 21:30:34 goose: up to current file version: 217472026/09/21 21:30:34 OK 20260920000000_drop_claims.sql (45.75ms)17482026/09/21 21:30:34 goose: successfully migrated database to version: 2026092000000017492026/09/21 21:30:34 OK 1_commit_pending_closure.sql (1.37ms)17502026/09/21 21:30:34 OK 2_object_stats_trigger.sql (347.63µs)17512026/09/21 21:30:34 goose: up to current file version: 217522026/09/21 21:30:34 OK 20260920000000_drop_claims.sql (52.35ms)17532026/09/21 21:30:34 goose: successfully migrated database to version: 2026092000000017542026/09/21 21:30:34 OK 1_commit_pending_closure.sql (1.59ms)17552026/09/21 21:30:34 OK 2_object_stats_trigger.sql (352.92µs)17562026/09/21 21:30:34 goose: up to current file version: 217572026/09/21 21:30:35 INFO Received uploads request method=POST path=/api/pending_closures17582026/09/21 21:30:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17592026/09/21 21:30:35 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZWM2MmQ5MWMtNzQwMi00ZGY1LWJmZjctYzhhOWZiMjMzZTRjLmI5YjE5NDA3LTc1MzQtNGZhZi1iNDdhLTA1YzM0Zjk2ZmQyY3gxNzkwMDI2MjM1MjQ1Nzc1MDAw17602026/09/21 21:30:35 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZWM2MmQ5MWMtNzQwMi00ZGY1LWJmZjctYzhhOWZiMjMzZTRjLmI5YjE5NDA3LTc1MzQtNGZhZi1iNDdhLTA1YzM0Zjk2ZmQyY3gxNzkwMDI2MjM1MjQ1Nzc1MDAw parts=11761--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.01s)1762=== CONT TestService_AuthMiddleware_MTLSProxyHeader17632026-09-21 21:30:35.658 UTC [38983] ERROR: relation "goose_db_version" does not exist at character 3617642026-09-21 21:30:35.658 UTC [38983] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17652026/09/21 21:30:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17662026/09/21 21:30:35 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZWM2MmQ5MWMtNzQwMi00ZGY1LWJmZjctYzhhOWZiMjMzZTRjLmIxNzc4Zjc3LWE3MzEtNGZlNC05ZDExLWUwMDhmZjI2ZDBkZXgxNzkwMDI2MjM0MzA0MzA2MDAw parts=1017672026/09/21 21:30:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17682026/09/21 21:30:35 INFO Completed upload id=117692026/09/21 21:30:35 INFO Received uploads request method=POST path=/api/pending_closures17702026/09/21 21:30:35 INFO Received uploads request method=POST path=/api/pending_closures17712026/09/21 21:30:35 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo17722026/09/21 21:30:35 WARN Found objects in DB but missing from S3, will re-upload count=11773--- PASS: TestService_verifyS3Integrity (3.52s)1774=== CONT TestCacheConfigHandlerMaxNarSize1775--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1776=== CONT TestReadProxyInvalidPath1777--- PASS: TestReadProxyConditionalGet (3.29s)1778=== CONT TestCreatePendingClosureRejectsOversizedNAR17792026/09/21 21:30:35 INFO Received uploads request method=POST path=/api/pending_closures1780--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1781=== CONT TestGenerateLandingPage1782--- PASS: TestGenerateLandingPage (0.00s)1783=== CONT TestService_readinessHandler1784=== NAME TestNARDeduplicationMetadataUploadBug1785 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-38627-3659511840/TestNARDeduplicationMetadataUploadBug3793518922/001/store/mddyz7igscvbb19l5z9lxk17vm55iki9-file1.txt17862026/09/21 21:30:35 OK 20241026095416_initial_model.sql (156.87ms)17872026/09/21 21:30:35 OK 20251210153512_drop_unused_gin_index.sql (2.66ms)17882026/09/21 21:30:35 OK 20251218171726_add_pins.sql (29.38ms)17892026/09/21 21:30:35 OK 20260628120000_add_object_size_and_stats.sql (27.5ms)17902026/09/21 21:30:35 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17912026-09-21 21:30:35.960 UTC [38995] ERROR: relation "goose_db_version" does not exist at character 3617922026-09-21 21:30:35.960 UTC [38995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17932026/09/21 21:30:35 OK 20260905000000_add_claims.sql (39.1ms)17942026/09/21 21:30:35 OK 20260920000000_drop_claims.sql (38.15ms)17952026/09/21 21:30:35 goose: successfully migrated database to version: 2026092000000017962026/09/21 21:30:36 OK 1_commit_pending_closure.sql (1.36ms)17972026/09/21 21:30:36 OK 2_object_stats_trigger.sql (255.25µs)17982026/09/21 21:30:36 goose: up to current file version: 217992026/09/21 21:30:36 INFO Received uploads request method=POST path=/api/pending_closures18002026/09/21 21:30:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18012026/09/21 21:30:36 INFO Uploading mddyz7igscvbb19l5z9lxk17vm55iki9-file1.txt (160B)18022026/09/21 21:30:36 INFO Received uploads request method=POST path=/api/pending_closures18032026/09/21 21:30:36 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18042026/09/21 21:30:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18052026/09/21 21:30:36 INFO Signed narinfos id=1 count=118062026/09/21 21:30:36 INFO Uploading 1 narinfos18072026/09/21 21:30:36 WARN Failed to register uploaded object key=mddyz7igscvbb19l5z9lxk17vm55iki9.ls error="server returned 404: 404 page not found\n"18082026/09/21 21:30:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18092026/09/21 21:30:36 WARN Failed to register uploaded object key=mddyz7igscvbb19l5z9lxk17vm55iki9.narinfo error="server returned 404: 404 page not found\n"18102026/09/21 21:30:36 INFO Completed upload id=118112026/09/21 21:30:36 INFO Upload complete. (256ms)1812 metadata_upload_test.go:54: Retrieved narinfo from S3:1813 StorePath: /nix/var/nix/builds/nix-38627-3659511840/TestNARDeduplicationMetadataUploadBug3793518922/001/store/mddyz7igscvbb19l5z9lxk17vm55iki9-file1.txt1814 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1815 Compression: zstd1816 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1817 NarSize: 1601818 References: 1819 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1820 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1821 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1822 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}18232026/09/21 21:30:36 OK 20241026095416_initial_model.sql (176.78ms)18242026/09/21 21:30:36 OK 20251210153512_drop_unused_gin_index.sql (24.67ms)18252026/09/21 21:30:36 OK 20251218171726_add_pins.sql (32.32ms)1826 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-38627-3659511840/TestNARDeduplicationMetadataUploadBug3793518922/001/store/n4a9yksw7lvab9lwdq0r2k95z0g2bhl8-file2.txt18272026/09/21 21:30:36 OK 20260628120000_add_object_size_and_stats.sql (25.5ms)18282026/09/21 21:30:36 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18292026/09/21 21:30:36 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1830--- PASS: TestService_NativeMTLS (2.90s)1831=== CONT TestReadProxy40418322026/09/21 21:30:36 OK 20260905000000_add_claims.sql (55.51ms)18332026/09/21 21:30:36 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18342026/09/21 21:30:36 OK 20260920000000_drop_claims.sql (28.07ms)18352026/09/21 21:30:36 goose: successfully migrated database to version: 2026092000000018362026/09/21 21:30:36 OK 1_commit_pending_closure.sql (993.96µs)18372026/09/21 21:30:36 OK 2_object_stats_trigger.sql (248.75µs)18382026/09/21 21:30:36 goose: up to current file version: 218392026/09/21 21:30:36 INFO Received uploads request method=POST path=/api/pending_closures18402026/09/21 21:30:36 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18412026/09/21 21:30:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18422026/09/21 21:30:36 WARN Failed to register uploaded object key=n4a9yksw7lvab9lwdq0r2k95z0g2bhl8.ls error="server returned 404: 404 page not found\n"18432026/09/21 21:30:36 INFO Signed narinfos id=2 count=118442026/09/21 21:30:36 INFO Uploading 1 narinfos18452026/09/21 21:30:36 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18462026/09/21 21:30:36 WARN Failed to register uploaded object key=n4a9yksw7lvab9lwdq0r2k95z0g2bhl8.narinfo error="server returned 404: 404 page not found\n"18472026/09/21 21:30:36 INFO Completed upload id=218482026/09/21 21:30:36 INFO Upload complete. (137ms)1849=== NAME TestNARDeduplicationMetadataUploadBug1850 metadata_upload_test.go:76: Retrieved narinfo from S3:1851 StorePath: /nix/var/nix/builds/nix-38627-3659511840/TestNARDeduplicationMetadataUploadBug3793518922/001/store/n4a9yksw7lvab9lwdq0r2k95z0g2bhl8-file2.txt1852 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1853 Compression: zstd1854 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1855 NarSize: 1601856 References: 1857 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1858 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1859 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1860 {"version":1,"root":{"type":"regular","size":44}}1861=== CONT TestReadProxyNarStreaming1862--- PASS: TestNARDeduplicationMetadataUploadBug (3.66s)1863--- PASS: TestMetricsInventory (2.80s)1864=== CONT TestProxyWriteTimeout/narinfo1865=== CONT TestProxyWriteTimeout/unknown_size1866=== CONT TestProxyWriteTimeout/1_GiB_nar1867=== CONT TestProxyWriteTimeout/10_GiB_nar1868--- PASS: TestProxyWriteTimeout (0.00s)1869 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1870 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1871 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1872 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1873=== CONT TestParseSingleRange/none1874=== CONT TestParseSingleRange/open-ended1875=== CONT TestParseSingleRange/start_far_past_EOF1876=== CONT TestParseSingleRange/start_past_EOF1877=== CONT TestParseSingleRange/single_byte1878=== CONT TestParseSingleRange/suffix_exceeds_size1879=== CONT TestParseSingleRange/suffix1880=== CONT TestParseSingleRange/end_clamped_to_size1881=== CONT TestParseSingleRange/malformed_both_empty1882=== CONT TestParseSingleRange/closed1883=== CONT TestParseSingleRange/malformed_end_before_start1884=== CONT TestParseSingleRange/multi-range_ignored1885=== CONT TestParseSingleRange/malformed_no_dash1886=== CONT TestParseSingleRange/unknown_unit1887--- PASS: TestParseSingleRange (0.00s)1888 --- PASS: TestParseSingleRange/none (0.00s)1889 --- PASS: TestParseSingleRange/open-ended (0.00s)1890 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1891 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1892 --- PASS: TestParseSingleRange/single_byte (0.00s)1893 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1894 --- PASS: TestParseSingleRange/suffix (0.00s)1895 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1896 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1897 --- PASS: TestParseSingleRange/closed (0.00s)1898 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1899 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1900 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1901 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1902=== CONT TestIsValidCachePath/narinfo1903=== CONT TestIsValidCachePath/index.html1904=== CONT TestIsValidCachePath/nar_uncompressed1905=== CONT TestIsValidCachePath/nix-cache-info1906=== CONT TestIsValidCachePath/realisation1907=== CONT TestIsValidCachePath/log1908=== CONT TestIsValidCachePath/ls1909=== CONT TestIsValidCachePath/nar_xz1910=== CONT TestIsValidCachePath/nar_bz21911=== CONT TestIsValidCachePath/nar_zst1912=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1913=== CONT TestIsValidCachePath/random_path1914=== CONT TestIsValidCachePath/short_hash1915=== CONT TestIsValidCachePath/wrong_extension1916=== CONT TestIsValidCachePath/leading_slash1917=== CONT TestIsValidCachePath/empty1918=== CONT TestIsValidCachePath/invalid_char_e1919=== CONT TestIsValidCachePath/invalid_char_u1920=== CONT TestIsValidCachePath/traversal_in_middle1921=== CONT TestIsValidCachePath/traversal_parent1922--- PASS: TestIsValidCachePath (0.00s)1923 --- PASS: TestIsValidCachePath/narinfo (0.00s)1924 --- PASS: TestIsValidCachePath/index.html (0.00s)1925 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1926 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1927 --- PASS: TestIsValidCachePath/realisation (0.00s)1928 --- PASS: TestIsValidCachePath/log (0.00s)1929 --- PASS: TestIsValidCachePath/ls (0.00s)1930 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1931 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1932 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1933 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1934 --- PASS: TestIsValidCachePath/random_path (0.00s)1935 --- PASS: TestIsValidCachePath/short_hash (0.00s)1936 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1937 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1938 --- PASS: TestIsValidCachePath/empty (0.00s)1939 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1940 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1941 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1942 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1943=== CONT TestClientErrorHandling/InvalidStorePath19442026-09-21 21:30:36.820 UTC [39010] ERROR: relation "goose_db_version" does not exist at character 3619452026-09-21 21:30:36.820 UTC [39010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19462026-09-21 21:30:36.834 UTC [39013] ERROR: relation "goose_db_version" does not exist at character 3619472026-09-21 21:30:36.834 UTC [39013] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19482026-09-21 21:30:36.936 UTC [39014] ERROR: relation "goose_db_version" does not exist at character 3619492026-09-21 21:30:36.936 UTC [39014] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19502026/09/21 21:30:36 OK 20241026095416_initial_model.sql (94.95ms)19512026/09/21 21:30:36 OK 20251210153512_drop_unused_gin_index.sql (6.12ms)19522026/09/21 21:30:36 OK 20241026095416_initial_model.sql (91.8ms)19532026/09/21 21:30:37 OK 20251210153512_drop_unused_gin_index.sql (6.41ms)19542026/09/21 21:30:37 OK 20251218171726_add_pins.sql (8.53ms)19552026/09/21 21:30:37 OK 20251218171726_add_pins.sql (10.64ms)19562026/09/21 21:30:37 OK 20260628120000_add_object_size_and_stats.sql (11.82ms)19572026/09/21 21:30:37 OK 20260905000000_add_claims.sql (5.75ms)19582026/09/21 21:30:37 OK 20260628120000_add_object_size_and_stats.sql (10.15ms)19592026/09/21 21:30:37 OK 20260920000000_drop_claims.sql (2.34ms)19602026/09/21 21:30:37 goose: successfully migrated database to version: 2026092000000019612026/09/21 21:30:37 OK 20241026095416_initial_model.sql (42.39ms)19622026/09/21 21:30:37 OK 20251210153512_drop_unused_gin_index.sql (755.04µs)19632026/09/21 21:30:37 OK 1_commit_pending_closure.sql (2.28ms)19642026/09/21 21:30:37 OK 20260905000000_add_claims.sql (3.34ms)19652026/09/21 21:30:37 OK 2_object_stats_trigger.sql (738.38µs)19662026/09/21 21:30:37 goose: up to current file version: 219672026/09/21 21:30:37 OK 20251218171726_add_pins.sql (2.17ms)19682026/09/21 21:30:37 OK 20260920000000_drop_claims.sql (1.74ms)19692026/09/21 21:30:37 goose: successfully migrated database to version: 2026092000000019702026/09/21 21:30:37 OK 1_commit_pending_closure.sql (1.78ms)19712026/09/21 21:30:37 OK 2_object_stats_trigger.sql (521.96µs)19722026/09/21 21:30:37 goose: up to current file version: 219732026/09/21 21:30:37 OK 20260628120000_add_object_size_and_stats.sql (17.16ms)19742026-09-21 21:30:37.084 UTC [39015] ERROR: relation "goose_db_version" does not exist at character 3619752026-09-21 21:30:37.084 UTC [39015] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19762026/09/21 21:30:37 OK 20260905000000_add_claims.sql (49.09ms)19772026/09/21 21:30:37 OK 20260920000000_drop_claims.sql (27.08ms)19782026/09/21 21:30:37 goose: successfully migrated database to version: 2026092000000019792026/09/21 21:30:37 OK 1_commit_pending_closure.sql (2.78ms)19802026/09/21 21:30:37 OK 2_object_stats_trigger.sql (602.75µs)19812026/09/21 21:30:37 goose: up to current file version: 219822026/09/21 21:30:37 OK 20241026095416_initial_model.sql (114.79ms)19832026/09/21 21:30:37 INFO Received uploads request method=POST path=/api/pending_closures19842026/09/21 21:30:37 OK 20251210153512_drop_unused_gin_index.sql (5.03ms)19852026/09/21 21:30:37 OK 20251218171726_add_pins.sql (14.4ms)19862026/09/21 21:30:37 OK 20260628120000_add_object_size_and_stats.sql (51.06ms)19872026/09/21 21:30:37 INFO Received uploads request method=POST path=/api/pending_closures19882026/09/21 21:30:37 OK 20260905000000_add_claims.sql (70.94ms)19892026/09/21 21:30:37 OK 20260920000000_drop_claims.sql (60.51ms)19902026/09/21 21:30:37 goose: successfully migrated database to version: 2026092000000019912026/09/21 21:30:37 OK 1_commit_pending_closure.sql (3.43ms)19922026/09/21 21:30:37 OK 2_object_stats_trigger.sql (713.71µs)19932026/09/21 21:30:37 goose: up to current file version: 219942026/09/21 21:30:37 INFO Received cleanup request method=DELETE path=/api/pending_closures19952026/09/21 21:30:37 INFO Aborted multipart uploads count=019962026/09/21 21:30:37 INFO Received uploads request method=POST path=/api/pending_closures19972026/09/21 21:30:37 INFO Received cleanup request method=DELETE path=/api/pending_closures19982026/09/21 21:30:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19992026/09/21 21:30:37 INFO Aborted multipart uploads count=120002026-09-21 21:30:37.702 UTC [39016] ERROR: relation "goose_db_version" does not exist at character 3620012026-09-21 21:30:37.702 UTC [39016] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20022026/09/21 21:30:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20032026-09-21 21:30:37.724 UTC [39013] ERROR: Closure does not exist: id=120042026-09-21 21:30:37.724 UTC [39013] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE20052026-09-21 21:30:37.724 UTC [39013] STATEMENT: -- name: CommitPendingClosure :exec2006 SELECT commit_pending_closure($1::bigint)2007 2008--- PASS: TestService_cleanupPendingClosuresHandler (3.01s)2009=== CONT TestClientErrorHandling/ServerNotAvailable20102026-09-21 21:30:37.765 UTC [39017] ERROR: relation "goose_db_version" does not exist at character 3620112026-09-21 21:30:37.765 UTC [39017] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20122026/09/21 21:30:37 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZWM2MmQ5MWMtNzQwMi00ZGY1LWJmZjctYzhhOWZiMjMzZTRjLmE4YWQ2MjM0LTY0YzctNDU0NS1iMTgwLWU3YzQ3YmUyMjFmYXgxNzkwMDI2MjM2MDc3NDE2MDAw parts=1220132026/09/21 21:30:37 INFO Received uploads request method=POST path=/api/pending_closures2014--- PASS: TestCompletedNarNotReofferedAcrossClosures (5.04s)2015=== CONT TestClientErrorHandling/InvalidAuthToken2016--- PASS: TestReadRedirectUsesPublicS3URL (3.13s)2017=== CONT TestResolveDBConnectionString/flag_wins2018=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2019=== CONT TestResolveDBConnectionString/nothing_configured2020=== CONT TestResolveDBConnectionString/missing_file_is_an_error2021=== CONT TestResolveDBConnectionString/file_when_flag_empty2022=== CONT TestCacheConfigHandler/full_config,_no_issuer2023=== CONT TestCacheConfigHandler/no_signing_keys2024=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2025=== CONT TestCacheConfigHandler/no_cache_url_configured2026--- PASS: TestCacheConfigHandler (0.00s)2027 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2028 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2029 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2030 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2031=== CONT TestService_RequireScope_OIDC/builder_may_write2032=== CONT TestService_RequireScope_OIDC/static_token_may_admin2033=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2034=== CONT TestService_RequireScope_OIDC/writer_implies_read2035=== CONT TestService_RequireScope_OIDC/reader_may_read2036=== CONT TestService_RequireScope_OIDC/static_token_may_write2037=== CONT TestService_RequireScope_OIDC/ops_may_not_write2038=== CONT TestService_RequireScope_OIDC/reader_may_not_write2039=== CONT TestService_RequireScope_OIDC/ops_may_admin2040=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2041=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2042=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20432026/09/21 21:30:37 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]2044=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2045=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20462026/09/21 21:30:37 WARN Authentication failed token_preview=eyJhbGciOi..._S2h9-HdyA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2047=== CONT TestServerTLSConfig/no_client_CA2048=== CONT TestServerTLSConfig/not_a_PEM_file2049--- PASS: TestResolveDBConnectionString (0.01s)2050 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2051 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2052 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2053 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2054 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2055--- PASS: TestService_RequireScope_OIDC (1.07s)2056 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2057 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2058 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2059 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2060 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2061 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2062 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2063 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2064 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2065 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2066--- PASS: TestService_AuthMiddleware_OIDC (1.05s)2067 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2068 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2069 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2070 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2071=== CONT TestServerTLSConfig/missing_CA_file2072--- PASS: TestServerTLSConfig (0.00s)2073 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2074 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2075 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2076=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20772026/09/21 21:30:37 INFO Received uploads request method=POST path=/20782026/09/21 21:30:37 OK 20241026095416_initial_model.sql (143.04ms)20792026/09/21 21:30:37 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)20802026/09/21 21:30:37 OK 20241026095416_initial_model.sql (122.7ms)20812026/09/21 21:30:37 OK 20251218171726_add_pins.sql (5.69ms)20822026/09/21 21:30:37 OK 20251210153512_drop_unused_gin_index.sql (847µs)20832026/09/21 21:30:37 OK 20260628120000_add_object_size_and_stats.sql (12.03ms)20842026/09/21 21:30:37 OK 20251218171726_add_pins.sql (24.6ms)20852026/09/21 21:30:37 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/present20862026/09/21 21:30:38 OK 20260628120000_add_object_size_and_stats.sql (21.71ms)20872026/09/21 21:30:38 OK 20260905000000_add_claims.sql (50.33ms)20882026/09/21 21:30:38 OK 20260920000000_drop_claims.sql (20.67ms)20892026/09/21 21:30:38 goose: successfully migrated database to version: 2026092000000020902026/09/21 21:30:38 OK 20260905000000_add_claims.sql (37.39ms)20912026/09/21 21:30:38 OK 1_commit_pending_closure.sql (1.5ms)20922026/09/21 21:30:38 OK 2_object_stats_trigger.sql (274.75µs)20932026/09/21 21:30:38 goose: up to current file version: 220942026/09/21 21:30:38 OK 20260920000000_drop_claims.sql (7.45ms)20952026/09/21 21:30:38 goose: successfully migrated database to version: 2026092000000020962026/09/21 21:30:38 OK 1_commit_pending_closure.sql (1.24ms)20972026/09/21 21:30:38 OK 2_object_stats_trigger.sql (263.29µs)20982026/09/21 21:30:38 goose: up to current file version: 220992026/09/21 21:30:38 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.222263ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2100--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.57s)2101=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts21022026/09/21 21:30:38 INFO Received request for more parts method=POST path=/21032026-09-21 21:30:38.141 UTC [39024] ERROR: relation "goose_db_version" does not exist at character 3621042026-09-21 21:30:38.141 UTC [39024] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2105=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart21062026/09/21 21:30:38 INFO Received complete multipart upload request method=POST path=/2107=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info21082026/09/21 21:30:38 INFO Received uploads request method=POST path=/2109=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key21102026/09/21 21:30:38 INFO Received complete multipart upload request method=POST path=/2111=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key21122026/09/21 21:30:38 INFO Received request for more parts method=POST path=/2113=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal21142026/09/21 21:30:38 INFO Received uploads request method=POST path=/2115--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2116 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2117 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2118 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2119 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2120=== CONT TestIsValidUploadKey/narinfo2121=== CONT TestIsValidUploadKey/realisation_plus_in_output2122=== CONT TestIsValidUploadKey/unknown_type2123=== CONT TestIsValidUploadKey/empty_key2124=== CONT TestIsValidUploadKey/absolute2125=== CONT TestIsValidUploadKey/traversal_nar2126=== CONT TestIsValidUploadKey/traversal2127=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2128=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2129=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2130=== CONT TestIsValidUploadKey/index.html2131=== CONT TestIsValidUploadKey/nix-cache-info2132=== CONT TestIsValidUploadKey/build_log_home-manager_file2133=== CONT TestIsValidUploadKey/realisation2134=== CONT TestIsValidUploadKey/build_log_equals2135=== CONT TestIsValidUploadKey/build_log_question_mark2136=== CONT TestIsValidUploadKey/build_log_plus_in_name2137=== CONT TestIsValidUploadKey/nar_plain2138=== CONT TestIsValidUploadKey/build_log2139=== CONT TestIsValidUploadKey/listing2140=== CONT TestIsValidUploadKey/nar_xz2141=== CONT TestIsValidUploadKey/nar_zst2142--- PASS: TestIsValidUploadKey (0.00s)2143 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2144 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2145 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2146 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2147 --- PASS: TestIsValidUploadKey/absolute (0.00s)2148 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2149 --- PASS: TestIsValidUploadKey/traversal (0.00s)2150 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2151 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2152 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2153 --- PASS: TestIsValidUploadKey/index.html (0.00s)2154 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2155 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2156 --- PASS: TestIsValidUploadKey/realisation (0.00s)2157 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2158 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2159 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2160 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2161 --- PASS: TestIsValidUploadKey/build_log (0.00s)2162 --- PASS: TestIsValidUploadKey/listing (0.00s)2163 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2164 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2165--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)2166 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2167 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2168 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)21692026-09-21 21:30:38.223 UTC [39025] ERROR: relation "goose_db_version" does not exist at character 3621702026-09-21 21:30:38.223 UTC [39025] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21712026/09/21 21:30:38 OK 20241026095416_initial_model.sql (37.67ms)21722026/09/21 21:30:38 OK 20251210153512_drop_unused_gin_index.sql (8.16ms)21732026/09/21 21:30:38 OK 20251218171726_add_pins.sql (10.8ms)21742026-09-21 21:30:38.256 UTC [39026] ERROR: relation "goose_db_version" does not exist at character 3621752026-09-21 21:30:38.256 UTC [39026] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21762026/09/21 21:30:38 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.920213ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21772026/09/21 21:30:38 OK 20260628120000_add_object_size_and_stats.sql (30.62ms)21782026/09/21 21:30:38 OK 20260905000000_add_claims.sql (27.56ms)21792026/09/21 21:30:38 OK 20260920000000_drop_claims.sql (10.41ms)21802026/09/21 21:30:38 goose: successfully migrated database to version: 2026092000000021812026/09/21 21:30:38 OK 1_commit_pending_closure.sql (1.05ms)21822026/09/21 21:30:38 OK 2_object_stats_trigger.sql (276.13µs)21832026/09/21 21:30:38 goose: up to current file version: 221842026/09/21 21:30:38 OK 20241026095416_initial_model.sql (82.47ms)21852026/09/21 21:30:38 OK 20251210153512_drop_unused_gin_index.sql (13.05ms)21862026/09/21 21:30:38 WARN readiness check failed error="closed pool"2187--- PASS: TestService_readinessHandler (2.51s)21882026/09/21 21:30:38 OK 20251218171726_add_pins.sql (21ms)21892026/09/21 21:30:38 OK 20260628120000_add_object_size_and_stats.sql (18.21ms)21902026/09/21 21:30:38 OK 20241026095416_initial_model.sql (96.51ms)21912026/09/21 21:30:38 OK 20251210153512_drop_unused_gin_index.sql (13.08ms)21922026/09/21 21:30:38 OK 20251218171726_add_pins.sql (7.91ms)21932026/09/21 21:30:38 OK 20260905000000_add_claims.sql (28.69ms)21942026/09/21 21:30:38 OK 20260920000000_drop_claims.sql (1.37ms)21952026/09/21 21:30:38 goose: successfully migrated database to version: 2026092000000021962026/09/21 21:30:38 OK 20260628120000_add_object_size_and_stats.sql (2.75ms)21972026/09/21 21:30:38 OK 1_commit_pending_closure.sql (1.62ms)21982026/09/21 21:30:38 OK 2_object_stats_trigger.sql (329.96µs)21992026/09/21 21:30:38 goose: up to current file version: 222002026/09/21 21:30:38 OK 20260905000000_add_claims.sql (12.42ms)22012026/09/21 21:30:38 OK 20260920000000_drop_claims.sql (28.52ms)22022026/09/21 21:30:38 goose: successfully migrated database to version: 2026092000000022032026/09/21 21:30:38 OK 1_commit_pending_closure.sql (1.5ms)22042026/09/21 21:30:38 OK 2_object_stats_trigger.sql (325.08µs)22052026/09/21 21:30:38 goose: up to current file version: 22206--- PASS: TestReadProxyInvalidPath (2.72s)22072026/09/21 21:30:38 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=731.753893ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22082026/09/21 21:30:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22092026/09/21 21:30:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZWM2MmQ5MWMtNzQwMi00ZGY1LWJmZjctYzhhOWZiMjMzZTRjLjkxNWRmYmQxLThlYmUtNDFhZC1hNGQyLTI1ODc5ZTM2YzkyMngxNzkwMDI2MjM3MzAwMzMxMDAw parts=122210--- PASS: TestRedundantMultipartUpload (4.02s)2211--- PASS: TestReadProxy404 (2.46s)22122026-09-21 21:30:38.828 UTC [39027] ERROR: relation "goose_db_version" does not exist at character 3622132026-09-21 21:30:38.828 UTC [39027] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22142026/09/21 21:30:38 OK 20241026095416_initial_model.sql (72.25ms)22152026/09/21 21:30:38 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)22162026/09/21 21:30:38 OK 20251218171726_add_pins.sql (5.43ms)2217--- PASS: TestReadProxyNarStreaming (2.38s)22182026/09/21 21:30:38 OK 20260628120000_add_object_size_and_stats.sql (15.4ms)22192026/09/21 21:30:38 OK 20260905000000_add_claims.sql (12.77ms)22202026/09/21 21:30:38 OK 20260920000000_drop_claims.sql (13.6ms)22212026/09/21 21:30:38 goose: successfully migrated database to version: 2026092000000022222026/09/21 21:30:38 OK 1_commit_pending_closure.sql (4.45ms)22232026/09/21 21:30:38 OK 2_object_stats_trigger.sql (777.88µs)22242026/09/21 21:30:38 goose: up to current file version: 222252026/09/21 21:30:39 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22262026/09/21 21:30:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22272026/09/21 21:30:39 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22282026/09/21 21:30:39 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.716463931s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22292026/09/21 21:30:41 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-config22302026/09/21 21:30:41 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.240196ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22312026/09/21 21:30:41 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=375.749987ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/09/21 21:30:41 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=869.534579ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22332026/09/21 21:30:42 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.653698437s 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/21 21:30:44 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"22352026/09/21 21:30:44 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_closures22362026/09/21 21:30:44 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.983047ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/09/21 21:30:44 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=404.107855ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22382026/09/21 21:30:45 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=732.512197ms 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/21 21:30:45 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.625864299s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2240--- PASS: TestClientErrorHandling (0.00s)2241 --- PASS: TestClientErrorHandling/InvalidStorePath (2.37s)2242 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.46s)2243 --- PASS: TestClientErrorHandling/ServerNotAvailable (9.86s)2244PASS2245{"timestamp":"2026-09-21T21:30:47.584607Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52205","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1880,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}22462026-09-21 21:30:47.693 UTC [38665] LOG: received smart shutdown request22472026-09-21 21:30:47.694 UTC [38665] LOG: background worker "logical replication launcher" (PID 38676) exited with exit code 122482026-09-21 21:30:47.699 UTC [38670] LOG: shutting down22492026-09-21 21:30:47.699 UTC [38670] LOG: checkpoint starting: shutdown immediate22502026-09-21 21:30:48.781 UTC [38670] LOG: checkpoint complete: wrote 13040 buffers (79.6%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=0.756 s, sync=0.318 s, total=1.083 s; sync files=19072, longest=0.001 s, average=0.001 s; distance=264769 kB, estimate=264769 kB; lsn=0/11A1D5B8, redo lsn=0/11A1D5B822512026-09-21 21:30:48.785 UTC [38665] LOG: database system is shut down2252Running OIDC tests...2253=== RUN TestAudienceForIssuer2254=== PAUSE TestAudienceForIssuer2255=== RUN TestGlobMatch2256=== PAUSE TestGlobMatch2257=== RUN TestValidateToken_ValidToken2258=== PAUSE TestValidateToken_ValidToken2259=== RUN TestValidateToken_WrongAudience2260=== PAUSE TestValidateToken_WrongAudience2261=== RUN TestValidateToken_Expired2262=== PAUSE TestValidateToken_Expired2263=== RUN TestValidateToken_BoundClaimsMismatch2264=== PAUSE TestValidateToken_BoundClaimsMismatch2265=== RUN TestValidateToken_BoundSubjectMismatch2266=== PAUSE TestValidateToken_BoundSubjectMismatch2267=== RUN TestValidateToken_MultipleProviders2268=== PAUSE TestValidateToken_MultipleProviders2269=== RUN TestValidateToken_NoMatchingProvider2270=== PAUSE TestValidateToken_NoMatchingProvider2271=== RUN TestValidateToken_KubernetesServiceAccount2272=== PAUSE TestValidateToken_KubernetesServiceAccount2273=== RUN TestNewValidator_KubernetesRequiresCA2274=== PAUSE TestNewValidator_KubernetesRequiresCA2275=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2276=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2277=== RUN TestPins_ReservedForMatchingRule2278=== PAUSE TestPins_ReservedForMatchingRule2279=== RUN TestPins_TopLevelShorthand2280=== PAUSE TestPins_TopLevelShorthand2281=== RUN TestPins_ConfigValidation2282=== PAUSE TestPins_ConfigValidation2283=== RUN TestScopes_LegacyProviderDefaultsToWrite2284=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2285=== RUN TestScopes_Rules2286=== PAUSE TestScopes_Rules2287=== RUN TestScopes_ConfigValidation2288=== PAUSE TestScopes_ConfigValidation2289=== CONT TestScopes_LegacyProviderDefaultsToWrite2290=== CONT TestPins_ReservedForMatchingRule2291=== CONT TestScopes_ConfigValidation2292=== CONT TestValidateToken_BoundSubjectMismatch2293=== CONT TestScopes_Rules2294=== CONT TestValidateToken_KubernetesServiceAccount2295=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2296--- PASS: TestScopes_ConfigValidation (0.00s)2297=== CONT TestValidateToken_NoMatchingProvider2298=== CONT TestAudienceForIssuer2299--- PASS: TestAudienceForIssuer (0.00s)2300=== CONT TestPins_ConfigValidation2301--- PASS: TestPins_ConfigValidation (0.00s)2302=== CONT TestValidateToken_BoundClaimsMismatch2303=== CONT TestValidateToken_WrongAudience2304=== CONT TestPins_TopLevelShorthand23052026/09/21 21:30:49 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232306--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)2307=== CONT TestValidateToken_Expired23082026/09/21 21:30:49 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5228123092026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52283/oidc2310--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)2311=== CONT TestValidateToken_MultipleProviders2312--- PASS: TestValidateToken_WrongAudience (0.05s)2313=== CONT TestNewValidator_KubernetesRequiresCA23142026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52286/oidc2315--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)2316=== CONT TestValidateToken_ValidToken23172026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52288/oidc2318--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2319=== CONT TestGlobMatch2320=== RUN TestGlobMatch/foo_foo2321=== PAUSE TestGlobMatch/foo_foo2322=== RUN TestGlobMatch/foo_bar2323=== PAUSE TestGlobMatch/foo_bar2324=== RUN TestGlobMatch/*_2325=== PAUSE TestGlobMatch/*_2326=== RUN TestGlobMatch/*_anything2327=== PAUSE TestGlobMatch/*_anything2328=== RUN TestGlobMatch/foo*_foo2329=== PAUSE TestGlobMatch/foo*_foo2330=== RUN TestGlobMatch/foo*_foobar2331=== PAUSE TestGlobMatch/foo*_foobar2332=== RUN TestGlobMatch/foo*_bar2333=== PAUSE TestGlobMatch/foo*_bar2334=== RUN TestGlobMatch/*bar_bar2335=== PAUSE TestGlobMatch/*bar_bar2336=== RUN TestGlobMatch/*bar_foobar2337=== PAUSE TestGlobMatch/*bar_foobar2338=== RUN TestGlobMatch/*bar_foo2339=== PAUSE TestGlobMatch/*bar_foo2340=== RUN TestGlobMatch/foo*bar_foobar2341=== PAUSE TestGlobMatch/foo*bar_foobar2342=== RUN TestGlobMatch/foo*bar_foo123bar2343=== PAUSE TestGlobMatch/foo*bar_foo123bar2344=== RUN TestGlobMatch/foo*bar_foobarbaz2345=== PAUSE TestGlobMatch/foo*bar_foobarbaz2346=== RUN TestGlobMatch/*/*_foo/bar2347=== PAUSE TestGlobMatch/*/*_foo/bar2348=== RUN TestGlobMatch/*/*_foo2349=== PAUSE TestGlobMatch/*/*_foo2350=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2351=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2352=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02353=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02354=== RUN TestGlobMatch/refs/*/main_refs/heads/main2355=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2356=== RUN TestGlobMatch/fo?_foo2357=== PAUSE TestGlobMatch/fo?_foo2358=== RUN TestGlobMatch/fo?_fo2359=== PAUSE TestGlobMatch/fo?_fo2360=== RUN TestGlobMatch/fo?_fooo2361=== PAUSE TestGlobMatch/fo?_fooo2362=== RUN TestGlobMatch/?oo_foo2363=== PAUSE TestGlobMatch/?oo_foo2364=== RUN TestGlobMatch/?oo_boo2365=== PAUSE TestGlobMatch/?oo_boo2366=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2367=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2368=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2369=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2370=== CONT TestGlobMatch/foo_foo2371=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2372=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2373=== CONT TestGlobMatch/?oo_boo2374=== CONT TestGlobMatch/?oo_foo2375=== CONT TestGlobMatch/fo?_fooo2376=== CONT TestGlobMatch/fo?_fo2377=== CONT TestGlobMatch/fo?_foo2378=== CONT TestGlobMatch/refs/*/main_refs/heads/main2379=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02380=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2381=== CONT TestGlobMatch/*/*_foo2382=== CONT TestGlobMatch/*/*_foo/bar2383=== CONT TestGlobMatch/foo*bar_foobarbaz2384=== CONT TestGlobMatch/foo*bar_foo123bar2385=== CONT TestGlobMatch/foo*bar_foobar2386=== CONT TestGlobMatch/*bar_foo2387=== CONT TestGlobMatch/*bar_foobar2388=== CONT TestGlobMatch/*bar_bar2389=== CONT TestGlobMatch/foo*_bar2390=== CONT TestGlobMatch/foo*_foobar2391=== CONT TestGlobMatch/foo*_foo2392=== CONT TestGlobMatch/*_anything2393=== CONT TestGlobMatch/*_2394=== CONT TestGlobMatch/foo_bar2395--- PASS: TestGlobMatch (0.00s)2396 --- PASS: TestGlobMatch/foo_foo (0.00s)2397 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2398 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2399 --- PASS: TestGlobMatch/?oo_boo (0.00s)2400 --- PASS: TestGlobMatch/?oo_foo (0.00s)2401 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2402 --- PASS: TestGlobMatch/fo?_fo (0.00s)2403 --- PASS: TestGlobMatch/fo?_foo (0.00s)2404 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2405 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2406 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2407 --- PASS: TestGlobMatch/*/*_foo (0.00s)2408 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2409 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2410 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2411 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2412 --- PASS: TestGlobMatch/*bar_foo (0.00s)2413 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2414 --- PASS: TestGlobMatch/*bar_bar (0.00s)2415 --- PASS: TestGlobMatch/foo*_bar (0.00s)2416 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2417 --- PASS: TestGlobMatch/foo*_foo (0.00s)2418 --- PASS: TestGlobMatch/*_anything (0.00s)2419 --- PASS: TestGlobMatch/*_ (0.00s)2420 --- PASS: TestGlobMatch/foo_bar (0.00s)24212026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52290/oidc2422--- PASS: TestScopes_Rules (0.11s)24232026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52293/oidc2424--- PASS: TestValidateToken_BoundClaimsMismatch (0.12s)24252026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52295/oidc2426--- PASS: TestPins_TopLevelShorthand (0.12s)24272026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52297/oidc2428--- PASS: TestValidateToken_ValidToken (0.07s)24292026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52303/oidc24302026/09/21 21:30:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52292/oidc2431--- PASS: TestValidateToken_Expired (0.09s)24322026/09/21 21:30:49 http: TLS handshake error from 127.0.0.1:52301: remote error: tls: bad certificate2433--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)2434--- PASS: TestValidateToken_NoMatchingProvider (0.14s)24352026/09/21 21:30:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52299/oidc24362026/09/21 21:30:49 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52306/oidc2437--- PASS: TestValidateToken_MultipleProviders (0.10s)24382026/09/21 21:30:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52309/oidc2439--- PASS: TestPins_ReservedForMatchingRule (0.18s)2440PASS2441Running hook tests...2442=== RUN TestSendPathsEmpty2443=== PAUSE TestSendPathsEmpty2444=== RUN TestQueueEnqueueAndFetch2445=== PAUSE TestQueueEnqueueAndFetch2446=== RUN TestQueueDeduplication2447=== PAUSE TestQueueDeduplication2448=== RUN TestQueueRemove2449=== PAUSE TestQueueRemove2450=== RUN TestQueueFetchBatchLimit2451=== PAUSE TestQueueFetchBatchLimit2452=== RUN TestQueueRetryMovesToBack2453=== PAUSE TestQueueRetryMovesToBack2454=== RUN TestQueueFetchRemoveLifecycle2455=== PAUSE TestQueueFetchRemoveLifecycle2456=== RUN TestQueueConcurrentWriters2457=== PAUSE TestQueueConcurrentWriters2458=== RUN TestQueueRemoveLargeClosure2459=== PAUSE TestQueueRemoveLargeClosure2460=== RUN TestServerClientIntegration2461=== PAUSE TestServerClientIntegration2462=== RUN TestServerQueueError2463=== PAUSE TestServerQueueError2464=== RUN TestGetListenerSocketActivation2465 server_test.go:210: === RUN TestGetListenerSocketActivation2466 --- PASS: TestGetListenerSocketActivation (0.00s)2467 PASS2468 2469--- PASS: TestGetListenerSocketActivation (0.01s)2470=== RUN TestDrainIsolatesPoisonPath2471=== PAUSE TestDrainIsolatesPoisonPath2472=== RUN TestRunNotBlockedByPoisonHead2473=== PAUSE TestRunNotBlockedByPoisonHead2474=== RUN TestDrainGivesUpWhenServerDown2475=== PAUSE TestDrainGivesUpWhenServerDown2476=== RUN TestFailedPathPrunedByLaterClosure2477=== PAUSE TestFailedPathPrunedByLaterClosure2478=== RUN TestWorkerUploadsAndRemoves2479=== PAUSE TestWorkerUploadsAndRemoves2480=== RUN TestWorkerSkipsGCdPaths2481=== PAUSE TestWorkerSkipsGCdPaths2482=== RUN TestWorkerPrunesClosureDeps2483=== PAUSE TestWorkerPrunesClosureDeps2484=== RUN TestDrainTimeout2485=== PAUSE TestDrainTimeout2486=== CONT TestSendPathsEmpty2487=== CONT TestServerQueueError2488--- PASS: TestSendPathsEmpty (0.00s)2489=== CONT TestWorkerUploadsAndRemoves2490=== CONT TestQueueFetchBatchLimit2491=== CONT TestQueueRemove2492=== CONT TestServerClientIntegration2493=== CONT TestDrainGivesUpWhenServerDown2494=== CONT TestQueueRemoveLargeClosure2495=== CONT TestQueueConcurrentWriters2496=== CONT TestQueueFetchRemoveLifecycle2497=== CONT TestQueueRetryMovesToBack24982026/09/21 21:30:50 ERROR Failed to queue paths error="permission denied" count=12499--- PASS: TestServerQueueError (0.00s)2500=== CONT TestQueueDeduplication2501--- PASS: TestServerClientIntegration (0.00s)2502=== CONT TestQueueEnqueueAndFetch2503--- PASS: TestQueueEnqueueAndFetch (0.01s)2504=== CONT TestFailedPathPrunedByLaterClosure2505--- PASS: TestQueueFetchBatchLimit (0.01s)2506=== CONT TestWorkerPrunesClosureDeps2507--- PASS: TestQueueDeduplication (0.01s)2508=== CONT TestDrainTimeout25092026/09/21 21:30:50 INFO Uploading batch count=225102026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=225112026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainGivesUpWhenServerDown1257592865/002/a2512--- PASS: TestQueueRemove (0.01s)2513=== CONT TestWorkerSkipsGCdPaths25142026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainGivesUpWhenServerDown1257592865/002/b25152026/09/21 21:30:50 INFO Upload queue status pending=22516--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2517=== CONT TestRunNotBlockedByPoisonHead25182026/09/21 21:30:50 INFO Uploading batch count=225192026/09/21 21:30:50 INFO Uploading batch count=225202026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=225212026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainGivesUpWhenServerDown1257592865/002/c2522--- PASS: TestQueueRetryMovesToBack (0.01s)2523=== CONT TestDrainIsolatesPoisonPath25242026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainGivesUpWhenServerDown1257592865/002/d25252026/09/21 21:30:50 INFO Uploading batch count=225262026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=225272026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainGivesUpWhenServerDown1257592865/002/e25282026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainGivesUpWhenServerDown1257592865/002/f25292026/09/21 21:30:50 ERROR Drain finished with paths left in queue remaining=1025302026/09/21 21:30:50 INFO Uploading batch count=125312026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=125322026/09/21 21:30:50 INFO Upload queue status pending=225332026/09/21 21:30:50 INFO Uploading batch count=125342026/09/21 21:30:50 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-38627-3659511840/TestWorkerSkipsGCdPaths1609022301/002/nonexistent25352026/09/21 21:30:50 INFO Uploading batch count=125362026/09/21 21:30:50 INFO Uploading batch count=125372026/09/21 21:30:50 INFO Upload queue status pending=225382026/09/21 21:30:50 INFO Uploading batch count=125392026/09/21 21:30:50 INFO Uploading batch count=225402026/09/21 21:30:50 INFO Uploading batch count=425412026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=425422026/09/21 21:30:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-38627-3659511840/TestDrainIsolatesPoisonPath19848841/002/bbb25432026/09/21 21:30:50 INFO Upload queue status pending=325442026/09/21 21:30:50 INFO Uploading batch count=125452026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=125462026/09/21 21:30:50 INFO Uploading batch count=12547--- PASS: TestDrainGivesUpWhenServerDown (0.02s)25482026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=125492026/09/21 21:30:50 INFO Uploading batch count=125502026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=125512026/09/21 21:30:50 INFO Uploading batch count=125522026/09/21 21:30:50 ERROR Upload failed error="upload failed" count=12553--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)25542026/09/21 21:30:50 ERROR Drain finished with paths left in queue remaining=12555--- PASS: TestDrainIsolatesPoisonPath (0.01s)2556--- PASS: TestWorkerUploadsAndRemoves (0.03s)2557--- PASS: TestWorkerSkipsGCdPaths (0.02s)2558--- PASS: TestWorkerPrunesClosureDeps (0.02s)2559--- PASS: TestQueueRemoveLargeClosure (0.06s)2560--- PASS: TestQueueConcurrentWriters (0.16s)25612026/09/21 21:30:50 ERROR Upload failed error="context deadline exceeded" count=225622026/09/21 21:30:50 ERROR Drain finished with paths left in queue remaining=42563--- PASS: TestDrainTimeout (0.21s)25642026/09/21 21:30:51 INFO Uploading batch count=125652026/09/21 21:30:51 INFO Uploading batch count=125662026/09/21 21:30:51 INFO Uploading batch count=125672026/09/21 21:30:51 ERROR Upload failed error="upload failed" count=125682026/09/21 21:30:51 INFO Uploading batch count=125692026/09/21 21:30:51 ERROR Upload failed error="upload failed" count=125702026/09/21 21:30:51 INFO Uploading batch count=125712026/09/21 21:30:51 ERROR Upload failed error="upload failed" count=125722026/09/21 21:30:51 INFO Uploading batch count=125732026/09/21 21:30:51 ERROR Upload failed error="upload failed" count=125742026/09/21 21:30:51 ERROR Drain finished with paths left in queue remaining=12575--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2576PASS