niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #255
· 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.20s)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 TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96=== CONT TestSetClientTLSErrors97--- PASS: TestShellSplit (0.00s)98=== CONT TestSetClientTLSDoesNotMutateDefaultTransport99=== CONT TestScriptTokenCachesUntilRefresh100=== CONT TestStreamPushGivesUpOnDeadServer101=== CONT TestSetClientTLS102=== CONT TestStreamPushBatchesUnderLoad103=== CONT TestDoWithRetry_BodyReplayedViaGetBody104=== CONT TestResolveStorePath105=== CONT TestEncodeNixBase32106=== RUN TestEncodeNixBase32/test_string_hash107=== PAUSE TestEncodeNixBase32/test_string_hash108=== RUN TestEncodeNixBase32/empty_input109=== PAUSE TestEncodeNixBase32/empty_input110=== CONT TestEncodeNixBase32/test_string_hash111=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1122026/09/23 09:31:33 ERROR Upload failed error="connection refused" count=201132026/09/23 09:31:33 ERROR Server seems unavailable, giving up on batch untried=17114--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)115=== CONT TestRateLimiterFeedback116=== RUN TestRateLimiterFeedback/429_enables_limiter117=== PAUSE TestRateLimiterFeedback/429_enables_limiter118=== RUN TestRateLimiterFeedback/503_enables_limiter119=== PAUSE TestRateLimiterFeedback/503_enables_limiter120=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter121=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter122=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter123=== RUN TestSetClientTLSErrors/missing_cert_file124=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter125=== CONT TestPathInfoCACompatibility126=== RUN TestPathInfoCACompatibility/null_ca_field127=== PAUSE TestSetClientTLSErrors/missing_cert_file128=== RUN TestSetClientTLSErrors/missing_key_file129=== PAUSE TestSetClientTLSErrors/missing_key_file130=== RUN TestSetClientTLSErrors/missing_ca_file131=== PAUSE TestSetClientTLSErrors/missing_ca_file1322026/09/23 09:31:33 WARN Rate limiter enabled after throttle name=server-test rate=5133=== RUN TestSetClientTLSErrors/invalid_ca_file134=== PAUSE TestSetClientTLSErrors/invalid_ca_file135=== PAUSE TestPathInfoCACompatibility/null_ca_field136=== CONT TestParsePathInfoJSONMultiplePaths137=== RUN TestPathInfoCACompatibility/old_string_format_-_text138=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text139=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths140=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive141=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive142=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths143=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths144=== RUN TestPathInfoCACompatibility/new_structured_format_-_text145=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths146=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text147=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method148=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method149=== CONT TestParsePathInfoJSON150=== RUN TestParsePathInfoJSON/Nix_format151=== PAUSE TestParsePathInfoJSON/Nix_format152=== CONT TestPathInfoHashCompatibility153=== RUN TestSetClientTLS/rejects_connection_without_client_cert154=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert155=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA156=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA157=== RUN TestSetClientTLS/preserves_debug_logging_transport158=== PAUSE TestSetClientTLS/preserves_debug_logging_transport159=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)160=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)161=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon162=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon163=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI164=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI165=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512166=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512167=== CONT TestGetStorePathHash168=== RUN TestGetStorePathHash/valid_store_path169=== PAUSE TestGetStorePathHash/valid_store_path170=== RUN TestGetStorePathHash/basename_without_hyphen_should_error171=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error172=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error173=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error174=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error175=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error176=== RUN TestParsePathInfoJSON/Lix_format177=== PAUSE TestParsePathInfoJSON/Lix_format178=== RUN TestParsePathInfoJSON/empty_input179=== PAUSE TestParsePathInfoJSON/empty_input180=== RUN TestParsePathInfoJSON/whitespace_only181--- PASS: TestResolveStorePath (0.01s)182=== CONT TestEncodeNixBase32/empty_input183=== CONT TestConvertHashToNix32184=== RUN TestConvertHashToNix32/SRI_format_to_Nix32185=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32186=== RUN TestConvertHashToNix32/already_Nix32_format187=== PAUSE TestConvertHashToNix32/already_Nix32_format188=== RUN TestConvertHashToNix32/invalid_format189=== PAUSE TestConvertHashToNix32/invalid_format190=== CONT TestEncodeNixBase32WithRealHash191=== CONT TestFileTokenEmpty192=== PAUSE TestParsePathInfoJSON/whitespace_only193=== CONT TestStreamPushReportsSignatures194=== CONT TestFileTokenMissing1952026/09/23 09:31:33 WARN Rate limiter enabled after throttle name=server-test rate=51962026/09/23 09:31:33 ERROR Upload failed error=boom count=11972026/09/23 09:31:33 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53857198=== CONT TestClientSignaturesByStorePath199=== CONT TestPartSizeForNAR200=== RUN TestPartSizeForNAR/zero_stays_at_minimum201=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum202=== CONT TestDumpPathWriterError203=== RUN TestPartSizeForNAR/small_stays_at_minimum204=== PAUSE TestPartSizeForNAR/small_stays_at_minimum205=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum206=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum207=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts208=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts209=== RUN TestPartSizeForNAR/1_TiB210=== PAUSE TestPartSizeForNAR/1_TiB211=== RUN TestPartSizeForNAR/5_TiB_S3_max_object212=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object213=== RUN TestPartSizeForNAR/capped_at_5_GiB214--- PASS: TestEncodeNixBase32 (0.00s)215 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)216 --- PASS: TestEncodeNixBase32/empty_input (0.00s)2172026/09/23 09:31:33 WARN Rate limiter backed off name=server-test rate=52182026/09/23 09:31:33 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53857219=== CONT TestScriptTokenNoExpiryRerunsEveryCall220--- PASS: TestEncodeNixBase32WithRealHash (0.00s)221--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)222--- PASS: TestStreamPushReportsSignatures (0.00s)223--- PASS: TestClientSignaturesByStorePath (0.00s)224--- PASS: TestDoServerRequestAttachesToken (0.02s)225--- PASS: TestFileTokenEmpty (0.00s)226=== CONT TestDumpPathSingleFile227--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)228=== CONT TestDumpPathMatchesNix229--- PASS: TestFileTokenMissing (0.00s)230=== CONT TestUploadMultipart_SupersededByPeer231=== RUN TestUploadMultipart_SupersededByPeer/exists232=== PAUSE TestUploadMultipart_SupersededByPeer/exists233=== RUN TestUploadMultipart_SupersededByPeer/missing234=== PAUSE TestUploadMultipart_SupersededByPeer/missing235=== CONT TestFileTokenReadsAndCaches236=== PAUSE TestPartSizeForNAR/capped_at_5_GiB237=== CONT TestScriptTokenScriptFails238=== RUN TestParsePathInfoJSON/invalid_JSON239=== PAUSE TestParsePathInfoJSON/invalid_JSON240=== CONT TestScriptTokenEmptyCommand241=== CONT TestStreamPushReportsEveryPath242--- PASS: TestScriptTokenEmptyCommand (0.00s)243--- PASS: TestStreamPushReportsEveryPath (0.00s)244=== CONT TestShellSplitErrors245--- PASS: TestShellSplitErrors (0.00s)246=== CONT TestStaticToken247--- PASS: TestStaticToken (0.00s)248=== CONT TestCaseHackSuffix249--- PASS: TestFileTokenReadsAndCaches (0.00s)250=== CONT TestUploadMultipart_PartsInParallel251--- PASS: TestScriptTokenScriptFails (0.01s)252=== CONT TestFilterOversizedClosures253=== RUN TestFilterOversizedClosures/no_limit_keeps_everything254=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything255=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped256=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped257=== RUN TestFilterOversizedClosures/all_closures_skipped258=== PAUSE TestFilterOversizedClosures/all_closures_skipped259=== CONT TestRegisterUploadedObjectReusesConnections260--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)261=== CONT TestStreamPushRequestLine2622026/09/23 09:31:33 ERROR Upload failed error=boom count=1263--- PASS: TestDumpPathWriterError (0.05s)264=== CONT TestStreamPushIsolatesFailures2652026/09/23 09:31:33 ERROR Upload failed error="bad path" count=3266--- PASS: TestStreamPushIsolatesFailures (0.00s)267=== CONT TestScriptTokenBadJSON268--- PASS: TestStreamPushRequestLine (0.01s)269=== CONT TestScriptTokenEmptyToken270--- PASS: TestScriptTokenBadJSON (0.02s)271=== CONT TestRateLimiterFeedback/429_enables_limiter2722026/09/23 09:31:33 WARN Rate limiter enabled after throttle name=server-test rate=52732026/09/23 09:31:33 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:539322742026/09/23 09:31:33 WARN Rate limiter backed off name=server-test rate=5275=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter276=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter277=== CONT TestRateLimiterFeedback/503_enables_limiter2782026/09/23 09:31:33 WARN Rate limiter enabled after throttle name=server-test rate=52792026/09/23 09:31:33 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:539382802026/09/23 09:31:33 WARN Rate limiter backed off name=server-test rate=5281--- PASS: TestRateLimiterFeedback (0.00s)282 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)283 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)284 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)285 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)286=== CONT TestSetClientTLSErrors/missing_cert_file287=== CONT TestSetClientTLSErrors/invalid_ca_file288=== CONT TestSetClientTLSErrors/missing_ca_file289=== CONT TestSetClientTLSErrors/missing_key_file290=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths291=== CONT TestPathInfoCACompatibility/null_ca_field292=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths293--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)294 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)295 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)296=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method297=== CONT TestPathInfoCACompatibility/new_structured_format_-_text298=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive299=== CONT TestPathInfoCACompatibility/old_string_format_-_text300--- PASS: TestPathInfoCACompatibility (0.00s)301 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)302 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)303 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)304 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)305 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)306=== CONT TestSetClientTLS/rejects_connection_without_client_cert307--- PASS: TestScriptTokenCachesUntilRefresh (0.09s)308=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)309=== CONT TestSetClientTLS/preserves_debug_logging_transport310--- PASS: TestSetClientTLSErrors (0.02s)311 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)312 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)313 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)314 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)315--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)316=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA317=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512318=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI319=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon320--- PASS: TestPathInfoHashCompatibility (0.00s)321 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)322 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)323 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)324 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)325=== CONT TestGetStorePathHash/valid_store_path326=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error327=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error328=== CONT TestGetStorePathHash/basename_without_hyphen_should_error329--- PASS: TestGetStorePathHash (0.00s)330 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)331 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)332 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)333 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)334=== CONT TestConvertHashToNix32/SRI_format_to_Nix32335=== CONT TestConvertHashToNix32/invalid_format336=== CONT TestConvertHashToNix32/already_Nix32_format337--- PASS: TestConvertHashToNix32 (0.00s)338 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)339 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)340 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)341=== CONT TestUploadMultipart_SupersededByPeer/exists342=== CONT TestUploadMultipart_SupersededByPeer/missing343=== CONT TestPartSizeForNAR/zero_stays_at_minimum344=== CONT TestPartSizeForNAR/1_TiB345=== CONT TestPartSizeForNAR/capped_at_5_GiB346=== CONT TestPartSizeForNAR/5_TiB_S3_max_object347=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum348=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts349=== CONT TestPartSizeForNAR/small_stays_at_minimum350--- PASS: TestPartSizeForNAR (0.00s)351 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)352 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)353 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)354 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)355 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)356 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)357 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)358=== CONT TestParsePathInfoJSON/Nix_format359=== CONT TestParsePathInfoJSON/empty_input360=== CONT TestParsePathInfoJSON/Lix_format361=== CONT TestParsePathInfoJSON/whitespace_only362=== CONT TestParsePathInfoJSON/invalid_JSON363--- PASS: TestParsePathInfoJSON (0.00s)364 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)365 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)366 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)367 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)368 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)369=== CONT TestFilterOversizedClosures/no_limit_keeps_everything370=== CONT TestFilterOversizedClosures/all_closures_skipped3712026/09/23 09:31:33 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50372=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3732026/09/23 09:31:33 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000374--- PASS: TestFilterOversizedClosures (0.00s)375 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)376 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)377 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)378--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)379 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)380 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)381--- PASS: TestScriptTokenEmptyToken (0.03s)3822026/09/23 09:31:33 http: TLS handshake error from 127.0.0.1:53942: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.01s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestStreamPushBatchesUnderLoad (0.10s)388--- PASS: TestDumpPathSingleFile (0.38s)389--- PASS: TestCaseHackSuffix (0.47s)390--- PASS: TestDumpPathMatchesNix (0.51s)391--- PASS: TestUploadMultipart_PartsInParallel (0.63s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld14".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-52991-3138667589/postgres969329208/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: 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.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-52991-3138667589/postgres969329208/data -l logfile start4214222026-09-23 09:31:41.162 UTC [62476] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4232026-09-23 09:31:41.162 UTC [62476] LOG: listening on Unix socket "/nix/var/nix/builds/nix-52991-3138667589/postgres969329208/.s.PGSQL.5432"4242026-09-23 09:31:41.166 UTC [62494] LOG: database system was shut down at 2026-09-23 09:31:40 UTC4252026-09-23 09:31:41.167 UTC [62476] LOG: database system is ready to accept connections426/nix/var/nix/builds/nix-52991-3138667589/postgres969329208:5432 - accepting connections427{"timestamp":"2026-09-23T09:31:43.33529Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"46b6cb13-7b40-4746-8223-859f517f3fce","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}428{"timestamp":"2026-09-23T09:31:43.438119Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"92827e39-0828-4989-9f28-f891f8f7f1eb","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestResolveDBConnectionString462=== PAUSE TestResolveDBConnectionString463=== RUN TestLeadElectsOneAndHandsOver464=== PAUSE TestLeadElectsOneAndHandsOver465=== RUN TestLeadIncumbentWinsAfterRestart4662026-09-23 09:31:44.027 UTC [63254] ERROR: relation "goose_db_version" does not exist at character 364672026-09-23 09:31:44.027 UTC [63254] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4682026/09/23 09:31:44 OK 20241026095416_initial_model.sql (8.26ms)4692026/09/23 09:31:44 OK 20251210153512_drop_unused_gin_index.sql (1.41ms)4702026/09/23 09:31:44 OK 20251218171726_add_pins.sql (2.86ms)4712026/09/23 09:31:44 OK 20260628120000_add_object_size_and_stats.sql (2.91ms)4722026/09/23 09:31:44 OK 20260905000000_add_claims.sql (3.24ms)4732026/09/23 09:31:44 OK 20260920000000_drop_claims.sql (1.15ms)4742026/09/23 09:31:44 goose: successfully migrated database to version: 202609200000004752026/09/23 09:31:44 OK 1_commit_pending_closure.sql (1.86ms)4762026/09/23 09:31:44 OK 2_object_stats_trigger.sql (534.83µs)4772026/09/23 09:31:44 goose: up to current file version: 24782026/09/23 09:31:44 INFO lead: acquired remote=192.0.2.1:12344792026/09/23 09:31:44 INFO lead: released remote=192.0.2.1:12344802026/09/23 09:31:44 INFO lead: acquired remote=192.0.2.1:12344812026/09/23 09:31:44 INFO lead: released remote=192.0.2.1:1234482--- PASS: TestLeadIncumbentWinsAfterRestart (1.25s)483=== RUN TestLeadEndsOnShutdown484=== PAUSE TestLeadEndsOnShutdown485=== RUN TestGCAdvisoryLockBlocksConcurrentRun4862026-09-23 09:31:45.037 UTC [63503] ERROR: relation "goose_db_version" does not exist at character 364872026-09-23 09:31:45.037 UTC [63503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4882026/09/23 09:31:45 OK 20241026095416_initial_model.sql (9.16ms)4892026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)4902026/09/23 09:31:45 OK 20251218171726_add_pins.sql (2.36ms)4912026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (2.6ms)4922026/09/23 09:31:45 OK 20260905000000_add_claims.sql (1.76ms)4932026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (3.22ms)4942026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000004952026/09/23 09:31:45 OK 1_commit_pending_closure.sql (1.77ms)4962026/09/23 09:31:45 OK 2_object_stats_trigger.sql (667.67µs)4972026/09/23 09:31:45 goose: up to current file version: 2498--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.38s)499=== RUN TestGCBugBareHashReferences500=== PAUSE TestGCBugBareHashReferences501=== RUN TestGCMetrics502=== PAUSE TestGCMetrics503=== RUN TestGCTaskStore_StartNew504=== PAUSE TestGCTaskStore_StartNew505=== RUN TestGCTaskStore_DeduplicateSameParams506=== PAUSE TestGCTaskStore_DeduplicateSameParams507=== RUN TestGCTaskStore_ConflictDifferentParams508=== PAUSE TestGCTaskStore_ConflictDifferentParams509=== RUN TestGCTaskStore_GetEmpty510=== PAUSE TestGCTaskStore_GetEmpty511=== RUN TestGCTaskStore_GetReturnsLatest512=== PAUSE TestGCTaskStore_GetReturnsLatest513=== RUN TestGCTaskStore_CompletedAllowsNewTask514=== PAUSE TestGCTaskStore_CompletedAllowsNewTask515=== RUN TestGCTaskStore_PhaseUpdates516=== PAUSE TestGCTaskStore_PhaseUpdates517=== RUN TestGCTaskStore_Fail518=== PAUSE TestGCTaskStore_Fail519=== RUN TestGracefulShutdownDrainsInflight520=== PAUSE TestGracefulShutdownDrainsInflight521=== RUN TestService_healthCheckHandler522=== PAUSE TestService_healthCheckHandler523=== RUN TestService_readinessHandler524=== PAUSE TestService_readinessHandler525=== RUN TestGenerateLandingPage526=== PAUSE TestGenerateLandingPage527=== RUN TestCacheConfigHandlerMaxNarSize528=== PAUSE TestCacheConfigHandlerMaxNarSize529=== RUN TestCreatePendingClosureRejectsOversizedNAR530=== PAUSE TestCreatePendingClosureRejectsOversizedNAR531=== RUN TestNARDeduplicationMetadataUploadBug532=== PAUSE TestNARDeduplicationMetadataUploadBug533=== RUN TestMetricsInventory534=== PAUSE TestMetricsInventory535=== RUN TestService_NativeMTLS536=== PAUSE TestService_NativeMTLS537=== RUN TestServerTLSConfig538=== PAUSE TestServerTLSConfig539=== RUN TestMultipartCleanup540=== PAUSE TestMultipartCleanup541=== RUN TestObjectStatsTrigger542=== PAUSE TestObjectStatsTrigger543=== RUN TestOrphanedObjectsGC544=== PAUSE TestOrphanedObjectsGC545=== RUN TestOrphanedObjectsGCStressTest546=== PAUSE TestOrphanedObjectsGCStressTest547=== RUN TestResurrectedObjectNotDeleted548=== PAUSE TestResurrectedObjectNotDeleted549=== RUN TestCreatePin_ReservedPins550=== PAUSE TestCreatePin_ReservedPins551=== RUN TestParseSingleRange552=== PAUSE TestParseSingleRange553=== RUN TestIsValidCachePath554=== PAUSE TestIsValidCachePath555=== RUN TestReadProxyNarinfo556=== PAUSE TestReadProxyNarinfo557=== RUN TestReadProxyNarinfoAlreadyDecompressed558=== PAUSE TestReadProxyNarinfoAlreadyDecompressed559=== RUN TestReadProxyNarStreaming560=== PAUSE TestReadProxyNarStreaming561=== RUN TestReadProxy404562=== PAUSE TestReadProxy404563=== RUN TestReadProxyInvalidPath564=== PAUSE TestReadProxyInvalidPath565=== RUN TestReadProxyHead566=== PAUSE TestReadProxyHead567=== RUN TestReadProxyConditionalGet568=== PAUSE TestReadProxyConditionalGet569=== RUN TestReadProxyRootRedirectsToIndexHTML570=== PAUSE TestReadProxyRootRedirectsToIndexHTML571=== RUN TestReadProxyDisabled572=== PAUSE TestReadProxyDisabled573=== RUN TestReadRedirectNar574=== PAUSE TestReadRedirectNar575=== RUN TestReadRedirectKeepsNarinfoProxied576=== PAUSE TestReadRedirectKeepsNarinfoProxied577=== RUN TestReadProxyRangeRequest578=== PAUSE TestReadProxyRangeRequest579=== RUN TestReadRedirectUsesPublicS3URL580=== PAUSE TestReadRedirectUsesPublicS3URL581=== RUN TestRedundantMultipartUpload582=== PAUSE TestRedundantMultipartUpload583=== RUN TestCompleteMultipartUpload_ErrorButObjectExists584=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists585=== RUN TestCompletedNarNotReofferedAcrossClosures586=== PAUSE TestCompletedNarNotReofferedAcrossClosures587=== RUN TestPresignedUploadRegisteredBeforeCommit588=== PAUSE TestPresignedUploadRegisteredBeforeCommit589=== RUN TestService_Rustfstest590=== PAUSE TestService_Rustfstest591=== RUN TestParseSize592=== PAUSE TestParseSize593=== RUN TestSkippedUploadsHandler594=== PAUSE TestSkippedUploadsHandler595=== RUN TestSystemdListenerNotActivated596--- PASS: TestSystemdListenerNotActivated (0.00s)597=== RUN TestWatchdogBeatsWhenHealthy598--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)599=== RUN TestWatchdogSkipsWhenUnhealthy6002026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6012026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6022026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6032026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6042026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6052026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6062026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6072026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6082026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6092026/09/23 09:31:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"610--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)611=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle612=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle613=== RUN TestProxyWriteTimeout614=== PAUSE TestProxyWriteTimeout615=== RUN TestIsValidUploadKey616=== PAUSE TestIsValidUploadKey617=== RUN TestUploadHandlersRejectInvalidKeys618=== PAUSE TestUploadHandlersRejectInvalidKeys619=== RUN TestUploadHandlersRejectOversizedBody620=== PAUSE TestUploadHandlersRejectOversizedBody621=== RUN TestService_cleanupPendingClosuresHandler622=== PAUSE TestService_cleanupPendingClosuresHandler623=== RUN TestService_createPendingClosureHandler624=== PAUSE TestService_createPendingClosureHandler625=== RUN TestService_verifyS3Integrity626=== PAUSE TestService_verifyS3Integrity627=== RUN TestCompleteMultipartUnregistered628=== PAUSE TestCompleteMultipartUnregistered629=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT630=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT631=== CONT TestService_AuthMiddleware632=== CONT TestMultipartCleanup633=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT634=== CONT TestCompleteMultipartUnregistered635=== CONT TestReadRedirectKeepsNarinfoProxied636=== CONT TestService_verifyS3Integrity637=== CONT TestService_createPendingClosureHandler638=== CONT TestParseSize639--- PASS: TestParseSize (0.00s)640=== CONT TestCompletedNarNotReofferedAcrossClosures641=== CONT TestService_Rustfstest642=== CONT TestPresignedUploadRegisteredBeforeCommit6432026-09-23 09:31:45.674 UTC [63669] ERROR: relation "goose_db_version" does not exist at character 366442026-09-23 09:31:45.674 UTC [63669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6452026/09/23 09:31:45 OK 20241026095416_initial_model.sql (16.02ms)6462026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)6472026/09/23 09:31:45 OK 20251218171726_add_pins.sql (4.31ms)6482026-09-23 09:31:45.730 UTC [63684] ERROR: relation "goose_db_version" does not exist at character 366492026-09-23 09:31:45.730 UTC [63684] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6502026-09-23 09:31:45.734 UTC [63685] ERROR: relation "goose_db_version" does not exist at character 366512026-09-23 09:31:45.734 UTC [63685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6522026-09-23 09:31:45.737 UTC [63688] ERROR: relation "goose_db_version" does not exist at character 366532026-09-23 09:31:45.737 UTC [63688] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6542026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (9.57ms)6552026-09-23 09:31:45.738 UTC [63686] ERROR: relation "goose_db_version" does not exist at character 366562026-09-23 09:31:45.738 UTC [63686] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6572026-09-23 09:31:45.742 UTC [63689] ERROR: relation "goose_db_version" does not exist at character 366582026-09-23 09:31:45.742 UTC [63689] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6592026/09/23 09:31:45 OK 20260905000000_add_claims.sql (6.45ms)6602026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (7.61ms)6612026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000006622026/09/23 09:31:45 OK 20241026095416_initial_model.sql (11.76ms)6632026-09-23 09:31:45.761 UTC [63692] ERROR: relation "goose_db_version" does not exist at character 366642026-09-23 09:31:45.761 UTC [63692] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6652026/09/23 09:31:45 OK 1_commit_pending_closure.sql (12.91ms)6662026/09/23 09:31:45 OK 20241026095416_initial_model.sql (13.83ms)6672026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (15.22ms)6682026/09/23 09:31:45 OK 2_object_stats_trigger.sql (5.27ms)6692026/09/23 09:31:45 goose: up to current file version: 26702026/09/23 09:31:45 OK 20241026095416_initial_model.sql (28.26ms)6712026/09/23 09:31:45 OK 20251218171726_add_pins.sql (3.17ms)6722026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)6732026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (8.39ms)6742026-09-23 09:31:45.776 UTC [63694] ERROR: relation "goose_db_version" does not exist at character 366752026-09-23 09:31:45.776 UTC [63694] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6762026/09/23 09:31:45 OK 20241026095416_initial_model.sql (22.67ms)6772026/09/23 09:31:45 OK 20251218171726_add_pins.sql (5.06ms)6782026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (6.92ms)6792026/09/23 09:31:45 OK 20251218171726_add_pins.sql (6.35ms)6802026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (4.21ms)6812026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (5.66ms)6822026/09/23 09:31:45 OK 20260905000000_add_claims.sql (10.27ms)6832026/09/23 09:31:45 OK 20241026095416_initial_model.sql (24ms)6842026-09-23 09:31:45.796 UTC [63698] ERROR: relation "goose_db_version" does not exist at character 366852026-09-23 09:31:45.796 UTC [63698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6862026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (16.68ms)6872026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (14.24ms)6882026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (16.52ms)6892026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000006902026/09/23 09:31:45 OK 20251218171726_add_pins.sql (25.89ms)6912026/09/23 09:31:45 OK 20260905000000_add_claims.sql (22.89ms)6922026/09/23 09:31:45 OK 1_commit_pending_closure.sql (1.3ms)6932026/09/23 09:31:45 OK 2_object_stats_trigger.sql (451µs)6942026/09/23 09:31:45 goose: up to current file version: 26952026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (17.45ms)6962026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000006972026/09/23 09:31:45 OK 20260905000000_add_claims.sql (28.2ms)6982026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (19.41ms)6992026/09/23 09:31:45 OK 20251218171726_add_pins.sql (22.1ms)7002026/09/23 09:31:45 OK 20241026095416_initial_model.sql (52.22ms)7012026/09/23 09:31:45 OK 1_commit_pending_closure.sql (4.82ms)7022026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (6.76ms)7032026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007042026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (5.38ms)7052026/09/23 09:31:45 OK 20241026095416_initial_model.sql (43.46ms)7062026/09/23 09:31:45 OK 20260905000000_add_claims.sql (7.17ms)7072026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (7.16ms)7082026/09/23 09:31:45 OK 2_object_stats_trigger.sql (4.6ms)7092026/09/23 09:31:45 goose: up to current file version: 27102026/09/23 09:31:45 OK 20241026095416_initial_model.sql (10.49ms)7112026/09/23 09:31:45 OK 1_commit_pending_closure.sql (4.38ms)7122026/09/23 09:31:45 OK 2_object_stats_trigger.sql (709.25µs)7132026/09/23 09:31:45 goose: up to current file version: 27142026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (8.38ms)7152026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (6.74ms)7162026/09/23 09:31:45 OK 20260905000000_add_claims.sql (9.76ms)7172026/09/23 09:31:45 OK 20251218171726_add_pins.sql (11.41ms)7182026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (16.27ms)7192026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007202026-09-23 09:31:45.850 UTC [63713] ERROR: relation "goose_db_version" does not exist at character 367212026-09-23 09:31:45.850 UTC [63713] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7222026/09/23 09:31:45 OK 20251218171726_add_pins.sql (10.58ms)7232026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (9.15ms)7242026/09/23 09:31:45 OK 20251218171726_add_pins.sql (9.98ms)7252026/09/23 09:31:45 OK 1_commit_pending_closure.sql (3.19ms)7262026/09/23 09:31:45 OK 2_object_stats_trigger.sql (534.13µs)7272026/09/23 09:31:45 goose: up to current file version: 27282026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (14.54ms)7292026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007302026/09/23 09:31:45 OK 1_commit_pending_closure.sql (4.33ms)7312026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (9.88ms)7322026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (10.02ms)7332026/09/23 09:31:45 OK 2_object_stats_trigger.sql (774µs)7342026/09/23 09:31:45 goose: up to current file version: 27352026/09/23 09:31:45 OK 20260905000000_add_claims.sql (18.34ms)7362026/09/23 09:31:45 OK 20260905000000_add_claims.sql (9.51ms)7372026/09/23 09:31:45 OK 20260905000000_add_claims.sql (9.65ms)7382026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (9.39ms)7392026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007402026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (8.14ms)7412026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007422026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (9.15ms)7432026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007442026/09/23 09:31:45 OK 1_commit_pending_closure.sql (3.46ms)7452026/09/23 09:31:45 OK 1_commit_pending_closure.sql (4.05ms)7462026/09/23 09:31:45 OK 2_object_stats_trigger.sql (679.33µs)7472026/09/23 09:31:45 goose: up to current file version: 27482026/09/23 09:31:45 OK 1_commit_pending_closure.sql (3.76ms)7492026/09/23 09:31:45 OK 2_object_stats_trigger.sql (495.88µs)7502026/09/23 09:31:45 goose: up to current file version: 27512026/09/23 09:31:45 OK 2_object_stats_trigger.sql (449.63µs)7522026/09/23 09:31:45 goose: up to current file version: 27532026/09/23 09:31:45 OK 20241026095416_initial_model.sql (44.29ms)7542026/09/23 09:31:45 OK 20251210153512_drop_unused_gin_index.sql (11.44ms)7552026/09/23 09:31:45 INFO Received uploads request method=POST path=/api/pending_closures7562026/09/23 09:31:45 OK 20251218171726_add_pins.sql (2.52ms)7572026/09/23 09:31:45 OK 20260628120000_add_object_size_and_stats.sql (5.26ms)7582026/09/23 09:31:45 OK 20260905000000_add_claims.sql (41.12ms)7592026/09/23 09:31:45 OK 20260920000000_drop_claims.sql (23.88ms)7602026/09/23 09:31:45 goose: successfully migrated database to version: 202609200000007612026/09/23 09:31:46 OK 1_commit_pending_closure.sql (1.83ms)7622026/09/23 09:31:46 OK 2_object_stats_trigger.sql (567.25µs)7632026/09/23 09:31:46 goose: up to current file version: 27642026/09/23 09:31:46 INFO Received uploads request method=POST path=/api/pending_closures7652026/09/23 09:31:46 INFO Received uploads request method=POST path=/api/pending_closures7662026/09/23 09:31:46 INFO Received uploads request method=POST path=/api/pending_closures7672026/09/23 09:31:46 INFO Received uploads request method=POST path=/api/pending_closures7682026/09/23 09:31:46 INFO Received cleanup request method=DELETE path=/api/pending_closures7692026/09/23 09:31:46 INFO Aborted multipart uploads count=1770--- PASS: TestMultipartCleanup (1.16s)771=== CONT TestCompleteMultipartUpload_ErrorButObjectExists772--- PASS: TestService_Rustfstest (1.28s)773=== CONT TestRedundantMultipartUpload7742026-09-23 09:31:46.869 UTC [63903] ERROR: relation "goose_db_version" does not exist at character 367752026-09-23 09:31:46.869 UTC [63903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7762026-09-23 09:31:46.876 UTC [63907] ERROR: relation "goose_db_version" does not exist at character 367772026-09-23 09:31:46.876 UTC [63907] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026/09/23 09:31:46 OK 20241026095416_initial_model.sql (6.6ms)7792026/09/23 09:31:46 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)7802026/09/23 09:31:46 OK 20251218171726_add_pins.sql (3.71ms)7812026/09/23 09:31:46 OK 20260628120000_add_object_size_and_stats.sql (4.91ms)7822026/09/23 09:31:46 OK 20260905000000_add_claims.sql (19.62ms)7832026/09/23 09:31:46 OK 20260920000000_drop_claims.sql (1.74ms)7842026/09/23 09:31:46 goose: successfully migrated database to version: 202609200000007852026/09/23 09:31:46 OK 1_commit_pending_closure.sql (2.02ms)7862026/09/23 09:31:46 OK 2_object_stats_trigger.sql (592.96µs)7872026/09/23 09:31:46 goose: up to current file version: 27882026/09/23 09:31:46 OK 20241026095416_initial_model.sql (55.81ms)7892026/09/23 09:31:46 OK 20251210153512_drop_unused_gin_index.sql (6.99ms)7902026/09/23 09:31:46 OK 20251218171726_add_pins.sql (3.71ms)7912026/09/23 09:31:46 OK 20260628120000_add_object_size_and_stats.sql (7.23ms)7922026/09/23 09:31:46 OK 20260905000000_add_claims.sql (2.76ms)7932026/09/23 09:31:46 OK 20260920000000_drop_claims.sql (1.3ms)7942026/09/23 09:31:46 goose: successfully migrated database to version: 202609200000007952026/09/23 09:31:46 OK 1_commit_pending_closure.sql (1.91ms)7962026/09/23 09:31:46 OK 2_object_stats_trigger.sql (557.33µs)7972026/09/23 09:31:46 goose: up to current file version: 27982026/09/23 09:31:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7992026/09/23 09:31:47 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst800--- PASS: TestCompleteMultipartUnregistered (1.65s)801=== CONT TestReadRedirectUsesPublicS3URL8022026/09/23 09:31:47 INFO Received uploads request method=POST path=/api/pending_closures8032026-09-23 09:31:47.370 UTC [64020] ERROR: relation "goose_db_version" does not exist at character 368042026-09-23 09:31:47.370 UTC [64020] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8052026/09/23 09:31:47 OK 20241026095416_initial_model.sql (3.55ms)8062026/09/23 09:31:47 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)8072026/09/23 09:31:47 OK 20251218171726_add_pins.sql (2.29ms)8082026/09/23 09:31:47 OK 20260628120000_add_object_size_and_stats.sql (1.17ms)8092026/09/23 09:31:47 OK 20260905000000_add_claims.sql (1.3ms)8102026/09/23 09:31:47 OK 20260920000000_drop_claims.sql (1.73ms)8112026/09/23 09:31:47 goose: successfully migrated database to version: 202609200000008122026/09/23 09:31:47 OK 1_commit_pending_closure.sql (1.94ms)8132026/09/23 09:31:47 OK 2_object_stats_trigger.sql (1.25ms)8142026/09/23 09:31:47 goose: up to current file version: 28152026/09/23 09:31:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8162026/09/23 09:31:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MTM5NzAyMmYtNzI0Ni00MzM0LWFmOTYtMjJmYmViMTQ5MDM4LjIxNGM5YjQzLTE4ZjktNDhmOS1iOGY5LTNkYzRmZTcwNDI4ZngxNzkwMTU1OTA1OTY5NTUxMDAw parts=108172026/09/23 09:31:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8182026/09/23 09:31:47 INFO Completed upload id=18192026/09/23 09:31:47 INFO Received uploads request method=POST path=/api/pending_closures8202026/09/23 09:31:47 INFO Received uploads request method=POST path=/api/pending_closures8212026/09/23 09:31:47 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8222026/09/23 09:31:47 WARN Found objects in DB but missing from S3, will re-upload count=1823--- PASS: TestService_verifyS3Integrity (2.21s)824=== CONT TestReadProxyRangeRequest8252026/09/23 09:31:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8262026/09/23 09:31:47 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MTM5NzAyMmYtNzI0Ni00MzM0LWFmOTYtMjJmYmViMTQ5MDM4LjM5NDBhMjRmLTNlOGEtNDMxZC1iZGU5LWRmNjBkYjU0Y2M1YXgxNzkwMTU1OTA2MTMwMDk3MDAw parts=108272026/09/23 09:31:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete828--- PASS: TestReadRedirectKeepsNarinfoProxied (2.33s)829=== CONT TestReadRedirectNar8302026/09/23 09:31:47 INFO Completed upload id=18312026/09/23 09:31:47 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008322026/09/23 09:31:47 INFO Received uploads request method=POST path=/api/pending_closures8332026/09/23 09:31:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures8342026/09/23 09:31:47 INFO Aborted multipart uploads count=08352026/09/23 09:31:47 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=08362026/09/23 09:31:47 INFO Vacuumed table table=pending_closures8372026/09/23 09:31:47 INFO Vacuumed table table=pending_objects8382026/09/23 09:31:47 INFO Vacuumed table table=multipart_uploads8392026/09/23 09:31:47 INFO Vacuumed table table=closures8402026/09/23 09:31:47 INFO Vacuumed table table=objects8412026/09/23 09:31:47 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000842--- PASS: TestService_createPendingClosureHandler (2.43s)843=== CONT TestReadProxyDisabled8442026/09/23 09:31:48 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"845--- PASS: TestService_AuthMiddleware (2.61s)846=== CONT TestReadProxyRootRedirectsToIndexHTML8472026-09-23 09:31:48.182 UTC [64198] ERROR: relation "goose_db_version" does not exist at character 368482026-09-23 09:31:48.182 UTC [64198] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8492026-09-23 09:31:48.182 UTC [64200] ERROR: relation "goose_db_version" does not exist at character 368502026-09-23 09:31:48.182 UTC [64200] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8512026/09/23 09:31:48 OK 20241026095416_initial_model.sql (11.28ms)8522026/09/23 09:31:48 OK 20241026095416_initial_model.sql (11.04ms)8532026/09/23 09:31:48 OK 20251210153512_drop_unused_gin_index.sql (828.25µs)8542026/09/23 09:31:48 OK 20251210153512_drop_unused_gin_index.sql (901.58µs)8552026/09/23 09:31:48 OK 20251218171726_add_pins.sql (2.34ms)8562026/09/23 09:31:48 OK 20251218171726_add_pins.sql (2.29ms)8572026/09/23 09:31:48 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)8582026/09/23 09:31:48 OK 20260628120000_add_object_size_and_stats.sql (2.76ms)8592026/09/23 09:31:48 OK 20260905000000_add_claims.sql (2.59ms)8602026/09/23 09:31:48 OK 20260905000000_add_claims.sql (2.81ms)8612026/09/23 09:31:48 OK 20260920000000_drop_claims.sql (1.82ms)8622026/09/23 09:31:48 goose: successfully migrated database to version: 202609200000008632026/09/23 09:31:48 OK 20260920000000_drop_claims.sql (1.74ms)8642026/09/23 09:31:48 goose: successfully migrated database to version: 202609200000008652026/09/23 09:31:48 OK 1_commit_pending_closure.sql (1.94ms)8662026/09/23 09:31:48 OK 1_commit_pending_closure.sql (2.17ms)8672026/09/23 09:31:48 OK 2_object_stats_trigger.sql (719µs)8682026/09/23 09:31:48 goose: up to current file version: 28692026/09/23 09:31:48 OK 2_object_stats_trigger.sql (735.67µs)8702026/09/23 09:31:48 goose: up to current file version: 28712026-09-23 09:31:48.279 UTC [64220] ERROR: relation "goose_db_version" does not exist at character 368722026-09-23 09:31:48.279 UTC [64220] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8732026/09/23 09:31:48 OK 20241026095416_initial_model.sql (45.8ms)8742026/09/23 09:31:48 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)8752026/09/23 09:31:48 OK 20251218171726_add_pins.sql (22.33ms)8762026/09/23 09:31:48 INFO Received uploads request method=POST path=/api/pending_closures8772026/09/23 09:31:48 OK 20260628120000_add_object_size_and_stats.sql (20.3ms)8782026/09/23 09:31:48 OK 20260905000000_add_claims.sql (69.73ms)879--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.07s)880=== CONT TestGCMetrics8812026/09/23 09:31:48 OK 20260920000000_drop_claims.sql (3.67ms)8822026/09/23 09:31:48 goose: successfully migrated database to version: 202609200000008832026/09/23 09:31:48 OK 1_commit_pending_closure.sql (8.78ms)8842026/09/23 09:31:48 OK 2_object_stats_trigger.sql (619.17µs)8852026/09/23 09:31:48 goose: up to current file version: 28862026-09-23 09:31:48.547 UTC [64275] ERROR: relation "goose_db_version" does not exist at character 368872026-09-23 09:31:48.547 UTC [64275] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8882026/09/23 09:31:48 OK 20241026095416_initial_model.sql (30.53ms)8892026/09/23 09:31:48 OK 20251210153512_drop_unused_gin_index.sql (5.4ms)8902026/09/23 09:31:48 OK 20251218171726_add_pins.sql (20.15ms)8912026/09/23 09:31:48 OK 20260628120000_add_object_size_and_stats.sql (3.17ms)8922026/09/23 09:31:48 OK 20260905000000_add_claims.sql (3.03ms)8932026/09/23 09:31:48 OK 20260920000000_drop_claims.sql (2.8ms)8942026/09/23 09:31:48 goose: successfully migrated database to version: 202609200000008952026/09/23 09:31:48 OK 1_commit_pending_closure.sql (1.79ms)8962026/09/23 09:31:48 OK 2_object_stats_trigger.sql (874.92µs)8972026/09/23 09:31:48 goose: up to current file version: 28982026/09/23 09:31:48 INFO Received uploads request method=POST path=/api/pending_closures8992026-09-23 09:31:48.771 UTC [64318] ERROR: relation "goose_db_version" does not exist at character 369002026-09-23 09:31:48.771 UTC [64318] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9012026/09/23 09:31:48 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9022026/09/23 09:31:48 INFO Received uploads request method=POST path=/api/pending_closures903--- PASS: TestPresignedUploadRegisteredBeforeCommit (3.37s)904=== CONT TestReadProxyConditionalGet9052026/09/23 09:31:48 OK 20241026095416_initial_model.sql (68.36ms)9062026/09/23 09:31:48 OK 20251210153512_drop_unused_gin_index.sql (7.58ms)9072026/09/23 09:31:48 OK 20251218171726_add_pins.sql (25.84ms)9082026/09/23 09:31:48 OK 20260628120000_add_object_size_and_stats.sql (8.66ms)9092026/09/23 09:31:48 OK 20260905000000_add_claims.sql (10.21ms)9102026/09/23 09:31:48 OK 20260920000000_drop_claims.sql (17.83ms)9112026/09/23 09:31:48 goose: successfully migrated database to version: 202609200000009122026/09/23 09:31:48 OK 1_commit_pending_closure.sql (2.87ms)9132026/09/23 09:31:48 OK 2_object_stats_trigger.sql (508.17µs)9142026/09/23 09:31:48 goose: up to current file version: 29152026/09/23 09:31:49 INFO Received uploads request method=POST path=/api/pending_closures9162026/09/23 09:31:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9172026/09/23 09:31:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9182026/09/23 09:31:49 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTM5NzAyMmYtNzI0Ni00MzM0LWFmOTYtMjJmYmViMTQ5MDM4LjQxY2RmZDFlLTQ2YjMtNDE3Ni05N2QyLTNlOGI2YmJmMWM1NngxNzkwMTU1OTA5MDE5Mjc0MDAw9192026/09/23 09:31:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTM5NzAyMmYtNzI0Ni00MzM0LWFmOTYtMjJmYmViMTQ5MDM4LjQxY2RmZDFlLTQ2YjMtNDE3Ni05N2QyLTNlOGI2YmJmMWM1NngxNzkwMTU1OTA5MDE5Mjc0MDAw parts=1920--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.65s)921=== CONT TestReadProxyHead9222026/09/23 09:31:49 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MTM5NzAyMmYtNzI0Ni00MzM0LWFmOTYtMjJmYmViMTQ5MDM4LjhlYjY1YzFkLTMwZmMtNGEyNi1iNGJmLTBiMjBiNTU4Y2ZhNHgxNzkwMTU1OTA3MzQ1NzE2MDAw parts=129232026/09/23 09:31:49 INFO Received uploads request method=POST path=/api/pending_closures924--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.85s)925=== CONT TestServerTLSConfig926=== RUN TestServerTLSConfig/no_client_CA927=== PAUSE TestServerTLSConfig/no_client_CA928=== RUN TestServerTLSConfig/missing_CA_file929=== PAUSE TestServerTLSConfig/missing_CA_file930=== RUN TestServerTLSConfig/not_a_PEM_file931=== PAUSE TestServerTLSConfig/not_a_PEM_file932=== CONT TestService_NativeMTLS9332026/09/23 09:31:49 INFO Received uploads request method=POST path=/api/pending_closures9342026/09/23 09:31:49 INFO Received uploads request method=POST path=/api/pending_closures9352026-09-23 09:31:49.424 UTC [64465] ERROR: relation "goose_db_version" does not exist at character 369362026-09-23 09:31:49.424 UTC [64465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9372026/09/23 09:31:49 OK 20241026095416_initial_model.sql (44.28ms)9382026/09/23 09:31:49 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)9392026/09/23 09:31:49 OK 20251218171726_add_pins.sql (12.71ms)9402026/09/23 09:31:49 OK 20260628120000_add_object_size_and_stats.sql (26.19ms)9412026/09/23 09:31:49 OK 20260905000000_add_claims.sql (6.62ms)9422026/09/23 09:31:49 OK 20260920000000_drop_claims.sql (2.81ms)9432026/09/23 09:31:49 goose: successfully migrated database to version: 202609200000009442026/09/23 09:31:49 OK 1_commit_pending_closure.sql (2.64ms)9452026/09/23 09:31:49 OK 2_object_stats_trigger.sql (796.5µs)9462026/09/23 09:31:49 goose: up to current file version: 29472026-09-23 09:31:49.643 UTC [64526] ERROR: relation "goose_db_version" does not exist at character 369482026-09-23 09:31:49.643 UTC [64526] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9492026-09-23 09:31:49.644 UTC [64527] ERROR: relation "goose_db_version" does not exist at character 369502026-09-23 09:31:49.644 UTC [64527] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9512026/09/23 09:31:49 OK 20241026095416_initial_model.sql (16.07ms)9522026/09/23 09:31:49 OK 20241026095416_initial_model.sql (16.08ms)9532026/09/23 09:31:49 OK 20251210153512_drop_unused_gin_index.sql (977.21µs)9542026/09/23 09:31:49 OK 20251210153512_drop_unused_gin_index.sql (942.38µs)9552026/09/23 09:31:49 OK 20251218171726_add_pins.sql (2.04ms)9562026/09/23 09:31:49 OK 20251218171726_add_pins.sql (1.98ms)9572026/09/23 09:31:49 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)9582026/09/23 09:31:49 OK 20260628120000_add_object_size_and_stats.sql (2.05ms)9592026/09/23 09:31:49 OK 20260905000000_add_claims.sql (1.83ms)9602026/09/23 09:31:49 OK 20260905000000_add_claims.sql (11.73ms)9612026/09/23 09:31:49 OK 20260920000000_drop_claims.sql (15.99ms)9622026/09/23 09:31:49 goose: successfully migrated database to version: 20260920000000963--- PASS: TestReadRedirectUsesPublicS3URL (2.65s)964=== CONT TestReadProxyInvalidPath9652026/09/23 09:31:49 OK 1_commit_pending_closure.sql (3.01ms)9662026/09/23 09:31:49 OK 2_object_stats_trigger.sql (947.71µs)9672026/09/23 09:31:49 goose: up to current file version: 29682026/09/23 09:31:49 OK 20260920000000_drop_claims.sql (16.62ms)9692026/09/23 09:31:49 goose: successfully migrated database to version: 202609200000009702026/09/23 09:31:49 OK 1_commit_pending_closure.sql (2.08ms)9712026/09/23 09:31:49 OK 2_object_stats_trigger.sql (770.71µs)9722026/09/23 09:31:49 goose: up to current file version: 2973--- PASS: TestReadRedirectNar (2.20s)974=== CONT TestReadProxy404975--- PASS: TestReadProxyRangeRequest (2.61s)976=== CONT TestMetricsInventory9772026-09-23 09:31:50.394 UTC [64697] ERROR: relation "goose_db_version" does not exist at character 369782026-09-23 09:31:50.394 UTC [64697] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9792026/09/23 09:31:50 OK 20241026095416_initial_model.sql (11.08ms)9802026/09/23 09:31:50 OK 20251210153512_drop_unused_gin_index.sql (845.46µs)9812026/09/23 09:31:50 OK 20251218171726_add_pins.sql (2.11ms)9822026/09/23 09:31:50 OK 20260628120000_add_object_size_and_stats.sql (34.19ms)9832026/09/23 09:31:50 OK 20260905000000_add_claims.sql (13.36ms)9842026/09/23 09:31:50 OK 20260920000000_drop_claims.sql (16.15ms)9852026/09/23 09:31:50 goose: successfully migrated database to version: 202609200000009862026/09/23 09:31:50 OK 1_commit_pending_closure.sql (2.58ms)9872026/09/23 09:31:50 OK 2_object_stats_trigger.sql (345.08µs)9882026/09/23 09:31:50 goose: up to current file version: 29892026-09-23 09:31:50.501 UTC [64711] ERROR: relation "goose_db_version" does not exist at character 369902026-09-23 09:31:50.501 UTC [64711] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9912026/09/23 09:31:50 OK 20241026095416_initial_model.sql (28.89ms)9922026/09/23 09:31:50 OK 20251210153512_drop_unused_gin_index.sql (3.9ms)9932026/09/23 09:31:50 OK 20251218171726_add_pins.sql (11.56ms)9942026/09/23 09:31:50 OK 20260628120000_add_object_size_and_stats.sql (5.35ms)9952026/09/23 09:31:50 OK 20260905000000_add_claims.sql (2.54ms)9962026/09/23 09:31:50 OK 20260920000000_drop_claims.sql (7.01ms)9972026/09/23 09:31:50 goose: successfully migrated database to version: 202609200000009982026/09/23 09:31:50 OK 1_commit_pending_closure.sql (3.09ms)9992026/09/23 09:31:50 OK 2_object_stats_trigger.sql (1.73ms)10002026/09/23 09:31:50 goose: up to current file version: 21001--- PASS: TestReadProxyDisabled (2.74s)1002=== CONT TestNARDeduplicationMetadataUploadBug10032026-09-23 09:31:50.683 UTC [64754] ERROR: relation "goose_db_version" does not exist at character 3610042026-09-23 09:31:50.683 UTC [64754] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10052026/09/23 09:31:50 OK 20241026095416_initial_model.sql (9.18ms)10062026/09/23 09:31:50 OK 20251210153512_drop_unused_gin_index.sql (531.79µs)10072026/09/23 09:31:50 OK 20251218171726_add_pins.sql (1.27ms)10082026/09/23 09:31:50 OK 20260628120000_add_object_size_and_stats.sql (2.04ms)10092026/09/23 09:31:50 OK 20260905000000_add_claims.sql (3.47ms)10102026/09/23 09:31:50 OK 20260920000000_drop_claims.sql (1.05ms)10112026/09/23 09:31:50 goose: successfully migrated database to version: 2026092000000010122026/09/23 09:31:50 OK 1_commit_pending_closure.sql (1.82ms)10132026/09/23 09:31:50 OK 2_object_stats_trigger.sql (600.63µs)10142026/09/23 09:31:50 goose: up to current file version: 21015--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.86s)1016=== CONT TestReadProxyNarStreaming10172026/09/23 09:31:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10182026-09-23 09:31:51.068 UTC [64836] ERROR: relation "goose_db_version" does not exist at character 3610192026-09-23 09:31:51.068 UTC [64836] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10202026/09/23 09:31:51 OK 20241026095416_initial_model.sql (46.54ms)10212026/09/23 09:31:51 OK 20251210153512_drop_unused_gin_index.sql (967.83µs)10222026/09/23 09:31:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MTM5NzAyMmYtNzI0Ni00MzM0LWFmOTYtMjJmYmViMTQ5MDM4LjhjOGJjOTMxLWVhNjEtNDVkNC1hMjI2LTM4MjgzNzQ1NzlmYngxNzkwMTU1OTA5MzQyNDY3MDAw parts=121023--- PASS: TestRedundantMultipartUpload (4.48s)1024=== CONT TestReadProxyNarinfoAlreadyDecompressed10252026/09/23 09:31:51 INFO Aborted multipart uploads count=010262026/09/23 09:31:51 OK 20251218171726_add_pins.sql (17.8ms)10272026/09/23 09:31:51 WARN Force mode enabled - objects will be deleted immediately without grace period10282026/09/23 09:31:51 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=010292026/09/23 09:31:51 INFO Vacuumed table table=pending_closures10302026/09/23 09:31:51 INFO Vacuumed table table=pending_objects10312026/09/23 09:31:51 INFO Vacuumed table table=multipart_uploads10322026/09/23 09:31:51 INFO Vacuumed table table=closures10332026/09/23 09:31:51 INFO Vacuumed table table=objects1034--- PASS: TestGCMetrics (2.71s)1035=== CONT TestReadProxyNarinfo10362026/09/23 09:31:51 OK 20260628120000_add_object_size_and_stats.sql (16.89ms)10372026/09/23 09:31:51 OK 20260905000000_add_claims.sql (32.44ms)10382026/09/23 09:31:51 OK 20260920000000_drop_claims.sql (27.69ms)10392026/09/23 09:31:51 goose: successfully migrated database to version: 2026092000000010402026/09/23 09:31:51 OK 1_commit_pending_closure.sql (3.74ms)10412026/09/23 09:31:51 OK 2_object_stats_trigger.sql (615.21µs)10422026/09/23 09:31:51 goose: up to current file version: 21043--- PASS: TestReadProxyConditionalGet (2.64s)1044=== CONT TestIsValidCachePath1045=== RUN TestIsValidCachePath/narinfo1046=== PAUSE TestIsValidCachePath/narinfo1047=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1048=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1049=== RUN TestIsValidCachePath/nar_zst1050=== PAUSE TestIsValidCachePath/nar_zst1051=== RUN TestIsValidCachePath/nar_xz1052=== PAUSE TestIsValidCachePath/nar_xz1053=== RUN TestIsValidCachePath/nar_bz21054=== PAUSE TestIsValidCachePath/nar_bz21055=== RUN TestIsValidCachePath/nar_uncompressed1056=== PAUSE TestIsValidCachePath/nar_uncompressed1057=== RUN TestIsValidCachePath/ls1058=== PAUSE TestIsValidCachePath/ls1059=== RUN TestIsValidCachePath/log1060=== PAUSE TestIsValidCachePath/log1061=== RUN TestIsValidCachePath/realisation1062=== PAUSE TestIsValidCachePath/realisation1063=== RUN TestIsValidCachePath/nix-cache-info1064=== PAUSE TestIsValidCachePath/nix-cache-info1065=== RUN TestIsValidCachePath/index.html1066=== PAUSE TestIsValidCachePath/index.html1067=== RUN TestIsValidCachePath/traversal_parent1068=== PAUSE TestIsValidCachePath/traversal_parent1069=== RUN TestIsValidCachePath/traversal_in_middle1070=== PAUSE TestIsValidCachePath/traversal_in_middle1071=== RUN TestIsValidCachePath/invalid_char_e1072=== PAUSE TestIsValidCachePath/invalid_char_e1073=== RUN TestIsValidCachePath/invalid_char_u1074=== PAUSE TestIsValidCachePath/invalid_char_u1075=== RUN TestIsValidCachePath/random_path1076=== PAUSE TestIsValidCachePath/random_path1077=== RUN TestIsValidCachePath/empty1078=== PAUSE TestIsValidCachePath/empty1079=== RUN TestIsValidCachePath/leading_slash1080=== PAUSE TestIsValidCachePath/leading_slash1081=== RUN TestIsValidCachePath/wrong_extension1082=== PAUSE TestIsValidCachePath/wrong_extension1083=== RUN TestIsValidCachePath/short_hash1084=== PAUSE TestIsValidCachePath/short_hash1085=== CONT TestParseSingleRange1086=== RUN TestParseSingleRange/none1087=== PAUSE TestParseSingleRange/none1088=== RUN TestParseSingleRange/unknown_unit1089=== PAUSE TestParseSingleRange/unknown_unit1090=== RUN TestParseSingleRange/multi-range_ignored1091=== PAUSE TestParseSingleRange/multi-range_ignored1092=== RUN TestParseSingleRange/malformed_no_dash1093=== PAUSE TestParseSingleRange/malformed_no_dash1094=== RUN TestParseSingleRange/malformed_both_empty1095=== PAUSE TestParseSingleRange/malformed_both_empty1096=== RUN TestParseSingleRange/malformed_end_before_start1097=== PAUSE TestParseSingleRange/malformed_end_before_start1098=== RUN TestParseSingleRange/closed1099=== PAUSE TestParseSingleRange/closed1100=== RUN TestParseSingleRange/open-ended1101=== PAUSE TestParseSingleRange/open-ended1102=== RUN TestParseSingleRange/end_clamped_to_size1103=== PAUSE TestParseSingleRange/end_clamped_to_size1104=== RUN TestParseSingleRange/suffix1105=== PAUSE TestParseSingleRange/suffix1106=== RUN TestParseSingleRange/suffix_exceeds_size1107=== PAUSE TestParseSingleRange/suffix_exceeds_size1108=== RUN TestParseSingleRange/single_byte1109=== PAUSE TestParseSingleRange/single_byte1110=== RUN TestParseSingleRange/start_past_EOF1111=== PAUSE TestParseSingleRange/start_past_EOF1112=== RUN TestParseSingleRange/start_far_past_EOF1113=== PAUSE TestParseSingleRange/start_far_past_EOF1114=== CONT TestCreatePin_ReservedPins1115--- PASS: TestReadProxyHead (2.48s)1116=== CONT TestResurrectedObjectNotDeleted11172026-09-23 09:31:51.778 UTC [64994] ERROR: relation "goose_db_version" does not exist at character 3611182026-09-23 09:31:51.778 UTC [64994] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11192026/09/23 09:31:51 OK 20241026095416_initial_model.sql (63.61ms)11202026/09/23 09:31:51 OK 20251210153512_drop_unused_gin_index.sql (10.97ms)11212026/09/23 09:31:51 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11222026/09/23 09:31:51 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1123--- PASS: TestService_NativeMTLS (2.65s)1124=== CONT TestCreatePendingClosureRejectsOversizedNAR11252026/09/23 09:31:51 INFO Received uploads request method=POST path=/api/pending_closures1126--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1127=== CONT TestCacheConfigHandlerMaxNarSize1128--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1129=== CONT TestOrphanedObjectsGCStressTest11302026/09/23 09:31:51 OK 20251218171726_add_pins.sql (23.63ms)11312026/09/23 09:31:51 OK 20260628120000_add_object_size_and_stats.sql (59.18ms)11322026/09/23 09:31:52 OK 20260905000000_add_claims.sql (41.67ms)11332026/09/23 09:31:52 OK 20260920000000_drop_claims.sql (13.99ms)11342026/09/23 09:31:52 goose: successfully migrated database to version: 2026092000000011352026/09/23 09:31:52 OK 1_commit_pending_closure.sql (1.96ms)11362026/09/23 09:31:52 OK 2_object_stats_trigger.sql (541.13µs)11372026/09/23 09:31:52 goose: up to current file version: 211382026-09-23 09:31:52.131 UTC [65063] ERROR: relation "goose_db_version" does not exist at character 3611392026-09-23 09:31:52.131 UTC [65063] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1140--- PASS: TestReadProxyInvalidPath (2.45s)1141=== CONT TestGenerateLandingPage1142--- PASS: TestGenerateLandingPage (0.00s)1143=== CONT TestOrphanedObjectsGC11442026-09-23 09:31:52.243 UTC [65094] ERROR: relation "goose_db_version" does not exist at character 3611452026-09-23 09:31:52.243 UTC [65094] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11462026/09/23 09:31:52 OK 20241026095416_initial_model.sql (95.61ms)11472026/09/23 09:31:52 OK 20251210153512_drop_unused_gin_index.sql (9.3ms)11482026/09/23 09:31:52 OK 20251218171726_add_pins.sql (35.6ms)11492026/09/23 09:31:52 OK 20260628120000_add_object_size_and_stats.sql (21.12ms)11502026/09/23 09:31:52 OK 20260905000000_add_claims.sql (37.07ms)11512026/09/23 09:31:52 OK 20241026095416_initial_model.sql (82.98ms)11522026/09/23 09:31:52 OK 20251210153512_drop_unused_gin_index.sql (15.27ms)11532026/09/23 09:31:52 OK 20260920000000_drop_claims.sql (27.49ms)11542026/09/23 09:31:52 goose: successfully migrated database to version: 2026092000000011552026/09/23 09:31:52 OK 1_commit_pending_closure.sql (1.11ms)11562026/09/23 09:31:52 OK 2_object_stats_trigger.sql (372µs)11572026/09/23 09:31:52 goose: up to current file version: 211582026/09/23 09:31:52 OK 20251218171726_add_pins.sql (19.09ms)11592026/09/23 09:31:52 OK 20260628120000_add_object_size_and_stats.sql (28.83ms)1160--- PASS: TestReadProxy404 (2.53s)1161=== CONT TestService_readinessHandler11622026/09/23 09:31:52 OK 20260905000000_add_claims.sql (18.83ms)11632026/09/23 09:31:52 OK 20260920000000_drop_claims.sql (39.85ms)11642026/09/23 09:31:52 goose: successfully migrated database to version: 2026092000000011652026/09/23 09:31:52 OK 1_commit_pending_closure.sql (2.16ms)11662026/09/23 09:31:52 OK 2_object_stats_trigger.sql (662.25µs)11672026/09/23 09:31:52 goose: up to current file version: 21168--- PASS: TestMetricsInventory (2.51s)1169=== CONT TestService_healthCheckHandler11702026-09-23 09:31:52.804 UTC [65206] ERROR: relation "goose_db_version" does not exist at character 3611712026-09-23 09:31:52.804 UTC [65206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11722026-09-23 09:31:52.874 UTC [65224] ERROR: relation "goose_db_version" does not exist at character 3611732026-09-23 09:31:52.874 UTC [65224] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11742026/09/23 09:31:52 OK 20241026095416_initial_model.sql (90.96ms)11752026/09/23 09:31:52 OK 20251210153512_drop_unused_gin_index.sql (19.49ms)11762026/09/23 09:31:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54083/oidc11772026/09/23 09:31:53 OK 20251218171726_add_pins.sql (76.43ms)11782026/09/23 09:31:53 OK 20241026095416_initial_model.sql (133.43ms)11792026/09/23 09:31:53 OK 20260628120000_add_object_size_and_stats.sql (42.24ms)11802026/09/23 09:31:53 OK 20251210153512_drop_unused_gin_index.sql (20.68ms)11812026/09/23 09:31:53 OK 20260905000000_add_claims.sql (6.34ms)11822026/09/23 09:31:53 OK 20251218171726_add_pins.sql (4.96ms)11832026/09/23 09:31:53 OK 20260920000000_drop_claims.sql (20.39ms)11842026/09/23 09:31:53 goose: successfully migrated database to version: 2026092000000011852026/09/23 09:31:53 OK 1_commit_pending_closure.sql (2.73ms)11862026/09/23 09:31:53 OK 2_object_stats_trigger.sql (801.42µs)11872026/09/23 09:31:53 goose: up to current file version: 211882026/09/23 09:31:53 OK 20260628120000_add_object_size_and_stats.sql (27.19ms)11892026/09/23 09:31:53 OK 20260905000000_add_claims.sql (33.73ms)11902026/09/23 09:31:53 OK 20260920000000_drop_claims.sql (47.2ms)11912026/09/23 09:31:53 goose: successfully migrated database to version: 2026092000000011922026/09/23 09:31:53 OK 1_commit_pending_closure.sql (2.24ms)11932026/09/23 09:31:53 OK 2_object_stats_trigger.sql (607.29µs)11942026/09/23 09:31:53 goose: up to current file version: 21195--- PASS: TestReadProxyNarStreaming (2.37s)1196=== CONT TestObjectStatsTrigger11972026-09-23 09:31:53.325 UTC [65309] ERROR: relation "goose_db_version" does not exist at character 3611982026-09-23 09:31:53.325 UTC [65309] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1199=== NAME TestNARDeduplicationMetadataUploadBug1200 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-52991-3138667589/TestNARDeduplicationMetadataUploadBug3477823743/001/store/v2grm2mp012y01b4nspddydk2l6ci2y6-file1.txt12012026/09/23 09:31:53 OK 20241026095416_initial_model.sql (71.69ms)12022026/09/23 09:31:53 OK 20251210153512_drop_unused_gin_index.sql (17.43ms)12032026/09/23 09:31:53 OK 20251218171726_add_pins.sql (18.22ms)12042026/09/23 09:31:53 OK 20260628120000_add_object_size_and_stats.sql (38.83ms)1205--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.40s)1206=== CONT TestGracefulShutdownDrainsInflight12072026/09/23 09:31:53 INFO Starting HTTP server address=127.0.0.1:5409112082026/09/23 09:31:53 INFO Shutdown signal received, draining in-flight requests timeout=10s12092026/09/23 09:31:53 OK 20260905000000_add_claims.sql (86.82ms)1210--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1211=== CONT TestIsValidUploadKey1212=== RUN TestIsValidUploadKey/narinfo1213=== PAUSE TestIsValidUploadKey/narinfo1214=== RUN TestIsValidUploadKey/nar_zst1215=== PAUSE TestIsValidUploadKey/nar_zst1216=== RUN TestIsValidUploadKey/nar_xz1217=== PAUSE TestIsValidUploadKey/nar_xz1218=== RUN TestIsValidUploadKey/nar_plain1219=== PAUSE TestIsValidUploadKey/nar_plain1220=== RUN TestIsValidUploadKey/listing1221=== PAUSE TestIsValidUploadKey/listing1222=== RUN TestIsValidUploadKey/build_log1223=== PAUSE TestIsValidUploadKey/build_log1224=== RUN TestIsValidUploadKey/build_log_home-manager_file1225=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1226=== RUN TestIsValidUploadKey/build_log_plus_in_name1227=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1228=== RUN TestIsValidUploadKey/build_log_question_mark1229=== PAUSE TestIsValidUploadKey/build_log_question_mark1230=== RUN TestIsValidUploadKey/build_log_equals1231=== PAUSE TestIsValidUploadKey/build_log_equals1232=== RUN TestIsValidUploadKey/realisation1233=== PAUSE TestIsValidUploadKey/realisation1234=== RUN TestIsValidUploadKey/realisation_plus_in_output1235=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1236=== RUN TestIsValidUploadKey/nix-cache-info1237=== PAUSE TestIsValidUploadKey/nix-cache-info1238=== RUN TestIsValidUploadKey/index.html1239=== PAUSE TestIsValidUploadKey/index.html1240=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1241=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1242=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1243=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1244=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1245=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1246=== RUN TestIsValidUploadKey/traversal1247=== PAUSE TestIsValidUploadKey/traversal1248=== RUN TestIsValidUploadKey/traversal_nar1249=== PAUSE TestIsValidUploadKey/traversal_nar1250=== RUN TestIsValidUploadKey/absolute1251=== PAUSE TestIsValidUploadKey/absolute1252=== RUN TestIsValidUploadKey/empty_key1253=== PAUSE TestIsValidUploadKey/empty_key1254=== RUN TestIsValidUploadKey/unknown_type1255=== PAUSE TestIsValidUploadKey/unknown_type1256=== CONT TestGCTaskStore_Fail1257--- PASS: TestGCTaskStore_Fail (0.00s)1258=== CONT TestGCTaskStore_PhaseUpdates1259--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1260=== CONT TestService_cleanupPendingClosuresHandler12612026/09/23 09:31:53 OK 20260920000000_drop_claims.sql (30.06ms)12622026/09/23 09:31:53 goose: successfully migrated database to version: 2026092000000012632026/09/23 09:31:53 OK 1_commit_pending_closure.sql (4.21ms)12642026/09/23 09:31:53 OK 2_object_stats_trigger.sql (592.79µs)12652026/09/23 09:31:53 goose: up to current file version: 212662026/09/23 09:31:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12672026/09/23 09:31:53 INFO Received uploads request method=POST path=/api/pending_closures12682026/09/23 09:31:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12692026/09/23 09:31:53 INFO Uploading v2grm2mp012y01b4nspddydk2l6ci2y6-file1.txt (160B)12702026-09-23 09:31:53.775 UTC [65394] ERROR: relation "goose_db_version" does not exist at character 3612712026-09-23 09:31:53.775 UTC [65394] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/09/23 09:31:53 WARN Failed to register uploaded object key=v2grm2mp012y01b4nspddydk2l6ci2y6.ls error="server returned 404: 404 page not found\n"12732026/09/23 09:31:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12742026/09/23 09:31:53 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12752026/09/23 09:31:53 INFO Signed narinfos id=1 count=112762026/09/23 09:31:53 INFO Uploading 1 narinfos12772026/09/23 09:31:53 WARN Failed to register uploaded object key=v2grm2mp012y01b4nspddydk2l6ci2y6.narinfo error="server returned 404: 404 page not found\n"12782026/09/23 09:31:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12792026/09/23 09:31:53 INFO Completed upload id=112802026/09/23 09:31:53 INFO Upload complete. (236ms)1281=== NAME TestNARDeduplicationMetadataUploadBug1282 metadata_upload_test.go:54: Retrieved narinfo from S3:1283 StorePath: /nix/var/nix/builds/nix-52991-3138667589/TestNARDeduplicationMetadataUploadBug3477823743/001/store/v2grm2mp012y01b4nspddydk2l6ci2y6-file1.txt1284 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1285 Compression: zstd1286 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1287 NarSize: 1601288 References: 1289 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1290 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1291 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1292 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1293--- PASS: TestReadProxyNarinfo (2.69s)1294=== CONT TestUploadHandlersRejectOversizedBody1295=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1296=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1297=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1298=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1299=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1300=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1301=== CONT TestUploadHandlersRejectInvalidKeys1302=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1303=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1304=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1305=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1306=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1307=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1308=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1309=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1310=== CONT TestGCTaskStore_CompletedAllowsNewTask1311--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1312=== CONT TestGCTaskStore_DeduplicateSameParams1313--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1314=== CONT TestGCTaskStore_ConflictDifferentParams1315--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1316=== CONT TestGCTaskStore_GetReturnsLatest1317--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1318=== CONT TestGCTaskStore_GetEmpty1319--- PASS: TestGCTaskStore_GetEmpty (0.00s)1320=== CONT TestGCTaskStore_StartNew1321--- PASS: TestGCTaskStore_StartNew (0.00s)1322=== CONT TestService_RequireScope_OIDC13232026/09/23 09:31:53 OK 20241026095416_initial_model.sql (123.94ms)13242026/09/23 09:31:53 OK 20251210153512_drop_unused_gin_index.sql (12.37ms)13252026/09/23 09:31:54 OK 20251218171726_add_pins.sql (9.6ms)13262026/09/23 09:31:54 OK 20260628120000_add_object_size_and_stats.sql (30.13ms)13272026-09-23 09:31:54.051 UTC [65448] ERROR: relation "goose_db_version" does not exist at character 3613282026-09-23 09:31:54.051 UTC [65448] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13292026/09/23 09:31:54 OK 20260905000000_add_claims.sql (20.46ms)13302026/09/23 09:31:54 OK 20260920000000_drop_claims.sql (21.89ms)13312026/09/23 09:31:54 goose: successfully migrated database to version: 2026092000000013322026/09/23 09:31:54 OK 1_commit_pending_closure.sql (2.84ms)13332026/09/23 09:31:54 OK 2_object_stats_trigger.sql (369.71µs)13342026/09/23 09:31:54 goose: up to current file version: 21335=== NAME TestNARDeduplicationMetadataUploadBug1336 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-52991-3138667589/TestNARDeduplicationMetadataUploadBug3477823743/001/store/lfhwb12hzpw61xyvvzkk2jic42v47ds8-file2.txt13372026/09/23 09:31:54 OK 20241026095416_initial_model.sql (19.26ms)13382026/09/23 09:31:54 OK 20251210153512_drop_unused_gin_index.sql (6.78ms)13392026-09-23 09:31:54.171 UTC [65474] ERROR: relation "goose_db_version" does not exist at character 3613402026-09-23 09:31:54.171 UTC [65474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13412026/09/23 09:31:54 OK 20251218171726_add_pins.sql (28.33ms)1342--- PASS: TestResurrectedObjectNotDeleted (2.50s)1343=== CONT TestClientErrorHandling1344=== RUN TestClientErrorHandling/InvalidStorePath1345=== PAUSE TestClientErrorHandling/InvalidStorePath1346=== RUN TestClientErrorHandling/InvalidAuthToken1347=== PAUSE TestClientErrorHandling/InvalidAuthToken1348=== RUN TestClientErrorHandling/ServerNotAvailable1349=== PAUSE TestClientErrorHandling/ServerNotAvailable1350=== CONT TestGCBugBareHashReferences13512026/09/23 09:31:54 OK 20260628120000_add_object_size_and_stats.sql (32.81ms)13522026/09/23 09:31:54 OK 20260905000000_add_claims.sql (39.99ms)13532026/09/23 09:31:54 OK 20260920000000_drop_claims.sql (13.3ms)13542026/09/23 09:31:54 goose: successfully migrated database to version: 2026092000000013552026/09/23 09:31:54 OK 1_commit_pending_closure.sql (1.34ms)13562026/09/23 09:31:54 OK 2_object_stats_trigger.sql (738.83µs)13572026/09/23 09:31:54 goose: up to current file version: 213582026/09/23 09:31:54 OK 20241026095416_initial_model.sql (59.03ms)13592026/09/23 09:31:54 OK 20251210153512_drop_unused_gin_index.sql (42.8ms)13602026/09/23 09:31:54 OK 20251218171726_add_pins.sql (19.78ms)13612026/09/23 09:31:54 OK 20260628120000_add_object_size_and_stats.sql (28.92ms)13622026/09/23 09:31:54 OK 20260905000000_add_claims.sql (44.33ms)13632026/09/23 09:31:54 OK 20260920000000_drop_claims.sql (16.11ms)13642026/09/23 09:31:54 goose: successfully migrated database to version: 2026092000000013652026/09/23 09:31:54 OK 1_commit_pending_closure.sql (1.71ms)13662026/09/23 09:31:54 OK 2_object_stats_trigger.sql (308.92µs)13672026/09/23 09:31:54 goose: up to current file version: 213682026-09-23 09:31:54.520 UTC [65552] ERROR: relation "goose_db_version" does not exist at character 3613692026-09-23 09:31:54.520 UTC [65552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13702026/09/23 09:31:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54102/oidc13712026/09/23 09:31:54 OK 20241026095416_initial_model.sql (60.64ms)13722026/09/23 09:31:54 OK 20251210153512_drop_unused_gin_index.sql (25.02ms)13732026/09/23 09:31:54 OK 20251218171726_add_pins.sql (11.62ms)13742026/09/23 09:31:54 OK 20260628120000_add_object_size_and_stats.sql (2.66ms)13752026-09-23 09:31:54.671 UTC [65589] ERROR: relation "goose_db_version" does not exist at character 3613762026-09-23 09:31:54.671 UTC [65589] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13772026/09/23 09:31:54 OK 20260905000000_add_claims.sql (3.14ms)13782026/09/23 09:31:54 OK 20260920000000_drop_claims.sql (1.1ms)13792026/09/23 09:31:54 goose: successfully migrated database to version: 2026092000000013802026/09/23 09:31:54 OK 1_commit_pending_closure.sql (1.28ms)13812026/09/23 09:31:54 OK 2_object_stats_trigger.sql (417.21µs)13822026/09/23 09:31:54 goose: up to current file version: 213832026/09/23 09:31:54 OK 20241026095416_initial_model.sql (31.8ms)13842026/09/23 09:31:54 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)13852026/09/23 09:31:54 OK 20251218171726_add_pins.sql (5.94ms)13862026/09/23 09:31:54 OK 20260628120000_add_object_size_and_stats.sql (55.92ms)13872026/09/23 09:31:54 OK 20260905000000_add_claims.sql (5.45ms)13882026/09/23 09:31:54 OK 20260920000000_drop_claims.sql (3.64ms)13892026/09/23 09:31:54 goose: successfully migrated database to version: 2026092000000013902026/09/23 09:31:54 OK 1_commit_pending_closure.sql (3.27ms)13912026/09/23 09:31:54 OK 2_object_stats_trigger.sql (8.73ms)13922026/09/23 09:31:54 goose: up to current file version: 213932026-09-23 09:31:54.824 UTC [65621] ERROR: relation "goose_db_version" does not exist at character 3613942026-09-23 09:31:54.824 UTC [65621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13952026/09/23 09:31:54 WARN readiness check failed error="closed pool"1396--- PASS: TestService_readinessHandler (2.43s)1397=== CONT TestLeadEndsOnShutdown13982026/09/23 09:31:54 OK 20241026095416_initial_model.sql (88.78ms)13992026/09/23 09:31:54 OK 20251210153512_drop_unused_gin_index.sql (7.2ms)14002026/09/23 09:31:54 OK 20251218171726_add_pins.sql (23.05ms)14012026/09/23 09:31:54 OK 20260628120000_add_object_size_and_stats.sql (24.04ms)14022026/09/23 09:31:54 OK 20260905000000_add_claims.sql (6.48ms)14032026/09/23 09:31:55 OK 20260920000000_drop_claims.sql (14.6ms)14042026/09/23 09:31:55 goose: successfully migrated database to version: 2026092000000014052026/09/23 09:31:55 OK 1_commit_pending_closure.sql (2.3ms)14062026/09/23 09:31:55 OK 2_object_stats_trigger.sql (657.71µs)14072026/09/23 09:31:55 goose: up to current file version: 214082026/09/23 09:31:55 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14092026/09/23 09:31:55 INFO Received uploads request method=POST path=/api/pending_closures14102026/09/23 09:31:55 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14112026/09/23 09:31:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14122026/09/23 09:31:55 WARN Failed to register uploaded object key=lfhwb12hzpw61xyvvzkk2jic42v47ds8.ls error="server returned 404: 404 page not found\n"14132026/09/23 09:31:55 INFO Signed narinfos id=2 count=114142026/09/23 09:31:55 INFO Uploading 1 narinfos14152026-09-23 09:31:55.115 UTC [65684] ERROR: relation "goose_db_version" does not exist at character 3614162026-09-23 09:31:55.115 UTC [65684] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14172026/09/23 09:31:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14182026/09/23 09:31:55 WARN Failed to register uploaded object key=lfhwb12hzpw61xyvvzkk2jic42v47ds8.narinfo error="server returned 404: 404 page not found\n"14192026/09/23 09:31:55 INFO Completed upload id=214202026/09/23 09:31:55 INFO Upload complete. (474ms)1421=== NAME TestNARDeduplicationMetadataUploadBug1422 metadata_upload_test.go:76: Retrieved narinfo from S3:1423 StorePath: /nix/var/nix/builds/nix-52991-3138667589/TestNARDeduplicationMetadataUploadBug3477823743/001/store/lfhwb12hzpw61xyvvzkk2jic42v47ds8-file2.txt1424 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1425 Compression: zstd1426 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1427 NarSize: 1601428 References: 1429 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1430 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1431 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1432 {"version":1,"root":{"type":"regular","size":44}}1433--- PASS: TestNARDeduplicationMetadataUploadBug (4.60s)1434=== CONT TestClientCADerivations14352026/09/23 09:31:55 OK 20241026095416_initial_model.sql (31.15ms)14362026/09/23 09:31:55 OK 20251210153512_drop_unused_gin_index.sql (17ms)14372026/09/23 09:31:55 OK 20251218171726_add_pins.sql (7.03ms)14382026/09/23 09:31:55 OK 20260628120000_add_object_size_and_stats.sql (19.14ms)14392026/09/23 09:31:55 OK 20260905000000_add_claims.sql (17.16ms)1440--- PASS: TestService_healthCheckHandler (2.50s)1441=== CONT TestCacheStatsHandler14422026/09/23 09:31:55 OK 20260920000000_drop_claims.sql (9.56ms)14432026/09/23 09:31:55 goose: successfully migrated database to version: 2026092000000014442026/09/23 09:31:55 OK 1_commit_pending_closure.sql (3.26ms)14452026/09/23 09:31:55 OK 2_object_stats_trigger.sql (684.88µs)14462026/09/23 09:31:55 goose: up to current file version: 21447=== NAME TestOrphanedObjectsGC1448 orphaned_objects_gc_test.go:290: GC Test Summary:1449 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1450 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1451 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1452 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1453 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1454--- PASS: TestOrphanedObjectsGC (3.15s)1455=== CONT TestCacheConfigHandler1456=== RUN TestCacheConfigHandler/full_config,_no_issuer1457=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1458=== RUN TestCacheConfigHandler/no_cache_url_configured1459=== PAUSE TestCacheConfigHandler/no_cache_url_configured1460=== RUN TestCacheConfigHandler/no_signing_keys1461=== PAUSE TestCacheConfigHandler/no_signing_keys1462=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1463=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1464=== CONT TestService_ReadScope_PublicByDefault14652026/09/23 09:31:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14662026/09/23 09:31:55 WARN Refused reserved pin name=worker-x86_64-linux14672026/09/23 09:31:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14682026/09/23 09:31:55 INFO Received create pin request method=POST path=/api/pins/my-app14692026/09/23 09:31:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1470--- PASS: TestCreatePin_ReservedPins (4.09s)1471=== CONT TestLeadElectsOneAndHandsOver14722026-09-23 09:31:55.721 UTC [65820] ERROR: relation "goose_db_version" does not exist at character 3614732026-09-23 09:31:55.721 UTC [65820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14742026/09/23 09:31:55 OK 20241026095416_initial_model.sql (23.79ms)14752026/09/23 09:31:55 OK 20251210153512_drop_unused_gin_index.sql (12.57ms)14762026/09/23 09:31:55 OK 20251218171726_add_pins.sql (30.44ms)14772026/09/23 09:31:55 OK 20260628120000_add_object_size_and_stats.sql (7.73ms)14782026/09/23 09:31:55 OK 20260905000000_add_claims.sql (30.16ms)14792026/09/23 09:31:55 OK 20260920000000_drop_claims.sql (3.79ms)14802026/09/23 09:31:55 goose: successfully migrated database to version: 202609200000001481--- PASS: TestObjectStatsTrigger (2.63s)1482=== CONT TestClientSharedPathCommittedMidPush14832026/09/23 09:31:55 OK 1_commit_pending_closure.sql (3.63ms)14842026/09/23 09:31:55 OK 2_object_stats_trigger.sql (1.22ms)14852026/09/23 09:31:55 goose: up to current file version: 214862026-09-23 09:31:56.004 UTC [65873] ERROR: relation "goose_db_version" does not exist at character 3614872026-09-23 09:31:56.004 UTC [65873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14882026/09/23 09:31:56 INFO Received cleanup request method=DELETE path=/api/pending_closures14892026/09/23 09:31:56 INFO Aborted multipart uploads count=014902026/09/23 09:31:56 INFO Received uploads request method=POST path=/api/pending_closures14912026/09/23 09:31:56 INFO Received cleanup request method=DELETE path=/api/pending_closures14922026/09/23 09:31:56 OK 20241026095416_initial_model.sql (166.38ms)14932026/09/23 09:31:56 INFO Aborted multipart uploads count=114942026/09/23 09:31:56 OK 20251210153512_drop_unused_gin_index.sql (9.67ms)14952026/09/23 09:31:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14962026-09-23 09:31:56.249 UTC [65589] ERROR: Closure does not exist: id=114972026-09-23 09:31:56.249 UTC [65589] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE14982026-09-23 09:31:56.249 UTC [65589] STATEMENT: -- name: CommitPendingClosure :exec1499 SELECT commit_pending_closure($1::bigint)1500 1501--- PASS: TestService_cleanupPendingClosuresHandler (2.62s)1502=== CONT TestClientWithDependencies15032026/09/23 09:31:56 OK 20251218171726_add_pins.sql (24.87ms)15042026/09/23 09:31:56 OK 20260628120000_add_object_size_and_stats.sql (35.18ms)15052026/09/23 09:31:56 OK 20260905000000_add_claims.sql (40.92ms)15062026-09-23 09:31:56.352 UTC [65947] ERROR: relation "goose_db_version" does not exist at character 3615072026-09-23 09:31:56.352 UTC [65947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15082026-09-23 09:31:56.353 UTC [65952] ERROR: relation "goose_db_version" does not exist at character 3615092026-09-23 09:31:56.353 UTC [65952] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15102026/09/23 09:31:56 OK 20260920000000_drop_claims.sql (22.48ms)15112026/09/23 09:31:56 goose: successfully migrated database to version: 2026092000000015122026/09/23 09:31:56 OK 1_commit_pending_closure.sql (1.73ms)15132026/09/23 09:31:56 OK 2_object_stats_trigger.sql (569.67µs)15142026/09/23 09:31:56 goose: up to current file version: 215152026/09/23 09:31:56 OK 20241026095416_initial_model.sql (62.65ms)15162026/09/23 09:31:56 OK 20251210153512_drop_unused_gin_index.sql (20.4ms)15172026/09/23 09:31:56 OK 20241026095416_initial_model.sql (102.11ms)15182026/09/23 09:31:56 OK 20251218171726_add_pins.sql (19.83ms)15192026/09/23 09:31:56 OK 20251210153512_drop_unused_gin_index.sql (23.25ms)15202026/09/23 09:31:56 OK 20251218171726_add_pins.sql (18.53ms)15212026/09/23 09:31:56 OK 20260628120000_add_object_size_and_stats.sql (41.26ms)15222026/09/23 09:31:56 OK 20260628120000_add_object_size_and_stats.sql (31.92ms)15232026/09/23 09:31:56 OK 20260905000000_add_claims.sql (32.67ms)15242026/09/23 09:31:56 OK 20260920000000_drop_claims.sql (17.29ms)15252026/09/23 09:31:56 goose: successfully migrated database to version: 2026092000000015262026-09-23 09:31:56.626 UTC [65999] ERROR: relation "goose_db_version" does not exist at character 3615272026-09-23 09:31:56.626 UTC [65999] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15282026/09/23 09:31:56 OK 1_commit_pending_closure.sql (5.25ms)15292026/09/23 09:31:56 OK 2_object_stats_trigger.sql (615.17µs)15302026/09/23 09:31:56 goose: up to current file version: 215312026/09/23 09:31:56 OK 20260905000000_add_claims.sql (42.49ms)15322026/09/23 09:31:56 OK 20260920000000_drop_claims.sql (13.28ms)15332026/09/23 09:31:56 goose: successfully migrated database to version: 2026092000000015342026/09/23 09:31:56 OK 1_commit_pending_closure.sql (2.94ms)15352026/09/23 09:31:56 OK 2_object_stats_trigger.sql (676.46µs)15362026/09/23 09:31:56 goose: up to current file version: 21537--- PASS: TestGCBugBareHashReferences (2.51s)1538=== CONT TestClientMultipleUploads1539=== RUN TestService_RequireScope_OIDC/builder_may_write1540=== PAUSE TestService_RequireScope_OIDC/builder_may_write1541=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1542=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1543=== RUN TestService_RequireScope_OIDC/ops_may_admin1544=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1545=== RUN TestService_RequireScope_OIDC/ops_may_not_write1546=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1547=== RUN TestService_RequireScope_OIDC/reader_may_not_write1548=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1549=== RUN TestService_RequireScope_OIDC/static_token_may_admin1550=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1551=== RUN TestService_RequireScope_OIDC/static_token_may_write1552=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1553=== RUN TestService_RequireScope_OIDC/reader_may_read1554=== PAUSE TestService_RequireScope_OIDC/reader_may_read1555=== RUN TestService_RequireScope_OIDC/writer_implies_read1556=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1557=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1558=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1559=== CONT TestClientIntegration15602026/09/23 09:31:56 OK 20241026095416_initial_model.sql (110.38ms)15612026/09/23 09:31:56 OK 20251210153512_drop_unused_gin_index.sql (10.71ms)15622026/09/23 09:31:56 OK 20251218171726_add_pins.sql (39.36ms)15632026/09/23 09:31:56 OK 20260628120000_add_object_size_and_stats.sql (15.7ms)15642026/09/23 09:31:56 OK 20260905000000_add_claims.sql (32.34ms)15652026/09/23 09:31:56 OK 20260920000000_drop_claims.sql (29.14ms)15662026/09/23 09:31:56 goose: successfully migrated database to version: 2026092000000015672026/09/23 09:31:56 OK 1_commit_pending_closure.sql (5.55ms)15682026/09/23 09:31:56 OK 2_object_stats_trigger.sql (1.43ms)15692026/09/23 09:31:56 goose: up to current file version: 215702026/09/23 09:31:57 INFO lead: acquired remote=192.0.2.1:123415712026/09/23 09:31:57 INFO lead: released remote=192.0.2.1:12341572--- PASS: TestLeadEndsOnShutdown (2.15s)1573=== CONT TestResolveDBConnectionString1574=== RUN TestResolveDBConnectionString/flag_wins1575=== PAUSE TestResolveDBConnectionString/flag_wins1576=== RUN TestResolveDBConnectionString/file_when_flag_empty1577=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1578=== RUN TestResolveDBConnectionString/missing_file_is_an_error1579=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1580=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1581=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1582=== RUN TestResolveDBConnectionString/nothing_configured1583=== PAUSE TestResolveDBConnectionString/nothing_configured1584=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle15852026-09-23 09:31:57.115 UTC [66112] ERROR: relation "goose_db_version" does not exist at character 3615862026-09-23 09:31:57.115 UTC [66112] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15872026/09/23 09:31:57 OK 20241026095416_initial_model.sql (100.45ms)15882026/09/23 09:31:57 OK 20251210153512_drop_unused_gin_index.sql (13.29ms)15892026/09/23 09:31:57 OK 20251218171726_add_pins.sql (14.69ms)15902026/09/23 09:31:57 OK 20260628120000_add_object_size_and_stats.sql (32.71ms)15912026-09-23 09:31:57.389 UTC [66170] ERROR: relation "goose_db_version" does not exist at character 3615922026-09-23 09:31:57.389 UTC [66170] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15932026/09/23 09:31:57 OK 20260905000000_add_claims.sql (65.9ms)15942026/09/23 09:31:57 OK 20260920000000_drop_claims.sql (23.62ms)15952026/09/23 09:31:57 goose: successfully migrated database to version: 2026092000000015962026/09/23 09:31:57 OK 1_commit_pending_closure.sql (2.65ms)15972026/09/23 09:31:57 OK 2_object_stats_trigger.sql (2.74ms)15982026/09/23 09:31:57 goose: up to current file version: 215992026/09/23 09:31:57 OK 20241026095416_initial_model.sql (51.54ms)16002026/09/23 09:31:57 OK 20251210153512_drop_unused_gin_index.sql (10.7ms)16012026/09/23 09:31:57 OK 20251218171726_add_pins.sql (6.59ms)16022026/09/23 09:31:57 OK 20260628120000_add_object_size_and_stats.sql (40.73ms)16032026/09/23 09:31:57 OK 20260905000000_add_claims.sql (31.77ms)16042026/09/23 09:31:57 OK 20260920000000_drop_claims.sql (28.31ms)16052026/09/23 09:31:57 goose: successfully migrated database to version: 2026092000000016062026/09/23 09:31:57 OK 1_commit_pending_closure.sql (5.16ms)16072026/09/23 09:31:57 OK 2_object_stats_trigger.sql (1.9ms)16082026/09/23 09:31:57 goose: up to current file version: 21609--- PASS: TestCacheStatsHandler (2.50s)1610=== CONT TestPinProtectsFromGC16112026-09-23 09:31:57.780 UTC [66252] ERROR: relation "goose_db_version" does not exist at character 3616122026-09-23 09:31:57.780 UTC [66252] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16132026-09-23 09:31:57.884 UTC [66278] ERROR: relation "goose_db_version" does not exist at character 3616142026-09-23 09:31:57.884 UTC [66278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16152026/09/23 09:31:57 OK 20241026095416_initial_model.sql (44.52ms)16162026/09/23 09:31:57 OK 20251210153512_drop_unused_gin_index.sql (2.72ms)16172026/09/23 09:31:57 OK 20251218171726_add_pins.sql (37.31ms)16182026/09/23 09:31:57 OK 20260628120000_add_object_size_and_stats.sql (22.06ms)16192026-09-23 09:31:57.966 UTC [66299] ERROR: relation "goose_db_version" does not exist at character 3616202026-09-23 09:31:57.966 UTC [66299] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16212026/09/23 09:31:57 OK 20260905000000_add_claims.sql (42.59ms)16222026/09/23 09:31:58 OK 20260920000000_drop_claims.sql (26.04ms)16232026/09/23 09:31:58 goose: successfully migrated database to version: 202609200000001624--- PASS: TestService_ReadScope_PublicByDefault (2.70s)1625=== CONT TestSkippedUploadsHandler16262026/09/23 09:31:58 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001627--- PASS: TestSkippedUploadsHandler (0.00s)1628=== CONT TestProxyWriteTimeout1629=== RUN TestProxyWriteTimeout/narinfo1630=== PAUSE TestProxyWriteTimeout/narinfo1631=== RUN TestProxyWriteTimeout/1_GiB_nar1632=== PAUSE TestProxyWriteTimeout/1_GiB_nar1633=== RUN TestProxyWriteTimeout/10_GiB_nar1634=== PAUSE TestProxyWriteTimeout/10_GiB_nar1635=== RUN TestProxyWriteTimeout/unknown_size1636=== PAUSE TestProxyWriteTimeout/unknown_size1637=== CONT TestService_ReadAuthMiddleware16382026/09/23 09:31:58 OK 20241026095416_initial_model.sql (99.87ms)16392026/09/23 09:31:58 OK 1_commit_pending_closure.sql (8.54ms)16402026/09/23 09:31:58 OK 2_object_stats_trigger.sql (1.46ms)16412026/09/23 09:31:58 goose: up to current file version: 216422026/09/23 09:31:58 OK 20251210153512_drop_unused_gin_index.sql (7.95ms)16432026/09/23 09:31:58 OK 20251218171726_add_pins.sql (31.82ms)16442026/09/23 09:31:58 OK 20241026095416_initial_model.sql (59.32ms)16452026/09/23 09:31:58 OK 20251210153512_drop_unused_gin_index.sql (7.91ms)16462026/09/23 09:31:58 OK 20251218171726_add_pins.sql (13.54ms)16472026/09/23 09:31:58 OK 20260628120000_add_object_size_and_stats.sql (21.77ms)16482026/09/23 09:31:58 OK 20260628120000_add_object_size_and_stats.sql (34.02ms)16492026/09/23 09:31:58 OK 20260905000000_add_claims.sql (49.27ms)16502026/09/23 09:31:58 OK 20260920000000_drop_claims.sql (23.09ms)16512026/09/23 09:31:58 goose: successfully migrated database to version: 2026092000000016522026/09/23 09:31:58 OK 20260905000000_add_claims.sql (42.02ms)16532026/09/23 09:31:58 OK 1_commit_pending_closure.sql (4.31ms)16542026/09/23 09:31:58 OK 2_object_stats_trigger.sql (617.83µs)16552026/09/23 09:31:58 goose: up to current file version: 216562026/09/23 09:31:58 OK 20260920000000_drop_claims.sql (28.72ms)16572026/09/23 09:31:58 goose: successfully migrated database to version: 2026092000000016582026/09/23 09:31:58 OK 1_commit_pending_closure.sql (2.2ms)16592026/09/23 09:31:58 OK 2_object_stats_trigger.sql (772.25µs)16602026/09/23 09:31:58 goose: up to current file version: 216612026/09/23 09:31:58 INFO lead: acquired remote=192.0.2.1:123416622026/09/23 09:31:58 INFO lead: released remote=192.0.2.1:123416632026/09/23 09:31:58 INFO lead: acquired remote=192.0.2.1:123416642026/09/23 09:31:58 INFO lead: released remote=192.0.2.1:12341665--- PASS: TestLeadElectsOneAndHandsOver (3.00s)1666=== CONT TestService_AuthMiddleware_OIDC16672026-09-23 09:31:58.571 UTC [66446] ERROR: relation "goose_db_version" does not exist at character 3616682026-09-23 09:31:58.571 UTC [66446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16692026/09/23 09:31:58 OK 20241026095416_initial_model.sql (24.68ms)16702026/09/23 09:31:58 OK 20251210153512_drop_unused_gin_index.sql (9.94ms)16712026/09/23 09:31:58 OK 20251218171726_add_pins.sql (17.52ms)16722026/09/23 09:31:58 OK 20260628120000_add_object_size_and_stats.sql (36.29ms)16732026/09/23 09:31:58 OK 20260905000000_add_claims.sql (23.13ms)16742026/09/23 09:31:58 OK 20260920000000_drop_claims.sql (24.56ms)16752026/09/23 09:31:58 goose: successfully migrated database to version: 2026092000000016762026/09/23 09:31:58 OK 1_commit_pending_closure.sql (3.1ms)16772026/09/23 09:31:58 OK 2_object_stats_trigger.sql (1.29ms)16782026/09/23 09:31:58 goose: up to current file version: 216792026-09-23 09:31:58.772 UTC [66506] ERROR: relation "goose_db_version" does not exist at character 3616802026-09-23 09:31:58.772 UTC [66506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16812026/09/23 09:31:58 OK 20241026095416_initial_model.sql (59.07ms)16822026/09/23 09:31:58 OK 20251210153512_drop_unused_gin_index.sql (11.63ms)16832026/09/23 09:31:58 OK 20251218171726_add_pins.sql (15.83ms)16842026/09/23 09:31:58 OK 20260628120000_add_object_size_and_stats.sql (5.47ms)16852026/09/23 09:31:58 OK 20260905000000_add_claims.sql (66.31ms)16862026/09/23 09:31:59 OK 20260920000000_drop_claims.sql (7.75ms)16872026/09/23 09:31:59 goose: successfully migrated database to version: 2026092000000016882026/09/23 09:31:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54126/oidc16892026/09/23 09:31:59 OK 1_commit_pending_closure.sql (2.4ms)16902026/09/23 09:31:59 OK 2_object_stats_trigger.sql (444.21µs)16912026/09/23 09:31:59 goose: up to current file version: 21692=== NAME TestClientCADerivations1693 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-52991-3138667589/TestClientCADerivations3418976764/001/store/3bnal2iaakhkl7x2fr5dmb9i8p4vijyc-ca-test1694=== NAME TestClientMultipleUploads1695 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-52991-3138667589/TestClientMultipleUploads558869644/001/store/qvnwg3p3jm71y91v00rgkvpcqfklhla0-test-file-0.txt1696=== NAME TestClientCADerivations1697 client_ca_test.go:139: Found 1 dependencies (including self)16982026/09/23 09:31:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16992026/09/23 09:31:59 INFO Received uploads request method=POST path=/api/pending_closures1700=== NAME TestClientMultipleUploads1701 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-52991-3138667589/TestClientMultipleUploads558869644/001/store/4s5p86mramn3as3zqgirva8c1dd0w28y-test-file-1.txt17022026/09/23 09:31:59 INFO Received uploads request method=POST path=/api/pending_closures1703=== NAME TestClientIntegration1704 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-52991-3138667589/TestClientIntegration421192954/002/store/da86cqkldd8rafsj5pc5awvl8v2k7m1q-test-file.txt17052026-09-23 09:32:00.016 UTC [66800] ERROR: relation "goose_db_version" does not exist at character 3617062026-09-23 09:32:00.016 UTC [66800] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17072026/09/23 09:32:00 OK 20241026095416_initial_model.sql (29.53ms)17082026/09/23 09:32:00 OK 20251210153512_drop_unused_gin_index.sql (13.09ms)17092026/09/23 09:32:00 OK 20251218171726_add_pins.sql (8.34ms)17102026/09/23 09:32:00 OK 20260628120000_add_object_size_and_stats.sql (27.5ms)17112026/09/23 09:32:00 OK 20260905000000_add_claims.sql (43.46ms)17122026/09/23 09:32:00 OK 20260920000000_drop_claims.sql (38.88ms)17132026/09/23 09:32:00 goose: successfully migrated database to version: 2026092000000017142026/09/23 09:32:00 OK 1_commit_pending_closure.sql (1.41ms)17152026/09/23 09:32:00 OK 2_object_stats_trigger.sql (805.83µs)17162026/09/23 09:32:00 goose: up to current file version: 217172026/09/23 09:32:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17182026/09/23 09:32:00 INFO Received uploads request method=POST path=/api/pending_closures17192026/09/23 09:32:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17202026/09/23 09:32:00 INFO Uploading a9619qwmnqxflpnpgkrkdxwxlhyh200q-shared-dep (136B)17212026/09/23 09:32:00 WARN Failed to register uploaded object key=a9619qwmnqxflpnpgkrkdxwxlhyh200q.ls error="server returned 404: 404 page not found\n"17222026/09/23 09:32:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17232026/09/23 09:32:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17242026/09/23 09:32:00 INFO Signed narinfos id=2 count=117252026/09/23 09:32:00 INFO Uploading 1 narinfos17262026/09/23 09:32:00 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17272026/09/23 09:32:00 WARN Failed to register uploaded object key=a9619qwmnqxflpnpgkrkdxwxlhyh200q.narinfo error="server returned 404: 404 page not found\n"17282026/09/23 09:32:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17292026/09/23 09:32:00 INFO Completed upload id=217302026/09/23 09:32:00 INFO Upload complete. (305ms)17312026/09/23 09:32:00 INFO Received uploads request method=POST path=/api/pending_closures17322026/09/23 09:32:00 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17332026/09/23 09:32:00 INFO Uploading 3mxirqmjnzlbxmlkf88aj7wcglm9df0a-top (256B)17342026/09/23 09:32:00 INFO Uploading a9619qwmnqxflpnpgkrkdxwxlhyh200q-shared-dep (136B)17352026/09/23 09:32:00 WARN Failed to register uploaded object key=3mxirqmjnzlbxmlkf88aj7wcglm9df0a.ls error="server returned 404: 404 page not found\n"17362026/09/23 09:32:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1737=== NAME TestClientMultipleUploads1738 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-52991-3138667589/TestClientMultipleUploads558869644/001/store/1wdzb0majnpcmzyr2b47ldn8ra77cizd-test-file-2.txt17392026/09/23 09:32:00 WARN Failed to register uploaded object key=nar/1bmx0mq4rx2cawhn4rlxg95ycci8djkr67n0frdj9xghdhjf80w2.nar.zst error="server returned 404: 404 page not found\n"17402026/09/23 09:32:00 WARN Failed to register uploaded object key=a9619qwmnqxflpnpgkrkdxwxlhyh200q.ls error="server returned 404: 404 page not found\n"17412026/09/23 09:32:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign17422026/09/23 09:32:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17432026/09/23 09:32:00 INFO Signed narinfos id=3 count=117442026/09/23 09:32:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17452026/09/23 09:32:00 INFO Signed narinfos id=1 count=117462026/09/23 09:32:00 INFO Uploading 2 narinfos1747=== NAME TestOrphanedObjectsGCStressTest1748 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17492026/09/23 09:32:00 WARN Failed to register uploaded object key=3mxirqmjnzlbxmlkf88aj7wcglm9df0a.narinfo error="server returned 404: 404 page not found\n"17502026/09/23 09:32:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17512026/09/23 09:32:00 WARN Failed to register uploaded object key=a9619qwmnqxflpnpgkrkdxwxlhyh200q.narinfo error="server returned 404: 404 page not found\n"17522026/09/23 09:32:00 INFO Completed upload id=117532026/09/23 09:32:00 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete17542026/09/23 09:32:00 INFO Completed upload id=317552026/09/23 09:32:00 INFO Upload complete. (937ms)1756=== NAME TestClientSharedPathCommittedMidPush1757 client_integration_test.go:680: Retrieved narinfo from S3:1758 StorePath: /nix/var/nix/builds/nix-52991-3138667589/TestClientSharedPathCommittedMidPush3606413332/001/store/a9619qwmnqxflpnpgkrkdxwxlhyh200q-shared-dep1759 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1760 Compression: zstd1761 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821762 NarSize: 1361763 References: 1764 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1765 client_integration_test.go:680: Retrieved narinfo from S3:1766 StorePath: /nix/var/nix/builds/nix-52991-3138667589/TestClientSharedPathCommittedMidPush3606413332/001/store/3mxirqmjnzlbxmlkf88aj7wcglm9df0a-top1767 URL: nar/1bmx0mq4rx2cawhn4rlxg95ycci8djkr67n0frdj9xghdhjf80w2.nar.zst1768 Compression: zstd1769 NarHash: sha256:1bmx0mq4rx2cawhn4rlxg95ycci8djkr67n0frdj9xghdhjf80w21770 NarSize: 2561771 References: /nix/var/nix/builds/nix-52991-3138667589/TestClientSharedPathCommittedMidPush3606413332/001/store/a9619qwmnqxflpnpgkrkdxwxlhyh200q-shared-dep1772 CA: text:sha256:0glqfj8rjscvksyn97vps5vwnbz69z0kd55zlh0nyw1i344fah6b1773=== NAME TestOrphanedObjectsGCStressTest1774 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1775--- PASS: TestClientSharedPathCommittedMidPush (4.48s)1776=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1777--- PASS: TestService_ReadAuthMiddleware (2.51s)1778=== CONT TestService_AuthMiddleware_MTLSProxyHeader17792026/09/23 09:32:00 INFO Received uploads request method=POST path=/api/pending_closures17802026/09/23 09:32:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17812026/09/23 09:32:00 INFO Uploading 3bnal2iaakhkl7x2fr5dmb9i8p4vijyc-ca-test (144B)17822026/09/23 09:32:00 WARN Failed to register uploaded object key=3bnal2iaakhkl7x2fr5dmb9i8p4vijyc.ls error="server returned 404: 404 page not found\n"17832026-09-23 09:32:00.762 UTC [66983] ERROR: relation "goose_db_version" does not exist at character 3617842026-09-23 09:32:00.762 UTC [66983] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17852026/09/23 09:32:00 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17862026/09/23 09:32:00 WARN Failed to register uploaded object key=log/qnsw04d3jzsi2hcpspg3xypxb26z30d9-ca-test.drv error="server returned 404: 404 page not found\n"17872026/09/23 09:32:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17882026/09/23 09:32:00 INFO Signed narinfos id=1 count=117892026/09/23 09:32:00 INFO Uploading 1 narinfos17902026/09/23 09:32:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17912026/09/23 09:32:00 WARN Failed to register uploaded object key=3bnal2iaakhkl7x2fr5dmb9i8p4vijyc.narinfo error="server returned 404: 404 page not found\n"17922026/09/23 09:32:00 INFO Completed upload id=117932026/09/23 09:32:00 INFO Upload complete. (878ms)1794=== NAME TestClientCADerivations1795 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-52991-3138667589/TestClientCADerivations3418976764/001/store/3bnal2iaakhkl7x2fr5dmb9i8p4vijyc-ca-test1796 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1797 Compression: zstd1798 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1799 NarSize: 1441800 References: 1801 Deriver: /nix/var/nix/builds/nix-52991-3138667589/TestClientCADerivations3418976764/001/store/qnsw04d3jzsi2hcpspg3xypxb26z30d9-ca-test.drv1802 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1803 client_ca_test.go:185: Checking for realisation files in S3...1804 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1805 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18062026/09/23 09:32:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18072026/09/23 09:32:00 INFO Received uploads request method=POST path=/api/pending_closures18082026/09/23 09:32:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18092026/09/23 09:32:00 INFO Uploading da86cqkldd8rafsj5pc5awvl8v2k7m1q-test-file.txt (152B)1810=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1811=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1812=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1813=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1814=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1815=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1816=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1817=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1818=== CONT TestServerTLSConfig/no_client_CA1819=== CONT TestServerTLSConfig/not_a_PEM_file1820=== CONT TestServerTLSConfig/missing_CA_file1821--- PASS: TestServerTLSConfig (0.00s)1822 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1823 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1824 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1825=== CONT TestIsValidCachePath/narinfo1826=== CONT TestIsValidCachePath/index.html1827=== CONT TestIsValidCachePath/short_hash1828=== CONT TestIsValidCachePath/wrong_extension1829=== CONT TestIsValidCachePath/leading_slash1830=== CONT TestIsValidCachePath/empty1831=== CONT TestIsValidCachePath/random_path1832=== CONT TestIsValidCachePath/invalid_char_u1833=== CONT TestIsValidCachePath/invalid_char_e1834=== CONT TestIsValidCachePath/traversal_in_middle1835=== CONT TestIsValidCachePath/traversal_parent1836=== CONT TestIsValidCachePath/nar_uncompressed1837=== CONT TestIsValidCachePath/nix-cache-info1838=== CONT TestIsValidCachePath/realisation1839=== CONT TestIsValidCachePath/log1840=== CONT TestIsValidCachePath/ls1841=== CONT TestIsValidCachePath/nar_xz1842=== CONT TestIsValidCachePath/nar_bz21843=== CONT TestIsValidCachePath/nar_zst1844=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1845--- PASS: TestIsValidCachePath (0.00s)1846 --- PASS: TestIsValidCachePath/narinfo (0.00s)1847 --- PASS: TestIsValidCachePath/index.html (0.00s)1848 --- PASS: TestIsValidCachePath/short_hash (0.00s)1849 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1850 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1851 --- PASS: TestIsValidCachePath/empty (0.00s)1852 --- PASS: TestIsValidCachePath/random_path (0.00s)1853 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1854 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1855 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1856 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1857 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1858 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1859 --- PASS: TestIsValidCachePath/realisation (0.00s)1860 --- PASS: TestIsValidCachePath/log (0.00s)1861 --- PASS: TestIsValidCachePath/ls (0.00s)1862 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1863 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1864 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1865 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1866=== CONT TestParseSingleRange/none1867=== CONT TestParseSingleRange/open-ended1868=== CONT TestParseSingleRange/start_far_past_EOF1869=== CONT TestParseSingleRange/start_past_EOF1870=== CONT TestParseSingleRange/single_byte1871=== CONT TestParseSingleRange/suffix_exceeds_size1872=== CONT TestParseSingleRange/suffix1873=== CONT TestParseSingleRange/end_clamped_to_size1874=== CONT TestParseSingleRange/malformed_both_empty1875=== CONT TestParseSingleRange/closed1876=== CONT TestParseSingleRange/malformed_end_before_start1877=== CONT TestParseSingleRange/multi-range_ignored1878=== CONT TestParseSingleRange/malformed_no_dash1879=== CONT TestParseSingleRange/unknown_unit1880--- PASS: TestParseSingleRange (0.00s)1881 --- PASS: TestParseSingleRange/none (0.00s)1882 --- PASS: TestParseSingleRange/open-ended (0.00s)1883 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1884 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1885 --- PASS: TestParseSingleRange/single_byte (0.00s)1886 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1887 --- PASS: TestParseSingleRange/suffix (0.00s)1888 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1889 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1890 --- PASS: TestParseSingleRange/closed (0.00s)1891 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1892 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1893 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1894 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1895=== CONT TestIsValidUploadKey/narinfo1896=== CONT TestIsValidUploadKey/realisation_plus_in_output1897=== CONT TestIsValidUploadKey/unknown_type1898=== CONT TestIsValidUploadKey/empty_key1899=== CONT TestIsValidUploadKey/absolute1900=== CONT TestIsValidUploadKey/traversal_nar1901=== CONT TestIsValidUploadKey/traversal1902=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1903=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1904=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1905=== CONT TestIsValidUploadKey/index.html1906=== CONT TestIsValidUploadKey/nix-cache-info1907=== CONT TestIsValidUploadKey/build_log_home-manager_file1908=== CONT TestIsValidUploadKey/realisation1909=== CONT TestIsValidUploadKey/build_log_equals1910=== CONT TestIsValidUploadKey/build_log_question_mark1911=== CONT TestIsValidUploadKey/build_log_plus_in_name1912=== CONT TestIsValidUploadKey/nar_plain1913=== CONT TestIsValidUploadKey/build_log1914=== CONT TestIsValidUploadKey/listing1915=== CONT TestIsValidUploadKey/nar_xz1916=== CONT TestIsValidUploadKey/nar_zst1917--- PASS: TestIsValidUploadKey (0.00s)1918 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1919 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1920 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1921 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1922 --- PASS: TestIsValidUploadKey/absolute (0.00s)1923 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1924 --- PASS: TestIsValidUploadKey/traversal (0.00s)1925 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1926 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1927 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1928 --- PASS: TestIsValidUploadKey/index.html (0.00s)1929 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1930 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1931 --- PASS: TestIsValidUploadKey/realisation (0.00s)1932 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1933 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1934 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1935 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1936 --- PASS: TestIsValidUploadKey/build_log (0.00s)1937 --- PASS: TestIsValidUploadKey/listing (0.00s)1938 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1939 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1940=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19412026/09/23 09:32:00 INFO Received uploads request method=POST path=/19422026/09/23 09:32:00 WARN Failed to register uploaded object key=da86cqkldd8rafsj5pc5awvl8v2k7m1q.ls error="server returned 404: 404 page not found\n"19432026/09/23 09:32:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19442026/09/23 09:32:00 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19452026/09/23 09:32:00 INFO Signed narinfos id=1 count=119462026/09/23 09:32:00 INFO Uploading 1 narinfos19472026/09/23 09:32:00 OK 20241026095416_initial_model.sql (80.84ms)19482026/09/23 09:32:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19492026/09/23 09:32:00 WARN Failed to register uploaded object key=da86cqkldd8rafsj5pc5awvl8v2k7m1q.narinfo error="server returned 404: 404 page not found\n"19502026/09/23 09:32:00 OK 20251210153512_drop_unused_gin_index.sql (5.56ms)19512026/09/23 09:32:00 INFO Completed upload id=119522026/09/23 09:32:00 INFO Upload complete. (627ms)19532026/09/23 09:32:00 OK 20251218171726_add_pins.sql (18.05ms)19542026/09/23 09:32:00 OK 20260628120000_add_object_size_and_stats.sql (61.53ms)19552026/09/23 09:32:00 OK 20260905000000_add_claims.sql (15.29ms)19562026/09/23 09:32:01 OK 20260920000000_drop_claims.sql (15.4ms)19572026/09/23 09:32:01 goose: successfully migrated database to version: 2026092000000019582026/09/23 09:32:01 OK 1_commit_pending_closure.sql (5.37ms)19592026/09/23 09:32:01 OK 2_object_stats_trigger.sql (635.54µs)19602026/09/23 09:32:01 goose: up to current file version: 219612026-09-23 09:32:01.105 UTC [67062] ERROR: relation "goose_db_version" does not exist at character 3619622026-09-23 09:32:01.105 UTC [67062] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1963=== NAME TestPinProtectsFromGC1964 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-52991-3138667589/TestPinProtectsFromGC1212700683/001/store/bnlqwaws5az9qw7c3c7yipfsb8xbw59i-pinned-file.txt1965 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-52991-3138667589/TestPinProtectsFromGC1212700683/001/store/svyjaxk95hbaj6h8rqkpsb64i39rryvp-unpinned-file.txt19662026/09/23 09:32:01 OK 20241026095416_initial_model.sql (33.96ms)19672026/09/23 09:32:01 OK 20251210153512_drop_unused_gin_index.sql (11.23ms)19682026/09/23 09:32:01 OK 20251218171726_add_pins.sql (12.21ms)19692026/09/23 09:32:01 OK 20260628120000_add_object_size_and_stats.sql (12.66ms)19702026/09/23 09:32:01 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19712026/09/23 09:32:01 INFO Received uploads request method=POST path=/api/pending_closures19722026/09/23 09:32:01 OK 20260905000000_add_claims.sql (26.61ms)1973=== NAME TestClientCADerivations1974 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket42?endpoint=http://localhost:53949®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-52991-3138667589/TestClientCADerivations3418976764/001/store'1975 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119762026/09/23 09:32:01 INFO Received uploads request method=POST path=/api/pending_closures19772026/09/23 09:32:01 INFO Received uploads request method=POST path=/api/pending_closures19782026/09/23 09:32:01 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19792026/09/23 09:32:01 INFO Uploading qvnwg3p3jm71y91v00rgkvpcqfklhla0-test-file-0.txt (160B)19802026/09/23 09:32:01 INFO Uploading 4s5p86mramn3as3zqgirva8c1dd0w28y-test-file-1.txt (160B)19812026/09/23 09:32:01 INFO Uploading 1wdzb0majnpcmzyr2b47ldn8ra77cizd-test-file-2.txt (160B)19822026/09/23 09:32:01 OK 20260920000000_drop_claims.sql (16.87ms)19832026/09/23 09:32:01 goose: successfully migrated database to version: 2026092000000019842026/09/23 09:32:01 OK 1_commit_pending_closure.sql (2.69ms)19852026/09/23 09:32:01 OK 2_object_stats_trigger.sql (836.08µs)19862026/09/23 09:32:01 goose: up to current file version: 21987--- PASS: TestClientCADerivations (6.08s)1988=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19892026/09/23 09:32:01 INFO Received request for more parts method=POST path=/19902026/09/23 09:32:01 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19912026/09/23 09:32:01 WARN mTLS auth: bound subjects configured but subject DN unavailable19922026/09/23 09:32:01 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1993--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.90s)1994=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19952026/09/23 09:32:01 INFO Received complete multipart upload request method=POST path=/19962026/09/23 09:32:01 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19972026/09/23 09:32:01 WARN Failed to register uploaded object key=qvnwg3p3jm71y91v00rgkvpcqfklhla0.ls error="server returned 404: 404 page not found\n"19982026/09/23 09:32:01 WARN Failed to register uploaded object key=1wdzb0majnpcmzyr2b47ldn8ra77cizd.ls error="server returned 404: 404 page not found\n"19992026/09/23 09:32:01 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20002026/09/23 09:32:01 WARN Failed to register uploaded object key=4s5p86mramn3as3zqgirva8c1dd0w28y.ls error="server returned 404: 404 page not found\n"20012026/09/23 09:32:01 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20022026/09/23 09:32:01 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20032026/09/23 09:32:01 INFO Signed narinfos id=1 count=120042026/09/23 09:32:01 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20052026/09/23 09:32:01 INFO Signed narinfos id=2 count=120062026/09/23 09:32:01 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign20072026/09/23 09:32:01 INFO Signed narinfos id=3 count=120082026/09/23 09:32:01 INFO Uploading 3 narinfos20092026/09/23 09:32:01 WARN Failed to register uploaded object key=4s5p86mramn3as3zqgirva8c1dd0w28y.narinfo error="server returned 404: 404 page not found\n"20102026/09/23 09:32:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20112026/09/23 09:32:01 WARN Failed to register uploaded object key=qvnwg3p3jm71y91v00rgkvpcqfklhla0.narinfo error="server returned 404: 404 page not found\n"20122026/09/23 09:32:01 WARN Failed to register uploaded object key=1wdzb0majnpcmzyr2b47ldn8ra77cizd.narinfo error="server returned 404: 404 page not found\n"20132026/09/23 09:32:01 INFO Completed upload id=120142026/09/23 09:32:01 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20152026/09/23 09:32:01 INFO All 1 paths already cached20162026/09/23 09:32:01 INFO Completed upload id=220172026/09/23 09:32:01 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete2018=== NAME TestClientIntegration2019 client_integration_test.go:312: Retrieved narinfo from S3:2020 StorePath: /nix/var/nix/builds/nix-52991-3138667589/TestClientIntegration421192954/002/store/da86cqkldd8rafsj5pc5awvl8v2k7m1q-test-file.txt2021 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2022 Compression: zstd2023 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12024 NarSize: 1522025 References: 2026 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk120272026/09/23 09:32:01 INFO Completed upload id=320282026/09/23 09:32:01 INFO Upload complete. (655ms)2029=== NAME TestClientMultipleUploads2030 client_integration_test.go:369: Uploaded 3 paths in 998.359458ms2031=== NAME TestClientIntegration2032 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2033 client_integration_test.go:313: Decompressed .ls content (64 bytes):2034 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2035 client_integration_test.go:316: Testing garbage collection...2036--- PASS: TestClientMultipleUploads (4.69s)2037=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20382026/09/23 09:32:01 INFO Received uploads request method=POST path=/2039=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20402026/09/23 09:32:01 INFO Received complete multipart upload request method=POST path=/2041=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20422026/09/23 09:32:01 INFO Received request for more parts method=POST path=/2043=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20442026/09/23 09:32:01 INFO Received uploads request method=POST path=/2045--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2046 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2047 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2048 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2049 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2050=== CONT TestClientErrorHandling/InvalidStorePath2051=== CONT TestClientErrorHandling/ServerNotAvailable2052=== CONT TestClientErrorHandling/InvalidAuthToken2053--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.99s)2054=== CONT TestCacheConfigHandler/full_config,_no_issuer2055=== CONT TestCacheConfigHandler/no_signing_keys2056=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2057=== CONT TestCacheConfigHandler/no_cache_url_configured2058--- PASS: TestCacheConfigHandler (0.00s)2059 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2060 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2061 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2062 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2063=== CONT TestService_RequireScope_OIDC/builder_may_write2064=== CONT TestService_RequireScope_OIDC/static_token_may_admin2065=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2066=== CONT TestService_RequireScope_OIDC/writer_implies_read2067=== CONT TestService_RequireScope_OIDC/reader_may_read2068=== CONT TestService_RequireScope_OIDC/static_token_may_write2069=== CONT TestService_RequireScope_OIDC/ops_may_admin2070=== CONT TestService_RequireScope_OIDC/ops_may_not_write2071=== CONT TestService_RequireScope_OIDC/reader_may_not_write2072=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2073=== CONT TestResolveDBConnectionString/flag_wins2074=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2075=== CONT TestResolveDBConnectionString/nothing_configured2076=== CONT TestResolveDBConnectionString/missing_file_is_an_error2077=== CONT TestResolveDBConnectionString/file_when_flag_empty2078=== CONT TestProxyWriteTimeout/narinfo2079=== CONT TestProxyWriteTimeout/10_GiB_nar2080=== CONT TestProxyWriteTimeout/unknown_size2081=== CONT TestProxyWriteTimeout/1_GiB_nar2082=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2083--- PASS: TestProxyWriteTimeout (0.00s)2084 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2085 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2086 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2087 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2088--- PASS: TestResolveDBConnectionString (0.01s)2089 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2090 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2091 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2092 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2093 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2094--- PASS: TestService_RequireScope_OIDC (2.79s)2095 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2100 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2101 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2102 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2103 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2104 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2105=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2106=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21072026/09/23 09:32:01 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]2108=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21092026/09/23 09:32:01 WARN Authentication failed token_preview=eyJhbGciOi...o53AhMLb1Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2110--- PASS: TestService_AuthMiddleware_OIDC (2.36s)2111 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2112 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2113 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2114 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2115=== NAME TestClientWithDependencies2116 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-52991-3138667589/TestClientWithDependencies51904003/001/store/irrj3kh1zffp8a9f9m3y2506pz7ad6ca-test-script21172026-09-23 09:32:01.752 UTC [67230] ERROR: relation "goose_db_version" does not exist at character 3621182026-09-23 09:32:01.752 UTC [67230] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21192026/09/23 09:32:01 OK 20241026095416_initial_model.sql (40.47ms)21202026/09/23 09:32:01 OK 20251210153512_drop_unused_gin_index.sql (1.44ms)21212026/09/23 09:32:01 OK 20251218171726_add_pins.sql (2.08ms)21222026/09/23 09:32:01 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)21232026-09-23 09:32:01.817 UTC [67246] ERROR: relation "goose_db_version" does not exist at character 3621242026-09-23 09:32:01.817 UTC [67246] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21252026/09/23 09:32:01 OK 20260905000000_add_claims.sql (7.65ms)21262026/09/23 09:32:01 OK 20260920000000_drop_claims.sql (24.36ms)21272026/09/23 09:32:01 goose: successfully migrated database to version: 2026092000000021282026/09/23 09:32:01 OK 1_commit_pending_closure.sql (2.54ms)21292026/09/23 09:32:01 OK 2_object_stats_trigger.sql (681.88µs)21302026/09/23 09:32:01 goose: up to current file version: 221312026/09/23 09:32:01 INFO Starting cleanup of old closures method=DELETE path=/api/closures21322026/09/23 09:32:01 INFO Garbage collection started21332026/09/23 09:32:01 OK 20241026095416_initial_model.sql (63.61ms)21342026/09/23 09:32:01 INFO Aborted multipart uploads count=021352026/09/23 09:32:01 WARN Force mode enabled - objects will be deleted immediately without grace period21362026/09/23 09:32:01 OK 20251210153512_drop_unused_gin_index.sql (7.3ms)21372026/09/23 09:32:01 OK 20251218171726_add_pins.sql (19.15ms)21382026/09/23 09:32:01 OK 20260628120000_add_object_size_and_stats.sql (16.5ms)21392026/09/23 09:32:01 OK 20260905000000_add_claims.sql (10.63ms)21402026/09/23 09:32:02 OK 20260920000000_drop_claims.sql (74.24ms)21412026/09/23 09:32:02 goose: successfully migrated database to version: 2026092000000021422026/09/23 09:32:02 OK 1_commit_pending_closure.sql (2.44ms)21432026/09/23 09:32:02 OK 2_object_stats_trigger.sql (998.75µs)21442026/09/23 09:32:02 goose: up to current file version: 22145 client_integration_test.go:615: Found 1 dependencies (including self)21462026/09/23 09:32:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21472026/09/23 09:32:02 INFO Received uploads request method=POST path=/api/pending_closures21482026/09/23 09:32:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21492026/09/23 09:32:02 INFO Uploading bnlqwaws5az9qw7c3c7yipfsb8xbw59i-pinned-file.txt (128B)21502026/09/23 09:32:02 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21512026/09/23 09:32:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21522026/09/23 09:32:02 WARN Failed to register uploaded object key=bnlqwaws5az9qw7c3c7yipfsb8xbw59i.ls error="server returned 404: 404 page not found\n"21532026/09/23 09:32:02 INFO Signed narinfos id=1 count=121542026/09/23 09:32:02 INFO Uploading 1 narinfos21552026/09/23 09:32:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21562026/09/23 09:32:02 WARN Failed to register uploaded object key=bnlqwaws5az9qw7c3c7yipfsb8xbw59i.narinfo error="server returned 404: 404 page not found\n"21572026/09/23 09:32:02 INFO Completed upload id=121582026/09/23 09:32:02 INFO Upload complete. (582ms)21592026/09/23 09:32:02 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/present21602026/09/23 09:32:02 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=207.707858ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21612026/09/23 09:32:02 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.450482ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2162=== NAME TestOrphanedObjectsGCStressTest2163 orphaned_objects_gc_test.go:509: Stress test completed successfully:2164 orphaned_objects_gc_test.go:510: - Active objects preserved: 202165 orphaned_objects_gc_test.go:511: - Objects deleted: 2102166 orphaned_objects_gc_test.go:512: - Total GC'd: 2102167--- PASS: TestOrphanedObjectsGCStressTest (10.78s)21682026/09/23 09:32:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21692026/09/23 09:32:02 INFO Received uploads request method=POST path=/api/pending_closures21702026/09/23 09:32:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21712026/09/23 09:32:02 INFO Uploading svyjaxk95hbaj6h8rqkpsb64i39rryvp-unpinned-file.txt (128B)21722026/09/23 09:32:02 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"21732026/09/23 09:32:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign21742026/09/23 09:32:02 WARN Failed to register uploaded object key=svyjaxk95hbaj6h8rqkpsb64i39rryvp.ls error="server returned 404: 404 page not found\n"21752026/09/23 09:32:02 INFO Signed narinfos id=2 count=121762026/09/23 09:32:02 INFO Uploading 1 narinfos21772026/09/23 09:32:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21782026/09/23 09:32:02 WARN Failed to register uploaded object key=svyjaxk95hbaj6h8rqkpsb64i39rryvp.narinfo error="server returned 404: 404 page not found\n"21792026/09/23 09:32:02 INFO Completed upload id=221802026/09/23 09:32:02 INFO Upload complete. (420ms)21812026/09/23 09:32:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21822026/09/23 09:32:02 INFO Received uploads request method=POST path=/api/pending_closures21832026/09/23 09:32:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21842026/09/23 09:32:02 INFO Uploading irrj3kh1zffp8a9f9m3y2506pz7ad6ca-test-script (136B)21852026/09/23 09:32:02 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"21862026/09/23 09:32:02 WARN Failed to register uploaded object key=log/d3s685qgp1zds5496i7wa4g2g2qyhqhb-test-script.drv error="server returned 404: 404 page not found\n"21872026/09/23 09:32:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21882026/09/23 09:32:02 WARN Failed to register uploaded object key=irrj3kh1zffp8a9f9m3y2506pz7ad6ca.ls error="server returned 404: 404 page not found\n"21892026/09/23 09:32:02 INFO Signed narinfos id=1 count=121902026/09/23 09:32:02 INFO Uploading 1 narinfos21912026/09/23 09:32:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21922026/09/23 09:32:02 WARN Failed to register uploaded object key=irrj3kh1zffp8a9f9m3y2506pz7ad6ca.narinfo error="server returned 404: 404 page not found\n"21932026/09/23 09:32:02 INFO Completed upload id=121942026/09/23 09:32:02 INFO Upload complete. (410ms)2195=== NAME TestClientWithDependencies2196 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-52991-3138667589/TestClientWithDependencies51904003/001/store) requires matching store prefix2197--- PASS: TestClientWithDependencies (6.71s)21982026/09/23 09:32:03 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=730.420887ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21992026/09/23 09:32:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22002026/09/23 09:32:03 INFO Received create pin request method=POST path=/api/pins/myapp22012026/09/23 09:32:03 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-52991-3138667589/TestPinProtectsFromGC1212700683/001/store/bnlqwaws5az9qw7c3c7yipfsb8xbw59i-pinned-file.txt narinfo_key=bnlqwaws5az9qw7c3c7yipfsb8xbw59i.narinfo22022026/09/23 09:32:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures22032026/09/23 09:32:03 INFO Garbage collection started22042026/09/23 09:32:03 INFO Aborted multipart uploads count=022052026/09/23 09:32:03 WARN Force mode enabled - objects will be deleted immediately without grace period22062026/09/23 09:32:03 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22072026/09/23 09:32:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22082026/09/23 09:32:03 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.630461396s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22092026/09/23 09:32:03 INFO Garbage collection progress phase=cleanup_orphan_objects failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=1000 objects_failed=022102026/09/23 09:32:04 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=022112026/09/23 09:32:04 WARN Rate limiter enabled after throttle name=s3-test rate=522122026/09/23 09:32:04 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2213=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2214 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102215 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002216--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.01s)22172026/09/23 09:32:04 INFO Vacuumed table table=pending_closures22182026/09/23 09:32:04 INFO Vacuumed table table=pending_objects22192026/09/23 09:32:04 INFO Vacuumed table table=multipart_uploads22202026/09/23 09:32:04 INFO Vacuumed table table=closures22212026/09/23 09:32:04 INFO Vacuumed table table=objects22222026/09/23 09:32:05 INFO Garbage collection progress phase=cleanup_orphan_objects failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=1000 objects_failed=02223--- PASS: TestUploadHandlersRejectOversizedBody (0.10s)2224 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.19s)2225 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.23s)2226 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (4.85s)22272026/09/23 09:32:05 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-config22282026/09/23 09:32:05 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=194.671979ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/09/23 09:32:05 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=022302026/09/23 09:32:05 INFO Vacuumed table table=pending_closures22312026/09/23 09:32:05 INFO Vacuumed table table=pending_objects22322026/09/23 09:32:05 INFO Vacuumed table table=multipart_uploads22332026/09/23 09:32:05 INFO Vacuumed table table=closures22342026/09/23 09:32:05 INFO Vacuumed table table=objects22352026/09/23 09:32:05 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02236=== NAME TestClientIntegration2237 client_integration_test.go:323: Objects in database after GC:2238 client_integration_test.go:323: Successfully deleted all objects with GC --force2239--- PASS: TestClientIntegration (9.18s)22402026/09/23 09:32:06 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=408.977226ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2241{"timestamp":"2026-09-23T09:32:06.378624Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":4,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2296,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}22422026/09/23 09:32:06 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=775.786828ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22432026/09/23 09:32:07 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.710895484s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22442026/09/23 09:32:07 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02245=== NAME TestPinProtectsFromGC2246 client_integration_test.go:794: Pin successfully protected closure from garbage collection2247--- PASS: TestPinProtectsFromGC (9.73s)22482026/09/23 09:32:08 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"22492026/09/23 09:32:08 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_closures22502026/09/23 09:32:09 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.793999ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22512026/09/23 09:32:09 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=373.578205ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22522026/09/23 09:32:09 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=775.150362ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2253{"timestamp":"2026-09-23T09:32:10.306887Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":4,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2296,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}22542026/09/23 09:32:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.624533681s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2255--- PASS: TestClientErrorHandling (0.00s)2256 --- PASS: TestClientErrorHandling/InvalidStorePath (1.02s)2257 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.28s)2258 --- PASS: TestClientErrorHandling/ServerNotAvailable (10.62s)2259PASS2260{"timestamp":"2026-09-23T09:32:12.071309Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54023","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2260,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}22612026-09-23 09:32:12.512 UTC [62476] LOG: received smart shutdown request22622026-09-23 09:32:12.514 UTC [62476] LOG: background worker "logical replication launcher" (PID 62500) exited with exit code 122632026-09-23 09:32:12.518 UTC [62492] LOG: shutting down22642026-09-23 09:32:12.518 UTC [62492] LOG: checkpoint starting: shutdown immediate22652026-09-23 09:32:20.744 UTC [62492] LOG: checkpoint complete: wrote 13099 buffers (79.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=1.796 s, sync=6.310 s, total=8.227 s; sync files=19072, longest=0.106 s, average=0.001 s; distance=264774 kB, estimate=264774 kB; lsn=0/11A1E8A8, redo lsn=0/11A1E8A822662026-09-23 09:32:20.756 UTC [62476] LOG: database system is shut down22672026/09/23 09:32:22 ERROR failed to kill rustfs error="no such process"22682026/09/23 09:32:22 ERROR failed to kill rustfs error="no such process"2269Running OIDC tests...2270=== RUN TestAudienceForIssuer2271=== PAUSE TestAudienceForIssuer2272=== RUN TestGlobMatch2273=== PAUSE TestGlobMatch2274=== RUN TestValidateToken_ValidToken2275=== PAUSE TestValidateToken_ValidToken2276=== RUN TestValidateToken_WrongAudience2277=== PAUSE TestValidateToken_WrongAudience2278=== RUN TestValidateToken_Expired2279=== PAUSE TestValidateToken_Expired2280=== RUN TestValidateToken_BoundClaimsMismatch2281=== PAUSE TestValidateToken_BoundClaimsMismatch2282=== RUN TestValidateToken_BoundSubjectMismatch2283=== PAUSE TestValidateToken_BoundSubjectMismatch2284=== RUN TestValidateToken_MultipleProviders2285=== PAUSE TestValidateToken_MultipleProviders2286=== RUN TestValidateToken_NoMatchingProvider2287=== PAUSE TestValidateToken_NoMatchingProvider2288=== RUN TestValidateToken_KubernetesServiceAccount2289=== PAUSE TestValidateToken_KubernetesServiceAccount2290=== RUN TestNewValidator_KubernetesRequiresCA2291=== PAUSE TestNewValidator_KubernetesRequiresCA2292=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2293=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2294=== RUN TestPins_ReservedForMatchingRule2295=== PAUSE TestPins_ReservedForMatchingRule2296=== RUN TestPins_TopLevelShorthand2297=== PAUSE TestPins_TopLevelShorthand2298=== RUN TestPins_ConfigValidation2299=== PAUSE TestPins_ConfigValidation2300=== RUN TestScopes_LegacyProviderDefaultsToWrite2301=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2302=== RUN TestScopes_Rules2303=== PAUSE TestScopes_Rules2304=== RUN TestScopes_ConfigValidation2305=== PAUSE TestScopes_ConfigValidation2306=== CONT TestAudienceForIssuer2307--- PASS: TestAudienceForIssuer (0.00s)2308=== CONT TestScopes_ConfigValidation2309=== CONT TestValidateToken_KubernetesServiceAccount2310=== CONT TestPins_TopLevelShorthand2311=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2312=== CONT TestValidateToken_BoundClaimsMismatch2313--- PASS: TestScopes_ConfigValidation (0.00s)2314=== CONT TestValidateToken_Expired2315=== CONT TestScopes_LegacyProviderDefaultsToWrite2316=== CONT TestPins_ConfigValidation2317=== CONT TestValidateToken_ValidToken2318=== CONT TestNewValidator_KubernetesRequiresCA2319--- PASS: TestPins_ConfigValidation (0.00s)2320=== CONT TestValidateToken_WrongAudience2321=== CONT TestScopes_Rules23222026/09/23 09:32:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54250/oidc2323--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)2324=== CONT TestPins_ReservedForMatchingRule23252026/09/23 09:32:29 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323262026/09/23 09:32:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54253/oidc2327--- PASS: TestPins_TopLevelShorthand (0.39s)2328=== CONT TestValidateToken_NoMatchingProvider2329--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.40s)2330=== CONT TestValidateToken_MultipleProviders23312026/09/23 09:32:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54256/oidc2332--- PASS: TestValidateToken_ValidToken (0.43s)2333=== CONT TestValidateToken_BoundSubjectMismatch23342026/09/23 09:32:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54259/oidc2335--- PASS: TestValidateToken_WrongAudience (0.65s)2336=== CONT TestGlobMatch2337=== RUN TestGlobMatch/foo_foo2338=== PAUSE TestGlobMatch/foo_foo2339=== RUN TestGlobMatch/foo_bar2340=== PAUSE TestGlobMatch/foo_bar2341=== RUN TestGlobMatch/*_2342=== PAUSE TestGlobMatch/*_2343=== RUN TestGlobMatch/*_anything2344=== PAUSE TestGlobMatch/*_anything2345=== RUN TestGlobMatch/foo*_foo2346=== PAUSE TestGlobMatch/foo*_foo2347=== RUN TestGlobMatch/foo*_foobar2348=== PAUSE TestGlobMatch/foo*_foobar2349=== RUN TestGlobMatch/foo*_bar2350=== PAUSE TestGlobMatch/foo*_bar2351=== RUN TestGlobMatch/*bar_bar2352=== PAUSE TestGlobMatch/*bar_bar2353=== RUN TestGlobMatch/*bar_foobar2354=== PAUSE TestGlobMatch/*bar_foobar2355=== RUN TestGlobMatch/*bar_foo2356=== PAUSE TestGlobMatch/*bar_foo2357=== RUN TestGlobMatch/foo*bar_foobar2358=== PAUSE TestGlobMatch/foo*bar_foobar2359=== RUN TestGlobMatch/foo*bar_foo123bar2360=== PAUSE TestGlobMatch/foo*bar_foo123bar2361=== RUN TestGlobMatch/foo*bar_foobarbaz2362=== PAUSE TestGlobMatch/foo*bar_foobarbaz2363=== RUN TestGlobMatch/*/*_foo/bar2364=== PAUSE TestGlobMatch/*/*_foo/bar2365=== RUN TestGlobMatch/*/*_foo2366=== PAUSE TestGlobMatch/*/*_foo2367=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2368=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2369=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02370=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02371=== RUN TestGlobMatch/refs/*/main_refs/heads/main2372=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2373=== RUN TestGlobMatch/fo?_foo2374=== PAUSE TestGlobMatch/fo?_foo2375=== RUN TestGlobMatch/fo?_fo2376=== PAUSE TestGlobMatch/fo?_fo2377=== RUN TestGlobMatch/fo?_fooo2378=== PAUSE TestGlobMatch/fo?_fooo2379=== RUN TestGlobMatch/?oo_foo2380=== PAUSE TestGlobMatch/?oo_foo2381=== RUN TestGlobMatch/?oo_boo2382=== PAUSE TestGlobMatch/?oo_boo2383=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2384=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2385=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2386=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2387=== CONT TestGlobMatch/foo_foo2388=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2389=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2390=== CONT TestGlobMatch/?oo_boo2391=== CONT TestGlobMatch/?oo_foo2392=== CONT TestGlobMatch/fo?_fooo2393=== CONT TestGlobMatch/fo?_fo2394=== CONT TestGlobMatch/fo?_foo2395=== CONT TestGlobMatch/refs/*/main_refs/heads/main2396=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02397=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2398=== CONT TestGlobMatch/*/*_foo2399=== CONT TestGlobMatch/*/*_foo/bar2400=== CONT TestGlobMatch/foo*bar_foobarbaz2401=== CONT TestGlobMatch/foo*bar_foo123bar2402=== CONT TestGlobMatch/foo*bar_foobar2403=== CONT TestGlobMatch/*bar_foo2404=== CONT TestGlobMatch/*bar_foobar2405=== CONT TestGlobMatch/*bar_bar2406=== CONT TestGlobMatch/foo*_bar2407=== CONT TestGlobMatch/foo*_foobar2408=== CONT TestGlobMatch/foo*_foo2409=== CONT TestGlobMatch/*_anything2410=== CONT TestGlobMatch/*_2411=== CONT TestGlobMatch/foo_bar2412--- PASS: TestGlobMatch (0.00s)2413 --- PASS: TestGlobMatch/foo_foo (0.00s)2414 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2415 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2416 --- PASS: TestGlobMatch/?oo_boo (0.00s)2417 --- PASS: TestGlobMatch/?oo_foo (0.00s)2418 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2419 --- PASS: TestGlobMatch/fo?_fo (0.00s)2420 --- PASS: TestGlobMatch/fo?_foo (0.00s)2421 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2422 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2423 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2424 --- PASS: TestGlobMatch/*/*_foo (0.00s)2425 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2426 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2427 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2428 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2429 --- PASS: TestGlobMatch/*bar_foo (0.00s)2430 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2431 --- PASS: TestGlobMatch/*bar_bar (0.00s)2432 --- PASS: TestGlobMatch/foo*_bar (0.00s)2433 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2434 --- PASS: TestGlobMatch/foo*_foo (0.00s)2435 --- PASS: TestGlobMatch/*_anything (0.00s)2436 --- PASS: TestGlobMatch/*_ (0.00s)2437 --- PASS: TestGlobMatch/foo_bar (0.00s)24382026/09/23 09:32:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54261/oidc2439--- PASS: TestPins_ReservedForMatchingRule (1.02s)24402026/09/23 09:32:29 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:542632441--- PASS: TestValidateToken_KubernetesServiceAccount (1.20s)24422026/09/23 09:32:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54266/oidc2443--- PASS: TestValidateToken_BoundClaimsMismatch (1.46s)24442026/09/23 09:32:30 http: TLS handshake error from 127.0.0.1:54269: remote error: tls: bad certificate2445--- PASS: TestNewValidator_KubernetesRequiresCA (1.51s)24462026/09/23 09:32:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54271/oidc24472026/09/23 09:32:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54270/oidc24482026/09/23 09:32:30 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54265/oidc2449--- PASS: TestValidateToken_BoundSubjectMismatch (1.15s)2450--- PASS: TestValidateToken_NoMatchingProvider (1.19s)24512026/09/23 09:32:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54276/oidc2452--- PASS: TestValidateToken_Expired (1.61s)2453--- PASS: TestScopes_Rules (1.65s)24542026/09/23 09:32:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54278/oidc24552026/09/23 09:32:31 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54279/oidc2456--- PASS: TestValidateToken_MultipleProviders (2.39s)2457PASS2458Running hook tests...2459=== RUN TestSendPathsEmpty2460=== PAUSE TestSendPathsEmpty2461=== RUN TestQueueEnqueueAndFetch2462=== PAUSE TestQueueEnqueueAndFetch2463=== RUN TestQueueDeduplication2464=== PAUSE TestQueueDeduplication2465=== RUN TestQueueRemove2466=== PAUSE TestQueueRemove2467=== RUN TestQueueFetchBatchLimit2468=== PAUSE TestQueueFetchBatchLimit2469=== RUN TestQueueRetryMovesToBack2470=== PAUSE TestQueueRetryMovesToBack2471=== RUN TestQueueFetchRemoveLifecycle2472=== PAUSE TestQueueFetchRemoveLifecycle2473=== RUN TestQueueConcurrentWriters2474=== PAUSE TestQueueConcurrentWriters2475=== RUN TestQueueRemoveLargeClosure2476=== PAUSE TestQueueRemoveLargeClosure2477=== RUN TestServerClientIntegration2478=== PAUSE TestServerClientIntegration2479=== RUN TestServerQueueError2480=== PAUSE TestServerQueueError2481=== RUN TestGetListenerSocketActivation2482 server_test.go:210: === RUN TestGetListenerSocketActivation2483 --- PASS: TestGetListenerSocketActivation (0.00s)2484 PASS2485 2486--- PASS: TestGetListenerSocketActivation (0.02s)2487=== RUN TestDrainIsolatesPoisonPath2488=== PAUSE TestDrainIsolatesPoisonPath2489=== RUN TestRunNotBlockedByPoisonHead2490=== PAUSE TestRunNotBlockedByPoisonHead2491=== RUN TestDrainGivesUpWhenServerDown2492=== PAUSE TestDrainGivesUpWhenServerDown2493=== RUN TestFailedPathPrunedByLaterClosure2494=== PAUSE TestFailedPathPrunedByLaterClosure2495=== RUN TestWorkerUploadsAndRemoves2496=== PAUSE TestWorkerUploadsAndRemoves2497=== RUN TestWorkerSkipsGCdPaths2498=== PAUSE TestWorkerSkipsGCdPaths2499=== RUN TestWorkerPrunesClosureDeps2500=== PAUSE TestWorkerPrunesClosureDeps2501=== RUN TestDrainTimeout2502=== PAUSE TestDrainTimeout2503=== CONT TestSendPathsEmpty2504--- PASS: TestSendPathsEmpty (0.00s)2505=== CONT TestDrainTimeout2506=== CONT TestServerClientIntegration2507=== CONT TestQueueRetryMovesToBack2508=== CONT TestQueueRemoveLargeClosure2509=== CONT TestQueueConcurrentWriters2510=== CONT TestQueueDeduplication2511=== CONT TestQueueFetchRemoveLifecycle2512=== CONT TestWorkerPrunesClosureDeps2513=== CONT TestFailedPathPrunedByLaterClosure2514=== CONT TestWorkerSkipsGCdPaths2515--- PASS: TestServerClientIntegration (0.00s)2516=== CONT TestServerQueueError25172026/09/23 09:32:31 ERROR Failed to queue paths error="permission denied" count=12518--- PASS: TestServerQueueError (0.00s)2519=== CONT TestDrainGivesUpWhenServerDown25202026/09/23 09:32:31 INFO Upload queue status pending=225212026/09/23 09:32:31 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-52991-3138667589/TestWorkerSkipsGCdPaths128314715/002/nonexistent25222026/09/23 09:32:31 INFO Uploading batch count=12523--- PASS: TestQueueDeduplication (0.01s)2524=== CONT TestQueueEnqueueAndFetch2525--- PASS: TestQueueRetryMovesToBack (0.01s)2526--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2527=== CONT TestDrainIsolatesPoisonPath2528=== CONT TestQueueFetchBatchLimit25292026/09/23 09:32:31 INFO Uploading batch count=225302026/09/23 09:32:31 INFO Uploading batch count=125312026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=125322026/09/23 09:32:31 INFO Upload queue status pending=225332026/09/23 09:32:31 INFO Uploading batch count=125342026/09/23 09:32:31 INFO Uploading batch count=125352026/09/23 09:32:31 INFO Uploading batch count=125362026/09/23 09:32:31 INFO Uploading batch count=225372026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=225382026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainGivesUpWhenServerDown3394646658/002/a25392026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainGivesUpWhenServerDown3394646658/002/b2540--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2541=== CONT TestRunNotBlockedByPoisonHead25422026/09/23 09:32:31 INFO Uploading batch count=225432026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=225442026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainGivesUpWhenServerDown3394646658/002/c25452026/09/23 09:32:31 INFO Uploading batch count=425462026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=42547--- PASS: TestQueueFetchBatchLimit (0.01s)2548=== CONT TestWorkerUploadsAndRemoves25492026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainGivesUpWhenServerDown3394646658/002/d25502026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainIsolatesPoisonPath4170434462/002/bbb2551--- PASS: TestQueueEnqueueAndFetch (0.01s)2552=== CONT TestQueueRemove25532026/09/23 09:32:31 INFO Uploading batch count=225542026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=225552026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainGivesUpWhenServerDown3394646658/002/e25562026/09/23 09:32:31 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-52991-3138667589/TestDrainGivesUpWhenServerDown3394646658/002/f25572026/09/23 09:32:31 ERROR Drain finished with paths left in queue remaining=1025582026/09/23 09:32:31 INFO Uploading batch count=125592026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=125602026/09/23 09:32:31 INFO Uploading batch count=125612026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=125622026/09/23 09:32:31 INFO Upload queue status pending=325632026/09/23 09:32:31 INFO Uploading batch count=125642026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=125652026/09/23 09:32:31 INFO Uploading batch count=125662026/09/23 09:32:31 ERROR Upload failed error="upload failed" count=125672026/09/23 09:32:31 ERROR Drain finished with paths left in queue remaining=12568--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2569--- PASS: TestWorkerSkipsGCdPaths (0.03s)2570--- PASS: TestDrainIsolatesPoisonPath (0.02s)25712026/09/23 09:32:31 INFO Upload queue status pending=225722026/09/23 09:32:31 INFO Uploading batch count=22573--- PASS: TestQueueRemove (0.01s)2574--- PASS: TestWorkerPrunesClosureDeps (0.04s)2575--- PASS: TestWorkerUploadsAndRemoves (0.03s)2576--- PASS: TestQueueConcurrentWriters (0.15s)25772026/09/23 09:32:32 ERROR Upload failed error="context deadline exceeded" count=225782026/09/23 09:32:32 ERROR Drain finished with paths left in queue remaining=42579--- PASS: TestDrainTimeout (0.22s)2580--- PASS: TestQueueRemoveLargeClosure (0.57s)25812026/09/23 09:32:32 INFO Uploading batch count=125822026/09/23 09:32:32 INFO Uploading batch count=125832026/09/23 09:32:32 INFO Uploading batch count=125842026/09/23 09:32:32 ERROR Upload failed error="upload failed" count=125852026/09/23 09:32:32 INFO Uploading batch count=125862026/09/23 09:32:32 ERROR Upload failed error="upload failed" count=125872026/09/23 09:32:32 INFO Uploading batch count=125882026/09/23 09:32:32 ERROR Upload failed error="upload failed" count=125892026/09/23 09:32:32 INFO Uploading batch count=125902026/09/23 09:32:32 ERROR Upload failed error="upload failed" count=125912026/09/23 09:32:32 ERROR Drain finished with paths left in queue remaining=12592--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2593PASS