niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #419
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestPartSizeForNAR20=== PAUSE TestPartSizeForNAR21=== RUN TestUploadMultipart_SupersededByPeer22=== PAUSE TestUploadMultipart_SupersededByPeer23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestSupersededNARStillUploadsListing28=== PAUSE TestSupersededNARStillUploadsListing29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestEncodeNixBase32115=== RUN TestEncodeNixBase32/test_string_hash116=== CONT TestRetryTimeoutOutlastsMaxRetries117=== CONT TestScriptTokenEmptyCommand118--- PASS: TestScriptTokenEmptyCommand (0.00s)119=== CONT TestScriptTokenScriptFails120=== CONT TestScriptTokenBadJSON121=== CONT TestScriptTokenEmptyToken122=== CONT TestScriptTokenCachesUntilRefresh123=== CONT TestScriptTokenNoExpiryRerunsEveryCall124=== CONT TestFileTokenEmpty125=== CONT TestFileTokenMissing126=== CONT TestFileTokenReadsAndCaches127=== CONT TestStaticToken128=== CONT TestSetClientTLSErrors129=== CONT TestSetClientTLSDoesNotMutateDefaultTransport130=== CONT TestSetClientTLS131=== CONT TestStreamPushStopsWhenCanceled132=== CONT TestClientSignaturesByStorePath133=== CONT TestStreamPushReportsSkippedPaths134=== CONT TestStreamPushReportsSignatures135=== CONT TestStreamPushRequestLine136=== CONT TestStreamPushGivesUpOnDeadServer137=== CONT TestStreamPushIsolatesFailures138=== CONT TestUploadMultipart_PartsInParallel139=== PAUSE TestEncodeNixBase32/test_string_hash140=== RUN TestEncodeNixBase32/empty_input141=== PAUSE TestEncodeNixBase32/empty_input142=== CONT TestStreamPushBatchesUnderLoad143--- PASS: TestFileTokenMissing (0.00s)144=== CONT TestShellSplitErrors145--- PASS: TestShellSplitErrors (0.00s)146=== CONT TestShellSplit147--- PASS: TestFileTokenEmpty (0.00s)148=== CONT TestDoWithRetry_FinalResponseBodyReadable149--- PASS: TestShellSplit (0.00s)150=== CONT TestDumpPathMatchesNix151=== CONT TestDumpPathWriterError152--- PASS: TestStaticToken (0.00s)153--- PASS: TestFileTokenReadsAndCaches (0.00s)154=== CONT TestDumpPathSingleFile155=== CONT TestStreamPushReportsEveryPath156=== CONT TestPathInfoCACompatibility157=== RUN TestPathInfoCACompatibility/null_ca_field158--- PASS: TestScriptTokenScriptFails (0.01s)159--- PASS: TestScriptTokenBadJSON (0.01s)160=== CONT TestDoWithRetry_BodyReplayedViaGetBody161=== PAUSE TestPathInfoCACompatibility/null_ca_field162=== RUN TestPathInfoCACompatibility/old_string_format_-_text163=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text164=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1652026/10/20 08:17:07 ERROR Upload failed error="bad path" count=3166=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive167=== RUN TestPathInfoCACompatibility/new_structured_format_-_text168=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text169=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method170=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method171--- PASS: TestStreamPushStopsWhenCanceled (0.08s)172=== CONT TestResolveStorePath173=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer174--- PASS: TestStreamPushReportsSkippedPaths (0.00s)1752026/10/20 08:17:07 ERROR Upload failed error="connection refused" count=20176=== CONT TestRegisterUploadedObjectReusesConnections1772026/10/20 08:17:07 ERROR Server seems unavailable, giving up on batch untried=171782026/10/20 08:17:07 ERROR Upload failed error=boom count=1179=== CONT TestSupersededNARStillUploadsListing180=== RUN TestSupersededNARStillUploadsListing/small_NAR181=== CONT TestRateLimiterFeedback182=== RUN TestRateLimiterFeedback/429_enables_limiter183=== PAUSE TestRateLimiterFeedback/429_enables_limiter1842026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:38953185=== RUN TestRateLimiterFeedback/503_enables_limiter186=== PAUSE TestRateLimiterFeedback/503_enables_limiter1872026/10/20 08:17:07 WARN Rate limiter enabled after throttle name=server-test rate=5188=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter189=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter190=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter191=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter1922026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:39285193=== CONT TestUploadMultipart_SupersededByPeer194=== RUN TestUploadMultipart_SupersededByPeer/exists195=== PAUSE TestUploadMultipart_SupersededByPeer/exists196=== RUN TestUploadMultipart_SupersededByPeer/missing197=== PAUSE TestUploadMultipart_SupersededByPeer/missing198=== CONT TestParsePathInfoJSONMultiplePaths1992026/10/20 08:17:07 ERROR Upload failed error=boom count=12002026/10/20 08:17:07 WARN Rate limiter backed off name=server-test rate=5201=== CONT TestPartSizeForNAR202=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2032026/10/20 08:17:07 WARN Rate limiter enabled after throttle name=server-test rate=52042026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:33201205=== RUN TestPartSizeForNAR/zero_stays_at_minimum206=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum207=== RUN TestPartSizeForNAR/small_stays_at_minimum208=== PAUSE TestPartSizeForNAR/small_stays_at_minimum209=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum210=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum211=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts212=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica213=== CONT TestParsePathInfoJSON214=== RUN TestParsePathInfoJSON/Nix_format215=== PAUSE TestParsePathInfoJSON/Nix_format216=== RUN TestParsePathInfoJSON/Lix_format217=== PAUSE TestParsePathInfoJSON/Lix_format2182026/10/20 08:17:07 WARN Rate limiter backed off name=server-test rate=5219=== RUN TestParsePathInfoJSON/empty_input2202026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:33201221=== PAUSE TestParsePathInfoJSON/empty_input222=== RUN TestParsePathInfoJSON/whitespace_only223=== PAUSE TestParsePathInfoJSON/whitespace_only224=== RUN TestParsePathInfoJSON/invalid_JSON2252026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:38953226=== PAUSE TestParsePathInfoJSON/invalid_JSON227=== CONT TestCaseHackSuffix228=== RUN TestSetClientTLSErrors/missing_cert_file229=== PAUSE TestSetClientTLSErrors/missing_cert_file230=== RUN TestSetClientTLSErrors/missing_key_file231=== PAUSE TestSetClientTLSErrors/missing_key_file232=== RUN TestSetClientTLSErrors/missing_ca_file233=== PAUSE TestSetClientTLSErrors/missing_ca_file234=== RUN TestSetClientTLSErrors/invalid_ca_file235=== PAUSE TestSetClientTLSErrors/invalid_ca_file236=== CONT TestEncodeNixBase32WithRealHash237=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry238--- PASS: TestStreamPushIsolatesFailures (0.08s)239--- PASS: TestStreamPushReportsEveryPath (0.08s)240--- PASS: TestStreamPushGivesUpOnDeadServer (0.09s)241--- PASS: TestClientSignaturesByStorePath (0.00s)242--- PASS: TestDoServerRequestAttachesToken (0.09s)243=== CONT TestPathInfoHashCompatibility244=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)245=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)246=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon247=== CONT TestFilterOversizedClosures248=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths249=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts250=== RUN TestPartSizeForNAR/1_TiB251=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess252=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun253=== CONT TestConvertHashToNix32254=== RUN TestConvertHashToNix32/SRI_format_to_Nix32255=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32256=== RUN TestConvertHashToNix32/already_Nix32_format257=== PAUSE TestConvertHashToNix32/already_Nix32_format258=== RUN TestConvertHashToNix32/invalid_format259=== PAUSE TestConvertHashToNix32/invalid_format260=== CONT TestEncodeNixBase32/test_string_hash261=== CONT TestEncodeNixBase32/empty_input262=== CONT TestPathInfoCACompatibility/null_ca_field263=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon264=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI265=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI266=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512267=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512268=== RUN TestFilterOversizedClosures/no_limit_keeps_everything2692026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:38953270=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything271=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped272=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2732026/10/20 08:17:07 INFO Garbage collection started274=== RUN TestFilterOversizedClosures/all_closures_skipped275=== PAUSE TestFilterOversizedClosures/all_closures_skipped276=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2772026/10/20 08:17:07 WARN Rate limiter enabled after throttle name=server-test rate=5278=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths279--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)280--- PASS: TestScriptTokenEmptyToken (0.09s)281--- PASS: TestResolveStorePath (0.00s)282--- PASS: TestStreamPushReportsSignatures (0.09s)283--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.09s)284--- PASS: TestEncodeNixBase32WithRealHash (0.00s)285--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.08s)286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== PAUSE TestSupersededNARStillUploadsListing/small_NAR288=== RUN TestSupersededNARStillUploadsListing/dump_cut_short289=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short290=== CONT TestUploadMultipart_SupersededByPeer/missing2912026/10/20 08:17:07 INFO Garbage collection started292=== CONT TestGetStorePathHash293=== RUN TestGetStorePathHash/valid_store_path294=== PAUSE TestGetStorePathHash/valid_store_path295=== RUN TestGetStorePathHash/basename_without_hyphen_should_error296=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error297=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error298=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error299=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error300=== CONT TestRateLimiterFeedback/429_enables_limiter301--- PASS: TestEncodeNixBase32 (0.00s)302 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)303 --- PASS: TestEncodeNixBase32/empty_input (0.00s)304--- PASS: TestScriptTokenCachesUntilRefresh (0.09s)305=== CONT TestPathInfoCACompatibility/new_structured_format_-_text306=== RUN TestSetClientTLS/rejects_connection_without_client_cert307=== PAUSE TestPartSizeForNAR/1_TiB308=== RUN TestPartSizeForNAR/5_TiB_S3_max_object309=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object310=== RUN TestPartSizeForNAR/capped_at_5_GiB311=== PAUSE TestPartSizeForNAR/capped_at_5_GiB312=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3132026/10/20 08:17:07 WARN Rate limiter enabled after throttle name=s3-test rate=53142026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37263315=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert316=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA317=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA318=== RUN TestSetClientTLS/preserves_debug_logging_transport3192026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:38953320=== PAUSE TestSetClientTLS/preserves_debug_logging_transport321=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails322=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails323=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter324=== CONT TestUploadMultipart_SupersededByPeer/exists325=== CONT TestRateLimiterFeedback/503_enables_limiter3262026/10/20 08:17:07 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=0327=== CONT TestParsePathInfoJSON/Nix_format3282026/10/20 08:17:07 WARN Rate limiter enabled after throttle name=server-test rate=53292026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:407933302026/10/20 08:17:07 WARN Rate limiter enabled after throttle name=server-test rate=5331=== CONT TestParsePathInfoJSON/empty_input3322026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:44703333=== CONT TestConvertHashToNix32/SRI_format_to_Nix323342026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:389533352026/10/20 08:17:07 WARN Rate limiter backed off name=server-test rate=53362026/10/20 08:17:07 WARN Garbage collection finished on another replica. Its statistics are not available here337=== CONT TestParsePathInfoJSON/Lix_format338=== CONT TestConvertHashToNix32/invalid_format3392026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:38953340=== CONT TestSetClientTLSErrors/missing_key_file341=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)342=== CONT TestFilterOversizedClosures/no_limit_keeps_everything343=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths344=== CONT TestConvertHashToNix32/already_Nix32_format345=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon346=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error347=== CONT TestSetClientTLSErrors/missing_cert_file348--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)3492026/10/20 08:17:07 WARN Rate limiter backed off name=server-test rate=5350=== CONT TestParsePathInfoJSON/whitespace_only351=== CONT TestParsePathInfoJSON/invalid_JSON352=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method353=== CONT TestSetClientTLSErrors/missing_ca_file354=== CONT TestSetClientTLSErrors/invalid_ca_file355=== CONT TestPathInfoCACompatibility/old_string_format_-_text356=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512357=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts358=== CONT TestPartSizeForNAR/1_TiB359=== CONT TestFilterOversizedClosures/all_closures_skipped360=== CONT TestSetClientTLS/preserves_debug_logging_transport3612026/10/20 08:17:07 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=50362=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3632026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:38953364--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)3652026/10/20 08:17:07 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=2000366=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths367=== CONT TestGetStorePathHash/valid_store_path368=== CONT TestPartSizeForNAR/zero_stays_at_minimum369=== CONT TestPartSizeForNAR/5_TiB_S3_max_object370=== CONT TestPartSizeForNAR/capped_at_5_GiB371=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI372=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum373=== CONT TestPartSizeForNAR/small_stays_at_minimum374=== CONT TestSetClientTLS/rejects_connection_without_client_cert375=== CONT TestSupersededNARStillUploadsListing/small_NAR376=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA377=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails378--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)379 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)380 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)381--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.10s)3822026/10/20 08:17:07 INFO Uploading abc-hello (1.0GB)383--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)384--- PASS: TestRateLimiterFeedback (0.00s)385 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)386 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)387 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)388 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)389--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)390 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)391 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)392--- PASS: TestParsePathInfoJSON (0.00s)393 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)394 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)395 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)396 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)397 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)3982026/10/20 08:17:07 INFO Uploading abc-hello (1.0GB)399=== CONT TestSupersededNARStillUploadsListing/dump_cut_short4002026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:38953401=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error402=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error403=== CONT TestGetStorePathHash/basename_without_hyphen_should_error404--- PASS: TestPathInfoHashCompatibility (0.00s)405 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)406 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)407 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)408 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)409--- PASS: TestPathInfoCACompatibility (0.08s)410 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)411 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)412 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)413 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)414 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)415--- PASS: TestConvertHashToNix32 (0.00s)416 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)417 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)418 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)419--- PASS: TestPartSizeForNAR (0.00s)420 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)421 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)422 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)423 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)424 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)425 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)426 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)427--- PASS: TestFilterOversizedClosures (0.00s)428 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)429 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)430 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)431--- PASS: TestSetClientTLSErrors (0.09s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)434 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)435 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)436--- PASS: TestGetStorePathHash (0.01s)437 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)438 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)439 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)440 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)4412026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:389534422026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:38953443--- PASS: TestCaseHackSuffix (0.15s)444--- PASS: TestDumpPathSingleFile (0.24s)4452026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:389534462026/10/20 08:17:07 http: TLS handshake error from 127.0.0.1:54938: remote error: tls: bad certificate447--- PASS: TestStreamPushBatchesUnderLoad (0.25s)448--- PASS: TestSetClientTLS (0.01s)449 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.14s)450 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.14s)451 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.14s)4522026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:389534532026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:389534542026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:389534552026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:38953456--- PASS: TestStreamPushRequestLine (0.25s)4572026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:389534582026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:389534592026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:389534602026/10/20 08:17:07 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:38953461--- PASS: TestRegisterUploadedObjectReusesConnections (0.17s)462--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.26s)463--- PASS: TestDumpPathWriterError (0.26s)4642026/10/20 08:17:07 INFO Uploading abc-hello (1.0GB)4652026/10/20 08:17:07 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:42909/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:42909/part/24662026/10/20 08:17:07 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"467--- PASS: TestDumpPathMatchesNix (0.32s)468--- PASS: TestSupersededNARStillUploadsListing (0.00s)469 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.14s)470 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.14s)471 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.69s)472--- PASS: TestUploadMultipart_PartsInParallel (0.82s)4732026/10/20 08:17:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:33669/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:33669/api/uploads/complete4742026/10/20 08:17:08 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4752026/10/20 08:17:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:33669/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:33669/api/uploads/complete4762026/10/20 08:17:08 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4772026/10/20 08:17:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:33669/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:33669/api/uploads/complete4782026/10/20 08:17:08 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"479--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)480--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "nixbld".484This user must also own the server process.485486The database cluster will be initialized with locale "C".487The default database encoding has accordingly been set to "SQL_ASCII".488The default text search configuration will be set to "english".489490Data page checksums are enabled.491492creating directory /build/postgres231468924/data ... ok493creating subdirectories ... ok494selecting dynamic shared memory implementation ... posix495selecting default "max_connections" ... 100496selecting default "shared_buffers" ... 128MB497selecting default time zone ... UTC498creating configuration files ... ok499running bootstrap script ... ok500performing post-bootstrap initialization ... ok501syncing data to disk ... ok502503initdb: warning: enabling "trust" authentication for local connections504initdb: 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.505506Success. You can now start the database server using:507508 pg_ctl -D /build/postgres231468924/data -l logfile start509510/build/postgres231468924:5432 - no response5112026-10-20 08:17:09.596 UTC [129] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5122026-10-20 08:17:09.597 UTC [129] LOG: listening on Unix socket "/build/postgres231468924/.s.PGSQL.5432"5132026-10-20 08:17:09.601 UTC [136] LOG: database system was shut down at 2026-10-20 08:17:09 UTC5142026-10-20 08:17:09.605 UTC [129] LOG: database system is ready to accept connections515/build/postgres231468924:5432 - accepting connections516=== RUN TestService_AuthMiddleware517=== PAUSE TestService_AuthMiddleware518=== RUN TestService_AuthMiddleware_MTLSProxyHeader519=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader520=== RUN TestService_AuthMiddleware_MTLSBoundSubjects521=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects522=== RUN TestService_ReadAuthMiddleware523=== PAUSE TestService_ReadAuthMiddleware524=== RUN TestService_AuthMiddleware_OIDC525=== PAUSE TestService_AuthMiddleware_OIDC526=== RUN TestService_RequireScope_OIDC527=== PAUSE TestService_RequireScope_OIDC528=== RUN TestService_ReadScope_PublicByDefault529=== PAUSE TestService_ReadScope_PublicByDefault530=== RUN TestCacheConfigHandler531=== PAUSE TestCacheConfigHandler532=== RUN TestCacheStatsHandler533=== PAUSE TestCacheStatsHandler534=== RUN TestClientCADerivations535=== PAUSE TestClientCADerivations536=== RUN TestClientErrorHandling537=== PAUSE TestClientErrorHandling538=== RUN TestClientIntegration539=== PAUSE TestClientIntegration540=== RUN TestClientMultipleUploads541=== PAUSE TestClientMultipleUploads542=== RUN TestClientWithDependencies543=== PAUSE TestClientWithDependencies544=== RUN TestClientSharedPathCommittedMidPush545=== PAUSE TestClientSharedPathCommittedMidPush546=== RUN TestPinProtectsFromGC547=== PAUSE TestPinProtectsFromGC548=== RUN TestClientPushesUseOnePush549=== PAUSE TestClientPushesUseOnePush550=== RUN TestClientFallsBackToClosures551=== PAUSE TestClientFallsBackToClosures552=== RUN TestDeleteClosuresRacingPins553=== PAUSE TestDeleteClosuresRacingPins554=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock555=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== RUN TestResolveDBConnectionString557=== PAUSE TestResolveDBConnectionString558=== RUN TestConnectWaitsForAPeerMigration559=== PAUSE TestConnectWaitsForAPeerMigration560=== RUN TestLeadElectsOneAndHandsOver561=== PAUSE TestLeadElectsOneAndHandsOver562=== RUN TestLeadIncumbentWinsAfterRestart5632026/10/20 08:17:10 INFO lead: acquired remote=192.0.2.1:12345642026/10/20 08:17:10 INFO lead: released remote=192.0.2.1:12345652026/10/20 08:17:10 INFO lead: acquired remote=192.0.2.1:12345662026/10/20 08:17:11 INFO lead: released remote=192.0.2.1:1234567--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)568=== RUN TestLeadIncumbentAnnouncesAtOnce569=== PAUSE TestLeadIncumbentAnnouncesAtOnce570=== RUN TestLeadEndsOnShutdown571=== PAUSE TestLeadEndsOnShutdown572=== RUN TestLeadEndsWhenItsConnectionHangs5732026/10/20 08:17:12 INFO lead: acquired remote=192.0.2.1:12345742026-10-20 08:17:13.407 UTC [577] FATAL: terminating connection due to administrator command5752026/10/20 08:17:13 INFO lead: acquired remote=192.0.2.1:12345762026/10/20 08:17:14 WARN lead: lock connection lost error="timeout: context deadline exceeded"5772026/10/20 08:17:14 INFO lead: released remote=192.0.2.1:12345782026/10/20 08:17:14 INFO lead: released remote=192.0.2.1:1234579--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)580=== RUN TestGCAdvisoryLockBlocksConcurrentRun581=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun582=== RUN TestGCBugBareHashReferences583=== PAUSE TestGCBugBareHashReferences584=== RUN TestGCMetrics585=== PAUSE TestGCMetrics586=== RUN TestPushDedupSurvivesConcurrentGC587=== PAUSE TestPushDedupSurvivesConcurrentGC588=== RUN TestDeduplicatedObjectsRecordedAsPending589=== PAUSE TestDeduplicatedObjectsRecordedAsPending590=== RUN TestGCSweepSkipsPendingObjects591=== PAUSE TestGCSweepSkipsPendingObjects592=== RUN TestTombstonedObjectOfferedWithoutWaiting593=== PAUSE TestTombstonedObjectOfferedWithoutWaiting594=== RUN TestGCSweepDeliversEachKeyOnce595=== PAUSE TestGCSweepDeliversEachKeyOnce596=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection597=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== RUN TestForceGCDuringPushOffersSweptObject599=== PAUSE TestForceGCDuringPushOffersSweptObject600=== RUN TestFailedS3DeleteKeepsTombstone601=== PAUSE TestFailedS3DeleteKeepsTombstone602=== RUN TestSweepSkipsRowsLockedByPush603=== PAUSE TestSweepSkipsRowsLockedByPush604=== RUN TestRegisterCompletedObjectNeedsPendingRow605=== PAUSE TestRegisterCompletedObjectNeedsPendingRow606=== RUN TestGetExistingObjectsLocksRows607=== PAUSE TestGetExistingObjectsLocksRows608=== RUN TestSweepRechecksPendingAfterLocking609=== PAUSE TestSweepRechecksPendingAfterLocking610=== RUN TestPushWaitsForSweepHoldingRow611=== PAUSE TestPushWaitsForSweepHoldingRow612=== RUN TestCommitRacingPendingCleanupKeepsObjects613=== PAUSE TestCommitRacingPendingCleanupKeepsObjects614=== RUN TestGCEndsOnShutdown615=== PAUSE TestGCEndsOnShutdown616=== RUN TestGCTaskStore_StartNew617=== PAUSE TestGCTaskStore_StartNew618=== RUN TestGCTaskStore_DeduplicateSameParams619=== PAUSE TestGCTaskStore_DeduplicateSameParams620=== RUN TestGCTaskStore_ConflictDifferentParams621=== PAUSE TestGCTaskStore_ConflictDifferentParams622=== RUN TestGCTaskStore_GetEmpty623=== PAUSE TestGCTaskStore_GetEmpty624=== RUN TestGCTaskStore_GetReturnsLatest625=== PAUSE TestGCTaskStore_GetReturnsLatest626=== RUN TestGCTaskStore_CompletedAllowsNewTask627=== PAUSE TestGCTaskStore_CompletedAllowsNewTask628=== RUN TestGCTaskStore_PhaseUpdates629=== PAUSE TestGCTaskStore_PhaseUpdates630=== RUN TestGCTaskStore_Fail631=== PAUSE TestGCTaskStore_Fail632=== RUN TestGracefulShutdownDrainsInflight633=== PAUSE TestGracefulShutdownDrainsInflight634=== RUN TestService_healthCheckHandler635=== PAUSE TestService_healthCheckHandler636=== RUN TestService_readinessHandler637=== PAUSE TestService_readinessHandler638=== RUN TestGenerateLandingPage639=== PAUSE TestGenerateLandingPage640=== RUN TestCacheConfigHandlerMaxNarSize641=== PAUSE TestCacheConfigHandlerMaxNarSize642=== RUN TestCreatePendingClosureRejectsOversizedNAR643=== PAUSE TestCreatePendingClosureRejectsOversizedNAR644=== RUN TestNARDeduplicationMetadataUploadBug645=== PAUSE TestNARDeduplicationMetadataUploadBug646=== RUN TestMetricsInventory647=== PAUSE TestMetricsInventory648=== RUN TestMetricsCommit649=== PAUSE TestMetricsCommit650=== RUN TestService_NativeMTLS651=== PAUSE TestService_NativeMTLS652=== RUN TestServerTLSConfig653=== PAUSE TestServerTLSConfig654=== RUN TestMultipartCleanup655=== PAUSE TestMultipartCleanup656=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded657=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== RUN TestPendingCleanupUsesOneCutoff659=== PAUSE TestPendingCleanupUsesOneCutoff660=== RUN TestObjectStatsTrigger661=== PAUSE TestObjectStatsTrigger662=== RUN TestObjectStatsLargeCommit663=== PAUSE TestObjectStatsLargeCommit664=== RUN TestOrphanedObjectsGC665=== PAUSE TestOrphanedObjectsGC666=== RUN TestOrphanedObjectsGCStressTest667=== PAUSE TestOrphanedObjectsGCStressTest668=== RUN TestCreatePin_ReservedPins669=== PAUSE TestCreatePin_ReservedPins670=== RUN TestPresentReportsOnlyClosureRoots671=== PAUSE TestPresentReportsOnlyClosureRoots672=== RUN TestPresentRefreshesOnlyStaleClosures673=== PAUSE TestPresentRefreshesOnlyStaleClosures674=== RUN TestPresentNotReportedWhileGCDeletesClosure675=== PAUSE TestPresentNotReportedWhileGCDeletesClosure676=== RUN TestParseSingleRange677=== PAUSE TestParseSingleRange678=== RUN TestProxyHeadersOnlyTrustedOnSocket6792026/10/20 08:17:14 INFO Starting HTTP server address=127.0.0.1:378236802026/10/20 08:17:14 INFO Starting HTTP server address=proxy.sock6812026/10/20 08:17:14 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6822026/10/20 08:17:14 INFO Shutdown signal received, draining in-flight requests timeout=10s683--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)684=== RUN TestIsValidCachePath685=== PAUSE TestIsValidCachePath686=== RUN TestReadProxyNarinfo687=== PAUSE TestReadProxyNarinfo688=== RUN TestReadProxyNarinfoAlreadyDecompressed689=== PAUSE TestReadProxyNarinfoAlreadyDecompressed690=== RUN TestReadProxyContentNegotiation691=== PAUSE TestReadProxyContentNegotiation692=== RUN TestReadProxyNarStreaming693=== PAUSE TestReadProxyNarStreaming694=== RUN TestReadProxy404695=== PAUSE TestReadProxy404696=== RUN TestReadProxyInvalidPath697=== PAUSE TestReadProxyInvalidPath698=== RUN TestReadProxyHead699=== PAUSE TestReadProxyHead700=== RUN TestReadProxyOutlastsServerWriteTimeout701=== PAUSE TestReadProxyOutlastsServerWriteTimeout702=== RUN TestReadProxyConditionalGet703=== PAUSE TestReadProxyConditionalGet704=== RUN TestReadProxyRootRedirectsToIndexHTML705=== PAUSE TestReadProxyRootRedirectsToIndexHTML706=== RUN TestReadProxyDisabled707=== PAUSE TestReadProxyDisabled708=== RUN TestReadRedirectNar709=== PAUSE TestReadRedirectNar710=== RUN TestReadRedirectKeepsNarinfoProxied711=== PAUSE TestReadRedirectKeepsNarinfoProxied712=== RUN TestReadProxyRangeRequest713=== PAUSE TestReadProxyRangeRequest714=== RUN TestReadRedirectUsesPublicS3URL715=== PAUSE TestReadRedirectUsesPublicS3URL716=== RUN TestPush_OverlappingRootsStoreOneRowPerKey717=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey718=== RUN TestPush_CompleteCommitsEveryRoot719=== PAUSE TestPush_CompleteCommitsEveryRoot720=== RUN TestPush_RepeatedRootCommitsOnce721=== PAUSE TestPush_RepeatedRootCommitsOnce722=== RUN TestPush_CompleteWaitsForCleanupOfThePush723=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush724=== RUN TestPush_RootsAreLockedInByteOrder725=== PAUSE TestPush_RootsAreLockedInByteOrder726=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit727=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit728=== RUN TestPush_RejectsBadRequests729=== PAUSE TestPush_RejectsBadRequests730=== RUN TestPush_SignsNarinfosOfItsPendingObjects731=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects732=== RUN TestRedundantMultipartUpload733=== PAUSE TestRedundantMultipartUpload734=== RUN TestCompleteMultipartUpload_ErrorButObjectExists735=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists736=== RUN TestCompletedNarNotReofferedAcrossClosures737=== PAUSE TestCompletedNarNotReofferedAcrossClosures738=== RUN TestPresignedUploadRegisteredBeforeCommit739=== PAUSE TestPresignedUploadRegisteredBeforeCommit740=== RUN TestService_Rustfstest741=== PAUSE TestService_Rustfstest742=== RUN TestParseSize743=== PAUSE TestParseSize744=== RUN TestSkippedUploadsHandler745=== PAUSE TestSkippedUploadsHandler746=== RUN TestSystemdListenerNotActivated747--- PASS: TestSystemdListenerNotActivated (0.00s)748=== RUN TestWatchdogBeatsWhenHealthy749--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)750=== RUN TestWatchdogSkipsWhenUnhealthy7512026/10/20 08:17:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/20 08:17:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/20 08:17:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"761--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)762=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle763=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== RUN TestProxyWriteTimeout765=== PAUSE TestProxyWriteTimeout766=== RUN TestPendingClosureWriteTimeout767=== PAUSE TestPendingClosureWriteTimeout768=== RUN TestIsValidUploadKey769=== PAUSE TestIsValidUploadKey770=== RUN TestUploadHandlersRejectInvalidKeys771=== PAUSE TestUploadHandlersRejectInvalidKeys772=== RUN TestUploadHandlersRejectOversizedBody773=== PAUSE TestUploadHandlersRejectOversizedBody774=== RUN TestService_cleanupPendingClosuresHandler775=== PAUSE TestService_cleanupPendingClosuresHandler776=== RUN TestService_createPendingClosureHandler777=== PAUSE TestService_createPendingClosureHandler778=== RUN TestService_verifyS3Integrity779=== PAUSE TestService_verifyS3Integrity780=== RUN TestCompleteMultipartUnregistered781=== PAUSE TestCompleteMultipartUnregistered782=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT783=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT784=== CONT TestService_AuthMiddleware785=== CONT TestParseSize786--- PASS: TestParseSize (0.00s)787=== CONT TestPush_RejectsBadRequests788=== CONT TestReadRedirectUsesPublicS3URL789=== CONT TestCompleteMultipartUnregistered790=== CONT TestService_verifyS3Integrity791=== CONT TestService_createPendingClosureHandler792=== CONT TestService_cleanupPendingClosuresHandler793=== CONT TestUploadHandlersRejectOversizedBody794=== CONT TestUploadHandlersRejectInvalidKeys795=== CONT TestIsValidUploadKey796=== CONT TestPendingClosureWriteTimeout797=== RUN TestPendingClosureWriteTimeout/empty798=== CONT TestProxyWriteTimeout799=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle800=== CONT TestSkippedUploadsHandler801=== CONT TestService_Rustfstest802=== CONT TestPresignedUploadRegisteredBeforeCommit803=== CONT TestCompletedNarNotReofferedAcrossClosures804=== CONT TestCompleteMultipartUpload_ErrorButObjectExists805=== CONT TestRedundantMultipartUpload806=== CONT TestGCTaskStore_ConflictDifferentParams807=== CONT TestReadProxyRangeRequest808=== CONT TestPush_SignsNarinfosOfItsPendingObjects809=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT810=== CONT TestReadRedirectKeepsNarinfoProxied811=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info8122026/10/20 08:17:15 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000813=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info814=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal815=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal816=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key817=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key818=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key819=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key820=== RUN TestIsValidUploadKey/narinfo821=== PAUSE TestIsValidUploadKey/narinfo822=== PAUSE TestPendingClosureWriteTimeout/empty823=== RUN TestPendingClosureWriteTimeout/400_objects824=== RUN TestProxyWriteTimeout/narinfo825=== RUN TestIsValidUploadKey/nar_zst826--- PASS: TestSkippedUploadsHandler (0.01s)827=== CONT TestReadProxyDisabled828=== CONT TestReadRedirectNar829=== PAUSE TestProxyWriteTimeout/narinfo830=== RUN TestProxyWriteTimeout/1_GiB_nar831=== PAUSE TestProxyWriteTimeout/1_GiB_nar832=== RUN TestProxyWriteTimeout/10_GiB_nar833=== PAUSE TestProxyWriteTimeout/10_GiB_nar834=== RUN TestProxyWriteTimeout/unknown_size835=== PAUSE TestPendingClosureWriteTimeout/400_objects836=== PAUSE TestIsValidUploadKey/nar_zst837--- PASS: TestGCTaskStore_ConflictDifferentParams (0.14s)838=== CONT TestReadProxyRootRedirectsToIndexHTML839=== PAUSE TestProxyWriteTimeout/unknown_size840=== RUN TestPendingClosureWriteTimeout/670k_objects841=== CONT TestReadProxyConditionalGet842=== RUN TestIsValidUploadKey/nar_xz843=== PAUSE TestIsValidUploadKey/nar_xz844=== RUN TestIsValidUploadKey/nar_plain845=== PAUSE TestIsValidUploadKey/nar_plain846=== RUN TestIsValidUploadKey/listing847=== PAUSE TestIsValidUploadKey/listing848=== RUN TestIsValidUploadKey/build_log849=== PAUSE TestIsValidUploadKey/build_log850=== RUN TestIsValidUploadKey/build_log_home-manager_file851=== PAUSE TestIsValidUploadKey/build_log_home-manager_file852=== PAUSE TestPendingClosureWriteTimeout/670k_objects853=== RUN TestIsValidUploadKey/build_log_plus_in_name854=== PAUSE TestIsValidUploadKey/build_log_plus_in_name855=== RUN TestIsValidUploadKey/build_log_question_mark856=== PAUSE TestIsValidUploadKey/build_log_question_mark857=== RUN TestIsValidUploadKey/build_log_equals858=== PAUSE TestIsValidUploadKey/build_log_equals859=== RUN TestIsValidUploadKey/realisation860=== PAUSE TestIsValidUploadKey/realisation861=== RUN TestIsValidUploadKey/realisation_plus_in_output862=== PAUSE TestIsValidUploadKey/realisation_plus_in_output863=== RUN TestIsValidUploadKey/nix-cache-info864=== PAUSE TestIsValidUploadKey/nix-cache-info865=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline866=== RUN TestIsValidUploadKey/index.html867=== PAUSE TestIsValidUploadKey/index.html868=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline869=== RUN TestIsValidUploadKey/narinfo_key,_nar_type870=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type871=== CONT TestReadProxyOutlastsServerWriteTimeout872=== RUN TestIsValidUploadKey/nar_key,_narinfo_type873=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type874=== RUN TestIsValidUploadKey/listing_key,_narinfo_type875=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type876=== RUN TestIsValidUploadKey/traversal877=== PAUSE TestIsValidUploadKey/traversal878=== RUN TestIsValidUploadKey/traversal_nar879=== PAUSE TestIsValidUploadKey/traversal_nar880=== RUN TestIsValidUploadKey/absolute881=== PAUSE TestIsValidUploadKey/absolute882=== RUN TestIsValidUploadKey/empty_key883=== PAUSE TestIsValidUploadKey/empty_key884=== RUN TestIsValidUploadKey/unknown_type885=== PAUSE TestIsValidUploadKey/unknown_type886=== CONT TestLeadIncumbentAnnouncesAtOnce887=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts888=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts889=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure890=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure891=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart892=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart893=== CONT TestReadProxyHead8942026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures8952026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures8962026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures8972026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures8982026/10/20 08:17:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8992026/10/20 08:17:15 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst900--- PASS: TestCompleteMultipartUnregistered (0.44s)901=== CONT TestGCTaskStore_DeduplicateSameParams902--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)903=== CONT TestReadProxyInvalidPath904--- PASS: TestService_Rustfstest (0.45s)905=== CONT TestGCTaskStore_StartNew906--- PASS: TestGCTaskStore_StartNew (0.00s)907=== CONT TestReadProxy4049082026/10/20 08:17:15 INFO Received cleanup request method=DELETE path=/api/pending_closures9092026/10/20 08:17:15 INFO Aborted multipart uploads count=0 kept=09102026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures9112026/10/20 08:17:15 INFO Received cleanup request method=DELETE path=/api/pending_closures9122026/10/20 08:17:15 INFO Aborted multipart uploads count=1 kept=09132026/10/20 08:17:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9142026-10-20 08:17:15.665 UTC [655] ERROR: Closure does not exist: id=19152026-10-20 08:17:15.665 UTC [655] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9162026-10-20 08:17:15.665 UTC [655] STATEMENT: -- name: CommitPendingClosure :one917 SELECT commit_pending_closure($1::bigint)::bigint918 919--- PASS: TestService_cleanupPendingClosuresHandler (0.51s)920=== CONT TestGCEndsOnShutdown921=== RUN TestGCEndsOnShutdown/before_the_run922=== PAUSE TestGCEndsOnShutdown/before_the_run923=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete924=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete925=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark926=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark927=== CONT TestReadProxyNarStreaming928=== RUN TestPush_RejectsBadRequests/no_roots929=== PAUSE TestPush_RejectsBadRequests/no_roots930=== RUN TestPush_RejectsBadRequests/no_objects931=== PAUSE TestPush_RejectsBadRequests/no_objects932=== RUN TestPush_RejectsBadRequests/bad_root933=== PAUSE TestPush_RejectsBadRequests/bad_root934=== RUN TestPush_RejectsBadRequests/root_not_in_objects935=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects936=== CONT TestCommitRacingPendingCleanupKeepsObjects937--- PASS: TestReadRedirectUsesPublicS3URL (0.53s)938=== CONT TestPushWaitsForSweepHoldingRow9392026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures9402026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures9422026/10/20 08:17:15 INFO Received push request method=POST path=/api/pushes9432026/10/20 08:17:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9442026/10/20 08:17:15 INFO Signed narinfos id=1 count=19452026/10/20 08:17:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9462026/10/20 08:17:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9472026/10/20 08:17:15 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9482026/10/20 08:17:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9492026/10/20 08:17:15 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9502026/10/20 08:17:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9512026/10/20 08:17:15 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19522026/10/20 08:17:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9532026/10/20 08:17:15 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo954--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.62s)955=== CONT TestReadProxyContentNegotiation956--- PASS: TestReadProxyRangeRequest (0.63s)957=== CONT TestSweepRechecksPendingAfterLocking9582026/10/20 08:17:15 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"959--- PASS: TestService_AuthMiddleware (0.66s)960=== CONT TestReadProxyNarinfoAlreadyDecompressed9612026/10/20 08:17:15 INFO Received uploads request method=POST path=/api/pending_closures962--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.69s)963=== CONT TestGetExistingObjectsLocksRows9642026/10/20 08:17:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete965--- PASS: TestReadRedirectNar (0.66s)966=== CONT TestRegisterCompletedObjectNeedsPendingRow967--- PASS: TestReadProxyConditionalGet (0.73s)968=== CONT TestSweepSkipsRowsLockedByPush9692026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures9702026/10/20 08:17:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9712026/10/20 08:17:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete972--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.82s)973=== CONT TestReadProxyNarinfo9742026/10/20 08:17:16 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LmVmOWYwNGZjLWVlMGItNDFmMC05MWI0LWJhYjljMmQ5OTNmN3gxNzkyNDg0MjM1NTgxNzQyMDYw parts=109752026/10/20 08:17:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9762026/10/20 08:17:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LjA3YjIzNTcyLWE4OGMtNDE3ZS05NzcxLWIwZjdmZWE1NjYwNXgxNzkyNDg0MjM1NTU5Mjg2ODky parts=109772026/10/20 08:17:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete978--- PASS: TestReadProxyDisabled (1.00s)979=== CONT TestFailedS3DeleteKeepsTombstone9802026/10/20 08:17:16 INFO Completed upload id=1 objects=2 duration=4.58948ms9812026/10/20 08:17:16 INFO Completed upload id=1 objects=2 duration=4.72621ms9822026/10/20 08:17:16 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009832026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures9842026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures9852026/10/20 08:17:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures9862026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures9872026/10/20 08:17:16 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9882026/10/20 08:17:16 WARN Found objects in DB but missing from S3, will re-upload count=1989--- PASS: TestService_verifyS3Integrity (1.02s)990=== CONT TestIsValidCachePath991=== RUN TestIsValidCachePath/narinfo992=== PAUSE TestIsValidCachePath/narinfo993=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars994=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars995=== RUN TestIsValidCachePath/nar_zst996=== PAUSE TestIsValidCachePath/nar_zst997=== RUN TestIsValidCachePath/nar_xz998=== PAUSE TestIsValidCachePath/nar_xz999=== RUN TestIsValidCachePath/nar_bz21000=== PAUSE TestIsValidCachePath/nar_bz21001=== RUN TestIsValidCachePath/nar_uncompressed1002=== PAUSE TestIsValidCachePath/nar_uncompressed1003=== RUN TestIsValidCachePath/ls1004=== PAUSE TestIsValidCachePath/ls1005=== RUN TestIsValidCachePath/log1006=== PAUSE TestIsValidCachePath/log1007=== RUN TestIsValidCachePath/realisation1008=== PAUSE TestIsValidCachePath/realisation1009=== RUN TestIsValidCachePath/nix-cache-info1010=== PAUSE TestIsValidCachePath/nix-cache-info1011=== RUN TestIsValidCachePath/index.html1012=== PAUSE TestIsValidCachePath/index.html1013=== RUN TestIsValidCachePath/traversal_parent1014=== PAUSE TestIsValidCachePath/traversal_parent1015=== RUN TestIsValidCachePath/traversal_in_middle1016=== PAUSE TestIsValidCachePath/traversal_in_middle1017=== RUN TestIsValidCachePath/invalid_char_e1018=== PAUSE TestIsValidCachePath/invalid_char_e1019=== RUN TestIsValidCachePath/invalid_char_u1020=== PAUSE TestIsValidCachePath/invalid_char_u1021=== RUN TestIsValidCachePath/random_path1022=== PAUSE TestIsValidCachePath/random_path1023=== RUN TestIsValidCachePath/empty1024=== PAUSE TestIsValidCachePath/empty1025=== RUN TestIsValidCachePath/leading_slash1026=== PAUSE TestIsValidCachePath/leading_slash1027=== RUN TestIsValidCachePath/wrong_extension1028=== PAUSE TestIsValidCachePath/wrong_extension1029=== RUN TestIsValidCachePath/short_hash1030=== PAUSE TestIsValidCachePath/short_hash1031=== CONT TestForceGCDuringPushOffersSweptObject1032=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1033=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1034=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1035=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1036=== CONT TestClientMultipleUploads10372026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=010382026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures10392026/10/20 08:17:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010402026/10/20 08:17:16 INFO Vacuumed table table=pending_closures10412026/10/20 08:17:16 INFO Vacuumed table table=pending_objects10422026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads10432026/10/20 08:17:16 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10442026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures10452026/10/20 08:17:16 INFO Vacuumed table table=closures1046--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.05s)1047=== CONT TestParseSingleRange1048=== RUN TestParseSingleRange/none1049=== PAUSE TestParseSingleRange/none1050=== RUN TestParseSingleRange/unknown_unit1051=== PAUSE TestParseSingleRange/unknown_unit1052=== RUN TestParseSingleRange/multi-range_ignored1053=== PAUSE TestParseSingleRange/multi-range_ignored1054=== RUN TestParseSingleRange/malformed_no_dash1055=== PAUSE TestParseSingleRange/malformed_no_dash1056=== RUN TestParseSingleRange/malformed_both_empty1057=== PAUSE TestParseSingleRange/malformed_both_empty1058=== RUN TestParseSingleRange/malformed_end_before_start1059=== PAUSE TestParseSingleRange/malformed_end_before_start1060=== RUN TestParseSingleRange/closed1061=== PAUSE TestParseSingleRange/closed1062=== RUN TestParseSingleRange/open-ended1063=== PAUSE TestParseSingleRange/open-ended1064=== RUN TestParseSingleRange/end_clamped_to_size1065=== PAUSE TestParseSingleRange/end_clamped_to_size1066=== RUN TestParseSingleRange/suffix1067=== PAUSE TestParseSingleRange/suffix1068=== RUN TestParseSingleRange/suffix_exceeds_size1069=== PAUSE TestParseSingleRange/suffix_exceeds_size1070=== RUN TestParseSingleRange/single_byte1071=== PAUSE TestParseSingleRange/single_byte1072=== RUN TestParseSingleRange/start_past_EOF1073=== PAUSE TestParseSingleRange/start_past_EOF1074=== RUN TestParseSingleRange/start_far_past_EOF1075=== PAUSE TestParseSingleRange/start_far_past_EOF1076=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection10772026/10/20 08:17:16 INFO Vacuumed table table=objects10782026/10/20 08:17:16 INFO lead: acquired remote=192.0.2.1:123410792026/10/20 08:17:16 INFO lead: released remote=192.0.2.1:12341080--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.89s)1081=== CONT TestPresentNotReportedWhileGCDeletesClosure1082=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1083=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1084=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1085=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1086=== CONT TestGCSweepDeliversEachKeyOnce10872026/10/20 08:17:16 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001088--- PASS: TestService_createPendingClosureHandler (1.07s)1089=== CONT TestTombstonedObjectOfferedWithoutWaiting10902026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures1091--- PASS: TestReadProxyHead (0.87s)1092=== CONT TestGCSweepSkipsPendingObjects10932026/10/20 08:17:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10942026/10/20 08:17:16 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LjRhYTYxOTliLTU0ZDAtNDk4YS1iMzRhLWNjZDZhNzg5ZmU5ZngxNzkyNDg0MjM2MjUwMzA2OTM310952026/10/20 08:17:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LjRhYTYxOTliLTU0ZDAtNDk4YS1iMzRhLWNjZDZhNzg5ZmU5ZngxNzkyNDg0MjM2MjUwMzA2OTM3 parts=11096--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.14s)1097=== CONT TestDeduplicatedObjectsRecordedAsPending1098--- PASS: TestReadRedirectKeepsNarinfoProxied (0.97s)1099=== CONT TestPushDedupSurvivesConcurrentGC1100--- PASS: TestReadProxyInvalidPath (0.72s)1101=== CONT TestGCMetrics11022026/10/20 08:17:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11032026/10/20 08:17:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LjIwMjkzMjdjLWE0M2UtNGM0Mi1hODNmLWUxY2E4MjdlZWJhNXgxNzkyNDg0MjM1NzIxNTU5ODg3 parts=1211042026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures1106--- PASS: TestReadProxyNarStreaming (0.72s)1107=== CONT TestPresentRefreshesOnlyStaleClosures1108--- PASS: TestReadProxy404 (0.78s)1109=== CONT TestGCBugBareHashReferences11102026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures1111--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.65s)1112=== CONT TestPresentReportsOnlyClosureRoots11132026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=011142026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period11152026/10/20 08:17:16 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=011162026/10/20 08:17:16 INFO Vacuumed table table=pending_closures11172026/10/20 08:17:16 INFO Vacuumed table table=pending_objects11182026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads11192026/10/20 08:17:16 INFO Vacuumed table table=closures11202026/10/20 08:17:16 INFO Vacuumed table table=objects1121--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.82s)1122=== CONT TestGCAdvisoryLockBlocksConcurrentRun11232026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=011242026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period1125--- PASS: TestReadProxyContentNegotiation (0.76s)1126=== CONT TestCreatePin_ReservedPins11272026/10/20 08:17:16 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=011282026/10/20 08:17:16 INFO Vacuumed table table=pending_closures11292026/10/20 08:17:16 INFO Vacuumed table table=pending_objects11302026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads1131--- PASS: TestGetExistingObjectsLocksRows (0.70s)11322026/10/20 08:17:16 INFO Vacuumed table table=closures1133=== CONT TestLeadEndsOnShutdown11342026/10/20 08:17:16 INFO Vacuumed table table=objects1135--- PASS: TestSweepRechecksPendingAfterLocking (0.76s)1136=== CONT TestLeadElectsOneAndHandsOver1137--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.58s)1138=== CONT TestOrphanedObjectsGCStressTest11392026/10/20 08:17:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11402026/10/20 08:17:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36679/oidc11412026/10/20 08:17:16 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LmIzYjVhMDAxLTgzZjgtNDQ5Ny1hZDQ4LWY4YTAyNzg5MzgwNngxNzkyNDg0MjM2MDg4NTk0OTYy parts=1211422026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures1143--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.44s)1144=== CONT TestClientFallsBackToClosures11452026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=011462026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period11472026/10/20 08:17:16 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=011482026/10/20 08:17:16 INFO Vacuumed table table=pending_closures11492026/10/20 08:17:16 INFO Vacuumed table table=pending_objects11502026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads11512026/10/20 08:17:16 INFO Vacuumed table table=closures11522026/10/20 08:17:16 INFO Vacuumed table table=objects11532026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures11542026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=011552026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period11562026/10/20 08:17:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=011572026/10/20 08:17:16 INFO Vacuumed table table=pending_closures11582026/10/20 08:17:16 INFO Vacuumed table table=pending_objects11592026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads11602026/10/20 08:17:16 INFO Vacuumed table table=closures11612026/10/20 08:17:16 INFO Vacuumed table table=objects1162--- PASS: TestSweepSkipsRowsLockedByPush (0.62s)1163=== CONT TestOrphanedObjectsGC11642026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures1165=== NAME TestClientMultipleUploads1166 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads43294049/001/store/zbyacn7grf4l49bx8idlfc8n6ha12gc5-test-file-0.txt11672026/10/20 08:17:16 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1168--- PASS: TestReadProxyNarinfo (0.58s)1169=== CONT TestClientPushesUseOnePush11702026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=011712026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period1172=== NAME TestClientMultipleUploads1173 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads43294049/001/store/ippn0hkb3ngx0ivm31d0j72gwpllyjbh-test-file-1.txt11742026/10/20 08:17:16 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11752026/10/20 08:17:16 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1176--- PASS: TestFailedS3DeleteKeepsTombstone (0.67s)1177=== CONT TestConnectWaitsForAPeerMigration11782026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures11792026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=011802026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period1181--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.63s)1182=== CONT TestResolveDBConnectionString1183=== RUN TestResolveDBConnectionString/flag_wins1184=== PAUSE TestResolveDBConnectionString/flag_wins1185=== RUN TestResolveDBConnectionString/file_when_flag_empty1186=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1187=== RUN TestResolveDBConnectionString/missing_file_is_an_error1188=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1189=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1190=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1191=== RUN TestResolveDBConnectionString/nothing_configured1192=== PAUSE TestResolveDBConnectionString/nothing_configured1193=== CONT TestObjectStatsLargeCommit1194=== NAME TestClientMultipleUploads1195 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads43294049/001/store/0asmf6sbiqar9f5v48s7q2yv2j7lglmi-test-file-2.txt11962026/10/20 08:17:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=011972026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures11982026/10/20 08:17:16 INFO Vacuumed table table=pending_closures11992026/10/20 08:17:16 INFO Vacuumed table table=pending_objects12002026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads12012026/10/20 08:17:16 INFO Vacuumed table table=closures12022026/10/20 08:17:16 INFO Vacuumed table table=objects1203--- PASS: TestGCSweepDeliversEachKeyOnce (0.67s)1204=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12052026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=01206--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.70s)1207=== CONT TestPinProtectsFromGC12082026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period12092026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures12102026/10/20 08:17:16 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=012112026/10/20 08:17:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1212--- PASS: TestPushWaitsForSweepHoldingRow (1.23s)1213=== CONT TestObjectStatsTrigger12142026/10/20 08:17:16 INFO Vacuumed table table=pending_closures12152026/10/20 08:17:16 INFO Vacuumed table table=pending_objects1216--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.62s)12172026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads1218=== CONT TestDeleteClosuresRacingPins12192026/10/20 08:17:16 INFO Vacuumed table table=closures12202026/10/20 08:17:16 INFO Vacuumed table table=objects12212026/10/20 08:17:16 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LjNjYjc0MWY3LTQ5NWYtNDdkZS05NDE3LWQ1ZDM5OGQ0ODdhZXgxNzkyNDg0MjM2MzgxMDAwOTA0 error="Get \"http://127.0.0.1:1/bucket11/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12222026/10/20 08:17:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OWIzYWRmY2EtOTEwZi00OGMyLWE2YWEtZmNiOWM2MWJhMTA3LjdhYjIxZDc2LWE4OGEtNGYxOC1hNmEwLWNjN2ViZjg4YzJlMngxNzkyNDg0MjM2MzczMDMwMDA1 parts=1212232026/10/20 08:17:16 INFO Received cleanup request method=DELETE path=/api/pending_closures1224--- PASS: TestGCSweepSkipsPendingObjects (0.66s)1225=== CONT TestPendingCleanupUsesOneCutoff12262026/10/20 08:17:16 INFO Received push request method=POST path=/api/pushes12272026/10/20 08:17:16 INFO Aborted multipart uploads count=1 kept=012282026/10/20 08:17:16 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12292026/10/20 08:17:16 INFO Uploading ippn0hkb3ngx0ivm31d0j72gwpllyjbh-test-file-1.txt (160B)12302026/10/20 08:17:16 INFO Uploading 0asmf6sbiqar9f5v48s7q2yv2j7lglmi-test-file-2.txt (160B)12312026/10/20 08:17:16 INFO Uploading zbyacn7grf4l49bx8idlfc8n6ha12gc5-test-file-0.txt (160B)1232--- PASS: TestRedundantMultipartUpload (1.79s)1233=== CONT TestClientSharedPathCommittedMidPush12342026/10/20 08:17:16 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"12352026/10/20 08:17:16 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12362026/10/20 08:17:16 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"12372026/10/20 08:17:16 WARN Failed to register uploaded object key=0asmf6sbiqar9f5v48s7q2yv2j7lglmi.ls error="server returned 404: 404 page not found\n"12382026/10/20 08:17:16 WARN Failed to register uploaded object key=ippn0hkb3ngx0ivm31d0j72gwpllyjbh.ls error="server returned 404: 404 page not found\n"12392026/10/20 08:17:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12402026/10/20 08:17:16 WARN Failed to register uploaded object key=zbyacn7grf4l49bx8idlfc8n6ha12gc5.ls error="server returned 404: 404 page not found\n"12412026/10/20 08:17:16 INFO Signed narinfos id=1 count=312422026/10/20 08:17:16 INFO Uploading 3 narinfos12432026/10/20 08:17:16 WARN Failed to register uploaded object key=0asmf6sbiqar9f5v48s7q2yv2j7lglmi.narinfo error="server returned 404: 404 page not found\n"12442026/10/20 08:17:16 WARN Failed to register uploaded object key=zbyacn7grf4l49bx8idlfc8n6ha12gc5.narinfo error="server returned 404: 404 page not found\n"12452026/10/20 08:17:16 INFO Received complete push request method=POST path=/api/pushes/1/complete12462026/10/20 08:17:16 WARN Failed to register uploaded object key=ippn0hkb3ngx0ivm31d0j72gwpllyjbh.narinfo error="server returned 404: 404 page not found\n"12472026/10/20 08:17:16 INFO Aborted multipart uploads count=0 kept=012482026/10/20 08:17:16 WARN Force mode enabled - objects will be deleted immediately without grace period12492026/10/20 08:17:16 INFO Received uploads request method=POST path=/api/pending_closures12502026/10/20 08:17:16 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=012512026/10/20 08:17:16 INFO Completed push id=1 objects=9 duration=16.336069ms12522026/10/20 08:17:16 INFO Upload complete. (84ms)1253=== NAME TestClientMultipleUploads1254 client_integration_test.go:369: Uploaded 3 paths in 126.516048ms12552026/10/20 08:17:16 INFO Vacuumed table table=pending_closures12562026/10/20 08:17:16 INFO Vacuumed table table=pending_objects12572026/10/20 08:17:16 INFO Vacuumed table table=multipart_uploads12582026/10/20 08:17:16 INFO Vacuumed table table=closures12592026/10/20 08:17:16 INFO Vacuumed table table=objects1260--- PASS: TestPresentRefreshesOnlyStaleClosures (0.60s)1261=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1262--- PASS: TestGCMetrics (0.67s)1263=== CONT TestClientWithDependencies1264--- PASS: TestClientMultipleUploads (0.81s)1265=== CONT TestService_ReadScope_PublicByDefault1266--- PASS: TestPresentReportsOnlyClosureRoots (0.59s)1267=== CONT TestMultipartCleanup12682026/10/20 08:17:17 INFO Aborted multipart uploads count=0 kept=012692026/10/20 08:17:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012702026/10/20 08:17:17 INFO Vacuumed table table=pending_closures12712026/10/20 08:17:17 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1272--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.56s)1273=== CONT TestClientIntegration12742026/10/20 08:17:17 INFO Vacuumed table table=pending_objects12752026/10/20 08:17:17 INFO Vacuumed table table=multipart_uploads12762026/10/20 08:17:17 INFO Vacuumed table table=closures12772026/10/20 08:17:17 INFO Vacuumed table table=objects12782026/10/20 08:17:17 INFO Aborted multipart uploads count=0 kept=012792026/10/20 08:17:17 INFO lead: acquired remote=192.0.2.1:123412802026/10/20 08:17:17 WARN Force mode enabled - objects will be deleted immediately without grace period12812026/10/20 08:17:17 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=012822026/10/20 08:17:17 INFO Vacuumed table table=pending_closures12832026/10/20 08:17:17 INFO Vacuumed table table=pending_objects12842026/10/20 08:17:17 INFO Vacuumed table table=multipart_uploads12852026/10/20 08:17:17 INFO Vacuumed table table=closures12862026/10/20 08:17:17 INFO Vacuumed table table=objects1287--- PASS: TestPushDedupSurvivesConcurrentGC (0.81s)1288=== CONT TestServerTLSConfig1289=== RUN TestServerTLSConfig/no_client_CA1290=== PAUSE TestServerTLSConfig/no_client_CA1291=== RUN TestServerTLSConfig/missing_CA_file1292=== PAUSE TestServerTLSConfig/missing_CA_file1293=== RUN TestServerTLSConfig/not_a_PEM_file1294=== PAUSE TestServerTLSConfig/not_a_PEM_file1295=== CONT TestService_ReadAuthMiddleware12962026/10/20 08:17:17 INFO lead: acquired remote=192.0.2.1:123412972026/10/20 08:17:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12982026/10/20 08:17:17 WARN Refused reserved pin name=worker-x86_64-linux12992026/10/20 08:17:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13002026/10/20 08:17:17 INFO Received create pin request method=POST path=/api/pins/my-app13012026/10/20 08:17:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1302--- PASS: TestCreatePin_ReservedPins (0.64s)1303=== CONT TestService_NativeMTLS1304--- PASS: TestGCBugBareHashReferences (0.85s)1305=== CONT TestService_RequireScope_OIDC13062026/10/20 08:17:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39433/oidc1307--- PASS: TestObjectStatsTrigger (0.60s)1308=== CONT TestService_AuthMiddleware_OIDC13092026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures13102026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures13112026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures13122026/10/20 08:17:17 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13132026/10/20 08:17:17 INFO Uploading kdy8cpy9hyw84725ma3yc3y0vbk70gq3-b (216B)13142026/10/20 08:17:17 INFO Uploading hjd8avk4r4y56c68fr7q93vag8k0dj5c-shared-dep (136B)13152026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13162026/10/20 08:17:17 WARN Failed to register uploaded object key=3nb7d313wi4q3ph2zgcnrlchydb72jzi.ls error="server returned 404: 404 page not found\n"13172026/10/20 08:17:17 WARN Failed to register uploaded object key=hjd8avk4r4y56c68fr7q93vag8k0dj5c.ls error="server returned 404: 404 page not found\n"13182026/10/20 08:17:17 WARN Failed to register uploaded object key=kdy8cpy9hyw84725ma3yc3y0vbk70gq3.ls error="server returned 404: 404 page not found\n"13192026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/0qflfapq850plg57y5gv470c0jbd33jxc8k1zl0ag3324pdanxrv.nar.zst error="server returned 404: 404 page not found\n"13202026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13212026/10/20 08:17:17 INFO Signed narinfos id=2 count=213222026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13232026/10/20 08:17:17 INFO Signed narinfos id=1 count=213242026/10/20 08:17:17 INFO Uploading 4 narinfos1325=== NAME TestPinProtectsFromGC1326 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3019758252/001/store/ddm77vgmxhc11hqakhp3w7vfywqb27m1-pinned-file.txt1327 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3019758252/001/store/7vpg0f7q2b5ka355xvgx83znrswy3r3r-unpinned-file.txt13282026/10/20 08:17:17 WARN Failed to register uploaded object key=hjd8avk4r4y56c68fr7q93vag8k0dj5c.narinfo error="server returned 404: 404 page not found\n"13292026/10/20 08:17:17 WARN Failed to register uploaded object key=kdy8cpy9hyw84725ma3yc3y0vbk70gq3.narinfo error="server returned 404: 404 page not found\n"13302026/10/20 08:17:17 WARN Failed to register uploaded object key=3nb7d313wi4q3ph2zgcnrlchydb72jzi.narinfo error="server returned 404: 404 page not found\n"13312026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures13322026/10/20 08:17:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13332026/10/20 08:17:17 WARN Failed to register uploaded object key=hjd8avk4r4y56c68fr7q93vag8k0dj5c.narinfo error="server returned 404: 404 page not found\n"1334=== NAME TestOrphanedObjectsGC1335 orphaned_objects_gc_test.go:287: GC Test Summary:1336 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1337 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1338 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1339 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1340 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1341--- PASS: TestOrphanedObjectsGC (0.90s)1342=== CONT TestPush_CompleteWaitsForCleanupOfThePush13432026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes13442026/10/20 08:17:17 INFO Received cleanup request method=DELETE path=/api/pending_closures13452026/10/20 08:17:17 INFO Completed upload id=1 objects=6 duration=8.627149ms13462026/10/20 08:17:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13472026/10/20 08:17:17 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13482026/10/20 08:17:17 INFO Uploading ldb7hjbbf9xgmjgwf1h4kpcxl5zhnmqy-shared-dep (136B)13492026/10/20 08:17:17 INFO Uploading zdhdzc148nnznvph07g4cmjy7dc3h7wl-b (208B)13502026/10/20 08:17:17 INFO Completed upload id=2 objects=6 duration=1.671ms13512026/10/20 08:17:17 INFO Upload complete. (79ms)1352=== NAME TestClientFallsBackToClosures1353 client_pushes_test.go:112: Retrieved narinfo from S3:1354 StorePath: /build/TestClientFallsBackToClosures3186947762/001/store/hjd8avk4r4y56c68fr7q93vag8k0dj5c-shared-dep1355 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1356 Compression: zstd1357 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821358 NarSize: 1361359 References: 1360 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1361 client_pushes_test.go:112: Retrieved narinfo from S3:1362 StorePath: /build/TestClientFallsBackToClosures3186947762/001/store/3nb7d313wi4q3ph2zgcnrlchydb72jzi-a1363 URL: nar/0qflfapq850plg57y5gv470c0jbd33jxc8k1zl0ag3324pdanxrv.nar.zst1364 Compression: zstd1365 NarHash: sha256:0qflfapq850plg57y5gv470c0jbd33jxc8k1zl0ag3324pdanxrv1366 NarSize: 21613672026/10/20 08:17:17 WARN Failed to register uploaded object key=ycan7zrc9lvras011mipyri175ih855i.ls error="server returned 404: 404 page not found\n"1368 References: /build/TestClientFallsBackToClosures3186947762/001/store/hjd8avk4r4y56c68fr7q93vag8k0dj5c-shared-dep1369 CA: text:sha256:0v0kf5khniwgmx7fj6q0axivab4r4dj1mcv65grsqq31n5hl603c13702026/10/20 08:17:17 WARN Failed to register uploaded object key=ldb7hjbbf9xgmjgwf1h4kpcxl5zhnmqy.ls error="server returned 404: 404 page not found\n"13712026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/12nk9nqar0b7xbs6zyp2g13dyq9ps3awvr6ckp6qvr0wkd5rp59w.nar.zst error="server returned 404: 404 page not found\n"13722026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13732026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13742026/10/20 08:17:17 WARN Failed to register uploaded object key=zdhdzc148nnznvph07g4cmjy7dc3h7wl.ls error="server returned 404: 404 page not found\n"13752026/10/20 08:17:17 INFO Signed narinfos id=1 count=313762026/10/20 08:17:17 INFO Uploading 3 narinfos1377 client_pushes_test.go:112: Retrieved narinfo from S3:1378 StorePath: /build/TestClientFallsBackToClosures3186947762/001/store/kdy8cpy9hyw84725ma3yc3y0vbk70gq3-b1379 URL: nar/0qflfapq850plg57y5gv470c0jbd33jxc8k1zl0ag3324pdanxrv.nar.zst1380 Compression: zstd1381 NarHash: sha256:0qflfapq850plg57y5gv470c0jbd33jxc8k1zl0ag3324pdanxrv1382 NarSize: 2161383 References: /build/TestClientFallsBackToClosures3186947762/001/store/hjd8avk4r4y56c68fr7q93vag8k0dj5c-shared-dep1384 CA: text:sha256:0v0kf5khniwgmx7fj6q0axivab4r4dj1mcv65grsqq31n5hl603c13852026/10/20 08:17:17 WARN Failed to register uploaded object key=ldb7hjbbf9xgmjgwf1h4kpcxl5zhnmqy.narinfo error="server returned 404: 404 page not found\n"13862026/10/20 08:17:17 WARN Failed to register uploaded object key=zdhdzc148nnznvph07g4cmjy7dc3h7wl.narinfo error="server returned 404: 404 page not found\n"13872026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete13882026/10/20 08:17:17 WARN Failed to register uploaded object key=ycan7zrc9lvras011mipyri175ih855i.narinfo error="server returned 404: 404 page not found\n"1389--- PASS: TestClientFallsBackToClosures (0.99s)1390=== CONT TestMetricsCommit13912026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures13922026/10/20 08:17:17 INFO Completed push id=1 objects=8 duration=8.268479ms13932026/10/20 08:17:17 INFO Upload complete. (64ms)1394=== NAME TestClientPushesUseOnePush1395 client_pushes_test.go:97: Retrieved narinfo from S3:1396 StorePath: /build/TestClientPushesUseOnePush597596876/001/store/ldb7hjbbf9xgmjgwf1h4kpcxl5zhnmqy-shared-dep1397 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1398 Compression: zstd1399 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821400 NarSize: 1361401 References: 1402 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1403 client_pushes_test.go:97: Retrieved narinfo from S3:1404 StorePath: /build/TestClientPushesUseOnePush597596876/001/store/ycan7zrc9lvras011mipyri175ih855i-a1405 URL: nar/12nk9nqar0b7xbs6zyp2g13dyq9ps3awvr6ckp6qvr0wkd5rp59w.nar.zst1406 Compression: zstd1407 NarHash: sha256:12nk9nqar0b7xbs6zyp2g13dyq9ps3awvr6ckp6qvr0wkd5rp59w1408 NarSize: 2081409 References: /build/TestClientPushesUseOnePush597596876/001/store/ldb7hjbbf9xgmjgwf1h4kpcxl5zhnmqy-shared-dep1410 CA: text:sha256:0v7p00a8n72k2haz895498g928v5s9ycii9zf5l10lsyk19fhrn31411 client_pushes_test.go:97: Retrieved narinfo from S3:1412 StorePath: /build/TestClientPushesUseOnePush597596876/001/store/zdhdzc148nnznvph07g4cmjy7dc3h7wl-b1413 URL: nar/12nk9nqar0b7xbs6zyp2g13dyq9ps3awvr6ckp6qvr0wkd5rp59w.nar.zst1414 Compression: zstd1415 NarHash: sha256:12nk9nqar0b7xbs6zyp2g13dyq9ps3awvr6ckp6qvr0wkd5rp59w1416 NarSize: 2081417 References: /build/TestClientPushesUseOnePush597596876/001/store/ldb7hjbbf9xgmjgwf1h4kpcxl5zhnmqy-shared-dep1418 CA: text:sha256:0v7p00a8n72k2haz895498g928v5s9ycii9zf5l10lsyk19fhrn31419--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.63s)1420=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1421--- PASS: TestClientPushesUseOnePush (0.89s)1422=== CONT TestMetricsInventory14232026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes1424--- PASS: TestService_ReadScope_PublicByDefault (0.65s)1425=== CONT TestPush_RootsAreLockedInByteOrder14262026/10/20 08:17:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14272026/10/20 08:17:17 INFO Uploading ddm77vgmxhc11hqakhp3w7vfywqb27m1-pinned-file.txt (128B)14282026/10/20 08:17:17 WARN Failed to register uploaded object key=ddm77vgmxhc11hqakhp3w7vfywqb27m1.ls error="server returned 404: 404 page not found\n"14292026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14302026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14312026/10/20 08:17:17 INFO Signed narinfos id=1 count=114322026/10/20 08:17:17 INFO Uploading 1 narinfos14332026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete14342026/10/20 08:17:17 WARN Failed to register uploaded object key=ddm77vgmxhc11hqakhp3w7vfywqb27m1.narinfo error="server returned 404: 404 page not found\n"14352026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures14362026/10/20 08:17:17 INFO Completed push id=1 objects=3 duration=7.91586ms14372026/10/20 08:17:17 INFO Upload complete. (75ms)1438--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.80s)1439=== CONT TestNARDeduplicationMetadataUploadBug14402026/10/20 08:17:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39273/oidc1441--- PASS: TestService_ReadAuthMiddleware (0.59s)1442=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1443=== NAME TestClientWithDependencies1444 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2062580575/001/store/kb0kw7dznpmhq8l4rhq7xyqppqk6j2q1-test-script1445=== NAME TestClientIntegration1446 client_integration_test.go:286: Created store path: /build/TestClientIntegration3897910070/002/store/73m6665hi54g4w2qjm5ii71zilq7rpwz-test-file.txt14472026/10/20 08:17:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14482026/10/20 08:17:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1449--- PASS: TestService_NativeMTLS (0.55s)1450=== CONT TestClientErrorHandling1451=== RUN TestClientErrorHandling/InvalidStorePath1452=== PAUSE TestClientErrorHandling/InvalidStorePath1453=== RUN TestClientErrorHandling/InvalidAuthToken1454=== PAUSE TestClientErrorHandling/InvalidAuthToken1455=== RUN TestClientErrorHandling/ServerNotAvailable1456=== PAUSE TestClientErrorHandling/ServerNotAvailable1457=== CONT TestCreatePendingClosureRejectsOversizedNAR14582026/10/20 08:17:17 INFO Received uploads request method=POST path=/api/pending_closures1459--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1460=== CONT TestService_AuthMiddleware_MTLSProxyHeader14612026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes14622026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes14632026/10/20 08:17:17 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14642026/10/20 08:17:17 INFO Uploading zrqydd3fc693vr0zy0yk5xm1iy857gd4-top (224B)14652026/10/20 08:17:17 INFO Uploading 2yjk5mnv3zk6byrxf6szd5iy4ig0h526-shared-dep (136B)14662026/10/20 08:17:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14672026/10/20 08:17:17 INFO Uploading 7vpg0f7q2b5ka355xvgx83znrswy3r3r-unpinned-file.txt (128B)1468=== NAME TestClientWithDependencies1469 client_integration_test.go:615: Found 1 dependencies (including self)14702026/10/20 08:17:17 WARN Failed to register uploaded object key=2yjk5mnv3zk6byrxf6szd5iy4ig0h526.ls error="server returned 404: 404 page not found\n"14712026/10/20 08:17:17 WARN Failed to register uploaded object key=zrqydd3fc693vr0zy0yk5xm1iy857gd4.ls error="server returned 404: 404 page not found\n"14722026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/1mqq2n9z51l47x2q2rd29zvy4mhv0067j505jlhgkh2qljcr0sma.nar.zst error="server returned 404: 404 page not found\n"14732026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14742026/10/20 08:17:17 WARN Failed to register uploaded object key=7vpg0f7q2b5ka355xvgx83znrswy3r3r.ls error="server returned 404: 404 page not found\n"14752026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14762026/10/20 08:17:17 INFO Signed narinfos id=1 count=214772026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14782026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14792026/10/20 08:17:17 INFO Uploading 2 narinfos14802026/10/20 08:17:17 INFO Signed narinfos id=2 count=114812026/10/20 08:17:17 INFO Uploading 1 narinfos14822026/10/20 08:17:17 WARN Failed to register uploaded object key=zrqydd3fc693vr0zy0yk5xm1iy857gd4.narinfo error="server returned 404: 404 page not found\n"14832026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete14842026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/2/complete14852026/10/20 08:17:17 WARN Failed to register uploaded object key=2yjk5mnv3zk6byrxf6szd5iy4ig0h526.narinfo error="server returned 404: 404 page not found\n"14862026/10/20 08:17:17 WARN Failed to register uploaded object key=7vpg0f7q2b5ka355xvgx83znrswy3r3r.narinfo error="server returned 404: 404 page not found\n"14872026/10/20 08:17:17 INFO Completed push id=2 objects=3 duration=2.51952ms14882026/10/20 08:17:17 INFO Upload complete. (52ms)1489=== RUN TestService_RequireScope_OIDC/builder_may_write1490=== PAUSE TestService_RequireScope_OIDC/builder_may_write1491=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1492=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1493=== RUN TestService_RequireScope_OIDC/ops_may_admin1494=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1495=== RUN TestService_RequireScope_OIDC/ops_may_not_write1496=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1497=== RUN TestService_RequireScope_OIDC/reader_may_not_write1498=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1499=== RUN TestService_RequireScope_OIDC/static_token_may_admin1500=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1501=== RUN TestService_RequireScope_OIDC/static_token_may_write1502=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1503=== RUN TestService_RequireScope_OIDC/reader_may_read1504=== PAUSE TestService_RequireScope_OIDC/reader_may_read1505=== RUN TestService_RequireScope_OIDC/writer_implies_read1506=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1507=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1508=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1509=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1510=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1511=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1512=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1513=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1514=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1515=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1516=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1517=== CONT TestClientCADerivations15182026/10/20 08:17:17 INFO Completed push id=1 objects=6 duration=23.879888ms15192026/10/20 08:17:17 INFO Upload complete. (87ms)15202026/10/20 08:17:17 INFO Received cleanup request method=DELETE path=/api/pending_closures1521=== NAME TestClientSharedPathCommittedMidPush15222026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes1523 client_integration_test.go:680: Retrieved narinfo from S3:1524 StorePath: /build/TestClientSharedPathCommittedMidPush3937556743/001/store/2yjk5mnv3zk6byrxf6szd5iy4ig0h526-shared-dep1525 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1526 Compression: zstd1527 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821528 NarSize: 1361529 References: 1530 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15312026/10/20 08:17:17 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket70/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""15322026/10/20 08:17:17 INFO Aborted multipart uploads count=0 kept=11533 client_integration_test.go:680: Retrieved narinfo from S3:1534 StorePath: /build/TestClientSharedPathCommittedMidPush3937556743/001/store/zrqydd3fc693vr0zy0yk5xm1iy857gd4-top1535 URL: nar/1mqq2n9z51l47x2q2rd29zvy4mhv0067j505jlhgkh2qljcr0sma.nar.zst1536 Compression: zstd1537 NarHash: sha256:1mqq2n9z51l47x2q2rd29zvy4mhv0067j505jlhgkh2qljcr0sma1538 NarSize: 2241539 References: /build/TestClientSharedPathCommittedMidPush3937556743/001/store/2yjk5mnv3zk6byrxf6szd5iy4ig0h526-shared-dep1540 CA: text:sha256:10890xbip7ca4gnd8wjvqvqg6svvpgllfbw9w2z7snz0bjingf0k1541--- PASS: TestClientSharedPathCommittedMidPush (0.84s)1542=== CONT TestCacheConfigHandlerMaxNarSize15432026/10/20 08:17:17 INFO Received cleanup request method=DELETE path=/api/pending_closures1544--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1545=== CONT TestCacheStatsHandler15462026/10/20 08:17:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures15472026/10/20 08:17:17 INFO Garbage collection started15482026/10/20 08:17:17 INFO Aborted multipart uploads count=1 kept=01549--- PASS: TestMultipartCleanup (0.74s)1550=== CONT TestCacheConfigHandler1551=== RUN TestCacheConfigHandler/full_config,_no_issuer1552=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1553=== RUN TestCacheConfigHandler/no_cache_url_configured1554=== PAUSE TestCacheConfigHandler/no_cache_url_configured1555=== RUN TestCacheConfigHandler/no_signing_keys1556=== PAUSE TestCacheConfigHandler/no_signing_keys1557=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1558=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1559=== CONT TestGCTaskStore_PhaseUpdates1560--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1561=== CONT TestPush_CompleteCommitsEveryRoot15622026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes15632026/10/20 08:17:17 INFO Aborted multipart uploads count=0 kept=015642026/10/20 08:17:17 WARN Force mode enabled - objects will be deleted immediately without grace period15652026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes15662026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes15672026/10/20 08:17:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=015682026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete15692026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes15702026/10/20 08:17:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15712026/10/20 08:17:17 INFO Uploading 73m6665hi54g4w2qjm5ii71zilq7rpwz-test-file.txt (152B)15722026/10/20 08:17:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15732026/10/20 08:17:17 INFO Uploading kb0kw7dznpmhq8l4rhq7xyqppqk6j2q1-test-script (136B)15742026/10/20 08:17:17 INFO Vacuumed table table=pending_closures15752026/10/20 08:17:17 WARN Failed to register uploaded object key=73m6665hi54g4w2qjm5ii71zilq7rpwz.ls error="server returned 404: 404 page not found\n"15762026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15772026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15782026/10/20 08:17:17 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15792026/10/20 08:17:17 WARN Failed to register uploaded object key=log/qxla8pv037dl9mrlm9l9ax4i014fxwi1-test-script.drv error="server returned 404: 404 page not found\n"15802026/10/20 08:17:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15812026/10/20 08:17:17 INFO Vacuumed table table=pending_objects15822026/10/20 08:17:17 WARN Failed to register uploaded object key=kb0kw7dznpmhq8l4rhq7xyqppqk6j2q1.ls error="server returned 404: 404 page not found\n"15832026/10/20 08:17:17 INFO Signed narinfos id=1 count=115842026/10/20 08:17:17 INFO Uploading 1 narinfos15852026/10/20 08:17:17 INFO Vacuumed table table=multipart_uploads15862026/10/20 08:17:17 INFO Signed narinfos id=1 count=115872026/10/20 08:17:17 INFO Uploading 1 narinfos15882026/10/20 08:17:17 INFO Vacuumed table table=closures15892026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete15902026/10/20 08:17:17 WARN Failed to register uploaded object key=73m6665hi54g4w2qjm5ii71zilq7rpwz.narinfo error="server returned 404: 404 page not found\n"15912026/10/20 08:17:17 INFO Vacuumed table table=objects15922026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete15932026/10/20 08:17:17 WARN Failed to register uploaded object key=kb0kw7dznpmhq8l4rhq7xyqppqk6j2q1.narinfo error="server returned 404: 404 page not found\n"15942026/10/20 08:17:17 INFO Completed push id=1 objects=4 duration=14.918939ms15952026/10/20 08:17:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15962026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/1/complete15972026/10/20 08:17:17 INFO Completed upload id=2 objects=2 duration=2.70437ms15982026/10/20 08:17:17 INFO Completed push id=1 objects=4 duration=10.466119ms15992026/10/20 08:17:17 INFO Upload complete. (77ms)16002026/10/20 08:17:17 INFO Completed push id=1 objects=3 duration=11.471609ms16012026/10/20 08:17:17 INFO Upload complete. (81ms)1602--- PASS: TestMetricsCommit (0.27s)1603=== CONT TestGCTaskStore_CompletedAllowsNewTask1604--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1605=== CONT TestPush_RepeatedRootCommitsOnce16062026/10/20 08:17:17 INFO Completed push id=1 objects=4 duration=8.343949ms1607=== NAME TestClientWithDependencies16082026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes1609 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2062580575/001/store) requires matching store prefix1610--- PASS: TestClientWithDependencies (0.87s)1611=== CONT TestGCTaskStore_Fail1612--- PASS: TestGCTaskStore_Fail (0.00s)1613=== CONT TestGCTaskStore_GetReturnsLatest1614--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1615=== CONT TestGenerateLandingPage1616--- PASS: TestGenerateLandingPage (0.00s)1617=== CONT TestService_healthCheckHandler1618--- PASS: TestMetricsInventory (0.26s)1619=== CONT TestService_readinessHandler16202026/10/20 08:17:17 INFO Received push request method=POST path=/api/pushes16212026/10/20 08:17:17 INFO All 1 paths already cached1622=== NAME TestClientIntegration1623 client_integration_test.go:312: Retrieved narinfo from S3:1624 StorePath: /build/TestClientIntegration3897910070/002/store/73m6665hi54g4w2qjm5ii71zilq7rpwz-test-file.txt1625 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1626 Compression: zstd1627 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11628 NarSize: 1521629 References: 1630 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11631 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1632 client_integration_test.go:313: Decompressed .ls content (64 bytes):1633 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1634 client_integration_test.go:316: Testing garbage collection...16352026/10/20 08:17:17 INFO Aborted multipart uploads count=0 kept=016362026/10/20 08:17:17 WARN Force mode enabled - objects will be deleted immediately without grace period16372026/10/20 08:17:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures16382026/10/20 08:17:17 INFO Garbage collection started16392026-10-20 08:17:17.939 UTC [1561] ERROR: could not obtain lock on row in relation "closures"16402026-10-20 08:17:17.939 UTC [1561] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16412026-10-20 08:17:17.939 UTC [1561] ERROR: could not obtain lock on row in relation "closures"16422026-10-20 08:17:17.939 UTC [1561] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16432026-10-20 08:17:17.940 UTC [1561] ERROR: could not obtain lock on row in relation "closures"16442026-10-20 08:17:17.940 UTC [1561] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16452026-10-20 08:17:17.940 UTC [1561] ERROR: could not obtain lock on row in relation "closures"16462026-10-20 08:17:17.940 UTC [1561] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16472026-10-20 08:17:17.940 UTC [1561] ERROR: could not obtain lock on row in relation "closures"16482026-10-20 08:17:17.940 UTC [1561] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1649=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1650=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1651=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1652=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1653=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1654=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1655=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1656=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1657=== CONT TestGracefulShutdownDrainsInflight16582026/10/20 08:17:17 INFO Starting HTTP server address=127.0.0.1:4022916592026/10/20 08:17:17 INFO Shutdown signal received, draining in-flight requests timeout=10s1660--- PASS: TestPush_RootsAreLockedInByteOrder (0.31s)1661=== CONT TestPush_OverlappingRootsStoreOneRowPerKey16622026/10/20 08:17:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=016632026/10/20 08:17:17 INFO Aborted multipart uploads count=0 kept=016642026/10/20 08:17:17 INFO Vacuumed table table=pending_closures16652026/10/20 08:17:17 WARN Force mode enabled - objects will be deleted immediately without grace period16662026/10/20 08:17:17 INFO Vacuumed table table=pending_objects16672026/10/20 08:17:17 INFO Vacuumed table table=multipart_uploads16682026/10/20 08:17:17 INFO Vacuumed table table=closures1669=== NAME TestNARDeduplicationMetadataUploadBug1670 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug841725259/001/store/4djgn7acb7dras9w2bsya8yma5l6nsi6-file1.txt16712026/10/20 08:17:17 INFO Vacuumed table table=objects16722026/10/20 08:17:17 INFO Received complete push request method=POST path=/api/pushes/2/complete16732026/10/20 08:17:17 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16742026/10/20 08:17:17 WARN mTLS auth: bound subjects configured but subject DN unavailable16752026/10/20 08:17:17 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1676--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.26s)1677=== CONT TestGCTaskStore_GetEmpty1678--- PASS: TestGCTaskStore_GetEmpty (0.00s)1679=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16802026/10/20 08:17:17 INFO Received uploads request method=POST path=/1681=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16822026/10/20 08:17:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=016832026/10/20 08:17:17 INFO Received complete multipart upload request method=POST path=/1684=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16852026/10/20 08:17:17 INFO Received request for more parts method=POST path=/1686=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16872026/10/20 08:17:17 INFO Received uploads request method=POST path=/1688--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1689 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1690 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1691 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1692 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1693=== CONT TestProxyWriteTimeout/narinfo1694=== CONT TestProxyWriteTimeout/unknown_size1695=== CONT TestProxyWriteTimeout/1_GiB_nar1696=== CONT TestProxyWriteTimeout/10_GiB_nar1697--- PASS: TestProxyWriteTimeout (0.16s)1698 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1699 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1700 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1701 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1702=== CONT TestPendingClosureWriteTimeout/empty1703=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17042026/10/20 08:17:17 INFO Completed push id=2 objects=4 duration=5.89955ms1705--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.36s)1706=== CONT TestPendingClosureWriteTimeout/670k_objects1707=== CONT TestPendingClosureWriteTimeout/400_objects1708=== CONT TestIsValidUploadKey/narinfo1709=== CONT TestIsValidUploadKey/traversal1710=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1711=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1712=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1713=== CONT TestIsValidUploadKey/index.html1714=== CONT TestIsValidUploadKey/nix-cache-info1715=== CONT TestIsValidUploadKey/realisation_plus_in_output1716=== CONT TestIsValidUploadKey/realisation1717=== CONT TestIsValidUploadKey/build_log_equals1718=== CONT TestIsValidUploadKey/build_log_question_mark1719=== CONT TestIsValidUploadKey/build_log_plus_in_name1720=== CONT TestIsValidUploadKey/build_log_home-manager_file1721=== CONT TestIsValidUploadKey/build_log1722=== CONT TestIsValidUploadKey/listing1723=== CONT TestIsValidUploadKey/nar_plain1724=== CONT TestIsValidUploadKey/nar_xz1725=== CONT TestIsValidUploadKey/nar_zst1726=== CONT TestIsValidUploadKey/unknown_type1727=== CONT TestIsValidUploadKey/traversal_nar1728=== CONT TestIsValidUploadKey/empty_key1729=== CONT TestIsValidUploadKey/absolute1730--- PASS: TestIsValidUploadKey (0.17s)1731 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1732 --- PASS: TestIsValidUploadKey/traversal (0.00s)1733 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1734 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1735 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1736 --- PASS: TestIsValidUploadKey/index.html (0.00s)1737 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1738 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1739 --- PASS: TestIsValidUploadKey/realisation (0.00s)1740 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1741 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1742 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1743 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1744 --- PASS: TestIsValidUploadKey/build_log (0.00s)1745 --- PASS: TestIsValidUploadKey/listing (0.00s)1746 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1747 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1748 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1749 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1750 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1751 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1752 --- PASS: TestIsValidUploadKey/absolute (0.00s)1753=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17542026/10/20 08:17:17 INFO Received complete multipart upload request method=POST path=/17552026/10/20 08:17:17 INFO Vacuumed table table=pending_closures17562026/10/20 08:17:17 INFO Vacuumed table table=pending_objects17572026/10/20 08:17:17 INFO Vacuumed table table=multipart_uploads17582026/10/20 08:17:17 INFO Vacuumed table table=closures17592026/10/20 08:17:17 INFO Vacuumed table table=objects1760--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.27s)1761=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17622026/10/20 08:17:17 INFO Received request for more parts method=POST path=/1763--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1764=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17652026/10/20 08:17:18 INFO Received uploads request method=POST path=/1766=== CONT TestGCEndsOnShutdown/before_the_run17672026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes17682026/10/20 08:17:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17692026/10/20 08:17:18 INFO Uploading 4djgn7acb7dras9w2bsya8yma5l6nsi6-file1.txt (160B)1770=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17712026/10/20 08:17:18 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17722026/10/20 08:17:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17732026/10/20 08:17:18 WARN Failed to register uploaded object key=4djgn7acb7dras9w2bsya8yma5l6nsi6.ls error="server returned 404: 404 page not found\n"17742026/10/20 08:17:18 INFO Signed narinfos id=1 count=117752026/10/20 08:17:18 INFO Uploading 1 narinfos17762026/10/20 08:17:18 INFO Received complete push request method=POST path=/api/pushes/1/complete17772026/10/20 08:17:18 WARN Failed to register uploaded object key=4djgn7acb7dras9w2bsya8yma5l6nsi6.narinfo error="server returned 404: 404 page not found\n"1778--- PASS: TestCacheStatsHandler (0.28s)1779=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17802026/10/20 08:17:18 INFO Completed push id=1 objects=3 duration=13.125029ms17812026/10/20 08:17:18 INFO Upload complete. (76ms)1782=== NAME TestNARDeduplicationMetadataUploadBug1783 metadata_upload_test.go:54: Retrieved narinfo from S3:1784 StorePath: /build/TestNARDeduplicationMetadataUploadBug841725259/001/store/4djgn7acb7dras9w2bsya8yma5l6nsi6-file1.txt1785 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1786 Compression: zstd1787 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1788 NarSize: 1601789 References: 1790 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1791 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1792 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1793 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}17942026-10-20 08:17:18.117 UTC [1484] ERROR: Push does not exist: id=117952026-10-20 08:17:18.117 UTC [1484] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE17962026-10-20 08:17:18.117 UTC [1484] STATEMENT: SELECT commit_push($1)1797--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.54s)1798=== CONT TestPush_RejectsBadRequests/no_roots17992026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes1800=== CONT TestPush_RejectsBadRequests/bad_root18012026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes1802=== CONT TestPush_RejectsBadRequests/root_not_in_objects18032026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes1804=== CONT TestPush_RejectsBadRequests/no_objects18052026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes1806=== CONT TestIsValidCachePath/narinfo1807=== CONT TestIsValidCachePath/index.html1808--- PASS: TestPush_RejectsBadRequests (0.53s)1809 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1810 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1811 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1812 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1813=== CONT TestIsValidCachePath/short_hash1814=== CONT TestIsValidCachePath/wrong_extension1815=== CONT TestIsValidCachePath/leading_slash1816=== CONT TestIsValidCachePath/empty1817=== CONT TestIsValidCachePath/random_path1818=== CONT TestIsValidCachePath/invalid_char_u1819=== CONT TestIsValidCachePath/invalid_char_e1820=== CONT TestIsValidCachePath/traversal_in_middle1821=== CONT TestIsValidCachePath/traversal_parent1822=== CONT TestIsValidCachePath/realisation1823=== CONT TestIsValidCachePath/nar_uncompressed1824=== CONT TestIsValidCachePath/log1825=== CONT TestIsValidCachePath/nix-cache-info1826=== CONT TestIsValidCachePath/nar_xz1827=== CONT TestIsValidCachePath/nar_zst1828=== CONT TestIsValidCachePath/ls1829=== CONT TestIsValidCachePath/nar_bz21830=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1831--- PASS: TestIsValidCachePath (0.00s)1832 --- PASS: TestIsValidCachePath/narinfo (0.00s)1833 --- PASS: TestIsValidCachePath/index.html (0.00s)1834 --- PASS: TestIsValidCachePath/short_hash (0.00s)1835 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1836 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1837 --- PASS: TestIsValidCachePath/empty (0.00s)1838 --- PASS: TestIsValidCachePath/random_path (0.00s)1839 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1840 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1841 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1842 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1843 --- PASS: TestIsValidCachePath/realisation (0.00s)1844 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1845 --- PASS: TestIsValidCachePath/log (0.00s)1846 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1847 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1848 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1849 --- PASS: TestIsValidCachePath/ls (0.00s)1850 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1851 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1852=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18532026/10/20 08:17:18 INFO lead: released remote=192.0.2.1:12341854--- PASS: TestLeadEndsOnShutdown (1.58s)1855=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18562026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes1857=== NAME TestNARDeduplicationMetadataUploadBug1858 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug841725259/001/store/l5z35x2z40wvm614v4mksz1kagxvjxkw-file2.txt1859=== NAME TestClientCADerivations1860 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3563995829/001/store/8jrpg4maycqhmjy95ggzsqnf5j5g9hv0-ca-test18612026/10/20 08:17:18 INFO Received complete push request method=POST path=/api/pushes/1/complete18622026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes18632026/10/20 08:17:18 INFO Completed push id=1 objects=6 duration=8.603459ms1864--- PASS: TestPush_CompleteCommitsEveryRoot (0.38s)1865=== CONT TestParseSingleRange/none1866=== CONT TestParseSingleRange/start_past_EOF1867=== CONT TestParseSingleRange/single_byte1868=== CONT TestParseSingleRange/suffix_exceeds_size1869=== CONT TestParseSingleRange/suffix1870=== CONT TestParseSingleRange/end_clamped_to_size1871=== CONT TestParseSingleRange/open-ended1872=== CONT TestParseSingleRange/closed1873=== CONT TestParseSingleRange/malformed_end_before_start1874=== CONT TestParseSingleRange/malformed_both_empty1875=== CONT TestParseSingleRange/malformed_no_dash1876=== CONT TestParseSingleRange/multi-range_ignored1877=== CONT TestParseSingleRange/unknown_unit1878=== CONT TestParseSingleRange/start_far_past_EOF1879--- PASS: TestParseSingleRange (0.00s)1880 --- PASS: TestParseSingleRange/none (0.00s)1881 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1882 --- PASS: TestParseSingleRange/single_byte (0.00s)1883 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1884 --- PASS: TestParseSingleRange/suffix (0.00s)1885 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1886 --- PASS: TestParseSingleRange/open-ended (0.00s)1887 --- PASS: TestParseSingleRange/closed (0.00s)1888 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1889 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1890 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1891 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1892 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1893 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1894=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18952026/10/20 08:17:18 INFO Received complete push request method=POST path=/api/pushes/1/complete18962026/10/20 08:17:18 INFO Completed push id=1 objects=4 duration=6.475679ms1897--- PASS: TestPush_RepeatedRootCommitsOnce (0.33s)1898=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18992026/10/20 08:17:18 WARN readiness check failed error="closed pool"1900=== NAME TestClientCADerivations1901 client_ca_test.go:139: Found 1 dependencies (including self)1902--- PASS: TestService_readinessHandler (0.32s)1903=== CONT TestResolveDBConnectionString/flag_wins1904=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1905=== CONT TestResolveDBConnectionString/nothing_configured1906=== CONT TestResolveDBConnectionString/missing_file_is_an_error1907=== CONT TestResolveDBConnectionString/file_when_flag_empty1908=== CONT TestServerTLSConfig/no_client_CA1909=== CONT TestServerTLSConfig/not_a_PEM_file1910--- PASS: TestResolveDBConnectionString (0.00s)1911 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1912 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1913 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1914 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1915 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1916=== CONT TestServerTLSConfig/missing_CA_file1917--- PASS: TestServerTLSConfig (0.00s)1918 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1919 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1920 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1921=== CONT TestClientErrorHandling/InvalidStorePath19222026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes1923--- PASS: TestService_healthCheckHandler (0.36s)1924=== CONT TestClientErrorHandling/ServerNotAvailable19252026/10/20 08:17:18 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19262026/10/20 08:17:18 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19272026/10/20 08:17:18 WARN Failed to register uploaded object key=l5z35x2z40wvm614v4mksz1kagxvjxkw.ls error="server returned 404: 404 page not found\n"19282026/10/20 08:17:18 INFO Signed narinfos id=2 count=119292026/10/20 08:17:18 INFO Uploading 1 narinfos19302026/10/20 08:17:18 INFO Received complete push request method=POST path=/api/pushes/2/complete19312026/10/20 08:17:18 WARN Failed to register uploaded object key=l5z35x2z40wvm614v4mksz1kagxvjxkw.narinfo error="server returned 404: 404 page not found\n"19322026/10/20 08:17:18 INFO Completed push id=2 objects=3 duration=3.62314ms19332026/10/20 08:17:18 INFO Upload complete. (62ms)1934=== NAME TestNARDeduplicationMetadataUploadBug1935 metadata_upload_test.go:76: Retrieved narinfo from S3:1936 StorePath: /build/TestNARDeduplicationMetadataUploadBug841725259/001/store/l5z35x2z40wvm614v4mksz1kagxvjxkw-file2.txt1937 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1938 Compression: zstd1939 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1940 NarSize: 1601941 References: 1942 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1943 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1944 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1945 {"version":1,"root":{"type":"regular","size":44}}1946--- PASS: TestNARDeduplicationMetadataUploadBug (0.57s)1947=== CONT TestClientErrorHandling/InvalidAuthToken19482026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes19492026/10/20 08:17:18 INFO Received uploads request method=POST path=/api/pending_closures1950--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.33s)1951=== CONT TestService_RequireScope_OIDC/builder_may_write1952=== CONT TestService_RequireScope_OIDC/reader_may_read1953=== CONT TestService_RequireScope_OIDC/static_token_may_write1954=== CONT TestService_RequireScope_OIDC/static_token_may_admin1955=== CONT TestService_RequireScope_OIDC/reader_may_not_write1956=== CONT TestService_RequireScope_OIDC/ops_may_not_write1957=== CONT TestService_RequireScope_OIDC/ops_may_admin1958=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1959=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19602026/10/20 08:17:18 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1961=== CONT TestService_RequireScope_OIDC/writer_implies_read1962=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1963=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1964=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1965=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1966=== CONT TestCacheConfigHandler/full_config,_no_issuer1967=== CONT TestCacheConfigHandler/no_signing_keys1968=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1969=== CONT TestCacheConfigHandler/no_cache_url_configured1970--- PASS: TestCacheConfigHandler (0.00s)1971 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1972 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1973 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1974 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1975=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1976--- PASS: TestService_RequireScope_OIDC (0.53s)1977 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1978 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1979 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1980 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1981 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1982 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1983 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1984 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1991=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19922026/10/20 08:17:18 WARN Authentication failed token_preview=eyJhbGciOi...QXqhMY3v5w token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1993=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19942026/10/20 08:17:18 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]1995=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1996--- PASS: TestService_AuthMiddleware_OIDC (0.42s)1997 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1998 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1999 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2000 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)20012026/10/20 08:17:18 INFO Received push request method=POST path=/api/pushes20022026/10/20 08:17:18 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20032026/10/20 08:17:18 INFO lead: released remote=192.0.2.1:123420042026/10/20 08:17:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20052026/10/20 08:17:18 INFO Uploading 8jrpg4maycqhmjy95ggzsqnf5j5g9hv0-ca-test (144B)20062026/10/20 08:17:18 WARN Failed to register uploaded object key=8jrpg4maycqhmjy95ggzsqnf5j5g9hv0.ls error="server returned 404: 404 page not found\n"20072026/10/20 08:17:18 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20082026/10/20 08:17:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20092026/10/20 08:17:18 WARN Failed to register uploaded object key=log/vxnljmiihz43dww2xdyrmbr012y99gz3-ca-test.drv error="server returned 404: 404 page not found\n"20102026/10/20 08:17:18 INFO Signed narinfos id=1 count=120112026/10/20 08:17:18 INFO Uploading 1 narinfos20122026/10/20 08:17:18 INFO Received complete push request method=POST path=/api/pushes/1/complete20132026/10/20 08:17:18 WARN Failed to register uploaded object key=8jrpg4maycqhmjy95ggzsqnf5j5g9hv0.narinfo error="server returned 404: 404 page not found\n"20142026/10/20 08:17:18 INFO Completed push id=1 objects=4 duration=6.264119ms20152026/10/20 08:17:18 INFO Upload complete. (227ms)20162026/10/20 08:17:18 INFO lead: acquired remote=192.0.2.1:12342017=== NAME TestClientCADerivations2018 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3563995829/001/store/8jrpg4maycqhmjy95ggzsqnf5j5g9hv0-ca-test2019 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2020 Compression: zstd2021 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2022 NarSize: 1442023 References: 2024 Deriver: /build/TestClientCADerivations3563995829/001/store/vxnljmiihz43dww2xdyrmbr012y99gz3-ca-test.drv2025 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2026 client_ca_test.go:185: Checking for realisation files in S3...2027 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2028 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20292026/10/20 08:17:18 INFO Aborted multipart uploads count=0 kept=02030--- PASS: TestObjectStatsLargeCommit (1.64s)20312026/10/20 08:17:18 WARN Force mode enabled - objects will be deleted immediately without grace period20322026/10/20 08:17:18 INFO Received uploads request method=POST path=/api/pending_closures20332026/10/20 08:17:18 INFO Aborted multipart uploads count=0 kept=020342026/10/20 08:17:18 WARN Force mode enabled - objects will be deleted immediately without grace period20352026/10/20 08:17:18 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=020362026/10/20 08:17:18 INFO Vacuumed table table=pending_closures20372026/10/20 08:17:18 INFO Vacuumed table table=pending_objects20382026/10/20 08:17:18 INFO Vacuumed table table=multipart_uploads20392026/10/20 08:17:18 INFO Vacuumed table table=closures20402026/10/20 08:17:18 INFO Vacuumed table table=objects20412026/10/20 08:17:18 WARN Request failed, retrying attempt=2 backoff=205.170666ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20422026/10/20 08:17:18 INFO Received uploads request method=POST path=/api/pending_closures20432026/10/20 08:17:18 INFO Aborted multipart uploads count=0 kept=020442026/10/20 08:17:18 WARN Force mode enabled - objects will be deleted immediately without grace period20452026/10/20 08:17:18 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=020462026/10/20 08:17:18 INFO Vacuumed table table=pending_closures20472026/10/20 08:17:18 INFO Vacuumed table table=pending_objects20482026/10/20 08:17:18 INFO Vacuumed table table=multipart_uploads20492026/10/20 08:17:18 INFO Vacuumed table table=closures20502026/10/20 08:17:18 INFO Vacuumed table table=objects2051--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2052 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.43s)2053 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.43s)20542026/10/20 08:17:18 INFO Aborted multipart uploads count=0 kept=020552026/10/20 08:17:18 WARN Force mode enabled - objects will be deleted immediately without grace period20562026/10/20 08:17:18 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:42351/bucket97/?delete=\": context canceled"2057--- PASS: TestGCEndsOnShutdown (0.00s)2058 --- PASS: TestGCEndsOnShutdown/before_the_run (0.41s)2059 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.47s)2060 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.54s)2061=== NAME TestClientCADerivations2062 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2063 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2064 error: binary cache 's3://bucket84?endpoint=http://localhost:42351®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3563995829/001/store'2065 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12066--- PASS: TestClientCADerivations (0.85s)2067--- PASS: TestDeleteClosuresRacingPins (1.73s)20682026/10/20 08:17:18 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20692026/10/20 08:17:18 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2070--- PASS: TestUploadHandlersRejectOversizedBody (0.25s)2071 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2072 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2073 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.73s)20742026/10/20 08:17:18 WARN Request failed, retrying attempt=3 backoff=388.127459ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2075--- PASS: TestPendingClosureWriteTimeout (0.17s)2076 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2077 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2078 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2079 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.12s)2080=== NAME TestOrphanedObjectsGCStressTest2081 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2082 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion20832026/10/20 08:17:19 WARN Request failed, retrying attempt=4 backoff=780.508455ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2084--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2085 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.88s)2086 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.95s)2087=== NAME TestOrphanedObjectsGCStressTest2088 orphaned_objects_gc_test.go:503: Stress test completed successfully:2089 orphaned_objects_gc_test.go:504: - Active objects preserved: 202090 orphaned_objects_gc_test.go:505: - Objects deleted: 2102091 orphaned_objects_gc_test.go:506: - Total GC'd: 2102092--- PASS: TestOrphanedObjectsGCStressTest (2.93s)20932026/10/20 08:17:19 INFO lead: released remote=192.0.2.1:12342094--- PASS: TestLeadElectsOneAndHandsOver (2.96s)20952026/10/20 08:17:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020962026/10/20 08:17:19 INFO Received create pin request method=POST path=/api/pins/myapp20972026/10/20 08:17:19 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3019758252/001/store/ddm77vgmxhc11hqakhp3w7vfywqb27m1-pinned-file.txt narinfo_key=ddm77vgmxhc11hqakhp3w7vfywqb27m1.narinfo20982026/10/20 08:17:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures20992026/10/20 08:17:19 INFO Garbage collection started21002026/10/20 08:17:19 INFO Aborted multipart uploads count=0 kept=021012026/10/20 08:17:19 WARN Force mode enabled - objects will be deleted immediately without grace period21022026/10/20 08:17:19 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=021032026/10/20 08:17:19 INFO Vacuumed table table=pending_closures21042026/10/20 08:17:19 INFO Vacuumed table table=pending_objects21052026/10/20 08:17:19 INFO Vacuumed table table=multipart_uploads21062026/10/20 08:17:19 INFO Vacuumed table table=closures21072026/10/20 08:17:19 INFO Vacuumed table table=objects21082026/10/20 08:17:19 WARN Request failed, retrying attempt=5 backoff=1.621048514s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21092026/10/20 08:17:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02110=== NAME TestClientIntegration2111 client_integration_test.go:323: Objects in database after GC:2112 client_integration_test.go:323: Successfully deleted all objects with GC --force2113--- PASS: TestClientIntegration (2.88s)2114--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.00s)21152026/10/20 08:17:20 WARN Rate limiter enabled after throttle name=s3-test rate=521162026/10/20 08:17:20 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2117=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2118 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102119 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002120--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.22s)21212026/10/20 08:17:21 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21222026/10/20 08:17:21 WARN Request failed, retrying attempt=2 backoff=185.101452ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2123=== NAME TestPinProtectsFromGC2124 client_integration_test.go:840: Pin successfully protected closure from garbage collection2125--- PASS: TestPinProtectsFromGC (4.90s)21262026/10/20 08:17:21 WARN Request failed, retrying attempt=3 backoff=432.855061ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2127--- PASS: TestConnectWaitsForAPeerMigration (5.16s)21282026/10/20 08:17:22 WARN Request failed, retrying attempt=4 backoff=840.551143ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21292026/10/20 08:17:23 WARN Request failed, retrying attempt=5 backoff=1.662122973s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21302026/10/20 08:17:23 INFO Aborted multipart uploads count=1 kept=021312026/10/20 08:17:23 INFO Received cleanup request method=DELETE path=/api/pending_closures21322026/10/20 08:17:23 INFO Aborted multipart uploads count=1 kept=02133--- PASS: TestPendingCleanupUsesOneCutoff (6.67s)21342026/10/20 08:17:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21352026/10/20 08:17:24 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/10/20 08:17:24 WARN Request failed, retrying attempt=2 backoff=207.745086ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21372026/10/20 08:17:25 WARN Request failed, retrying attempt=3 backoff=365.658682ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21382026/10/20 08:17:25 WARN Request failed, retrying attempt=4 backoff=753.370782ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21392026/10/20 08:17:26 WARN Request failed, retrying attempt=5 backoff=1.517276861s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/10/20 08:17:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21412026/10/20 08:17:27 WARN Request failed, retrying attempt=2 backoff=201.353586ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21422026/10/20 08:17:28 WARN Request failed, retrying attempt=3 backoff=434.175076ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21432026/10/20 08:17:28 WARN Request failed, retrying attempt=4 backoff=831.762593ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21442026/10/20 08:17:29 WARN Request failed, retrying attempt=5 backoff=1.568053867s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2145--- PASS: TestClientErrorHandling (0.00s)2146 --- PASS: TestClientErrorHandling/InvalidStorePath (0.43s)2147 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.48s)2148 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.68s)2149PASS2150{"timestamp":"2026-10-20T08:17:30.904272102Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41030","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2386,"threadName":"rustfs-worker","threadId":"ThreadId(390)"}21512026-10-20 08:17:31.213 UTC [129] LOG: received smart shutdown request21522026-10-20 08:17:31.220 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 121532026-10-20 08:17:31.228 UTC [134] LOG: shutting down21542026-10-20 08:17:31.228 UTC [134] LOG: checkpoint starting: shutdown immediate21552026-10-20 08:17:31.963 UTC [134] LOG: checkpoint complete: wrote 10850 buffers (66.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.316 s, sync=0.378 s, total=0.736 s; sync files=34046, longest=0.009 s, average=0.001 s; distance=531578 kB, estimate=531578 kB; lsn=0/21E844F8, redo lsn=0/21E844F821562026-10-20 08:17:32.046 UTC [129] LOG: database system is shut down2157Running OIDC tests...2158=== RUN TestAudienceForIssuer2159=== PAUSE TestAudienceForIssuer2160=== RUN TestGlobMatch2161=== PAUSE TestGlobMatch2162=== RUN TestValidateToken_ValidToken2163=== PAUSE TestValidateToken_ValidToken2164=== RUN TestValidateToken_WrongAudience2165=== PAUSE TestValidateToken_WrongAudience2166=== RUN TestValidateToken_Expired2167=== PAUSE TestValidateToken_Expired2168=== RUN TestValidateToken_BoundClaimsMismatch2169=== PAUSE TestValidateToken_BoundClaimsMismatch2170=== RUN TestValidateToken_BoundSubjectMismatch2171=== PAUSE TestValidateToken_BoundSubjectMismatch2172=== RUN TestValidateToken_MultipleProviders2173=== PAUSE TestValidateToken_MultipleProviders2174=== RUN TestValidateToken_NoMatchingProvider2175=== PAUSE TestValidateToken_NoMatchingProvider2176=== RUN TestValidateToken_KubernetesServiceAccount2177=== PAUSE TestValidateToken_KubernetesServiceAccount2178=== RUN TestNewValidator_KubernetesRequiresCA2179=== PAUSE TestNewValidator_KubernetesRequiresCA2180=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2181=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2182=== RUN TestPins_ReservedForMatchingRule2183=== PAUSE TestPins_ReservedForMatchingRule2184=== RUN TestPins_TopLevelShorthand2185=== PAUSE TestPins_TopLevelShorthand2186=== RUN TestPins_ConfigValidation2187=== PAUSE TestPins_ConfigValidation2188=== RUN TestScopes_LegacyProviderDefaultsToWrite2189=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2190=== RUN TestScopes_Rules2191=== PAUSE TestScopes_Rules2192=== RUN TestScopes_ConfigValidation2193=== PAUSE TestScopes_ConfigValidation2194=== CONT TestAudienceForIssuer2195=== CONT TestPins_ConfigValidation2196=== CONT TestValidateToken_MultipleProviders2197=== CONT TestValidateToken_BoundClaimsMismatch2198--- PASS: TestAudienceForIssuer (0.00s)2199=== CONT TestValidateToken_NoMatchingProvider2200=== CONT TestPins_TopLevelShorthand2201=== CONT TestValidateToken_KubernetesServiceAccount2202=== CONT TestPins_ReservedForMatchingRule2203=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2204--- PASS: TestPins_ConfigValidation (0.00s)2205=== CONT TestValidateToken_Expired2206=== CONT TestNewValidator_KubernetesRequiresCA2207=== CONT TestScopes_Rules2208=== CONT TestValidateToken_BoundSubjectMismatch2209=== CONT TestScopes_ConfigValidation2210=== CONT TestValidateToken_WrongAudience2211=== CONT TestValidateToken_ValidToken2212=== CONT TestGlobMatch2213--- PASS: TestScopes_ConfigValidation (0.00s)2214=== RUN TestGlobMatch/foo_foo2215=== CONT TestScopes_LegacyProviderDefaultsToWrite2216=== PAUSE TestGlobMatch/foo_foo2217=== RUN TestGlobMatch/foo_bar2218=== PAUSE TestGlobMatch/foo_bar2219=== RUN TestGlobMatch/*_2220=== PAUSE TestGlobMatch/*_2221=== RUN TestGlobMatch/*_anything2222=== PAUSE TestGlobMatch/*_anything2223=== RUN TestGlobMatch/foo*_foo2224=== PAUSE TestGlobMatch/foo*_foo2225=== RUN TestGlobMatch/foo*_foobar2226=== PAUSE TestGlobMatch/foo*_foobar2227=== RUN TestGlobMatch/foo*_bar2228=== PAUSE TestGlobMatch/foo*_bar2229=== RUN TestGlobMatch/*bar_bar2230=== PAUSE TestGlobMatch/*bar_bar2231=== RUN TestGlobMatch/*bar_foobar2232=== PAUSE TestGlobMatch/*bar_foobar2233=== RUN TestGlobMatch/*bar_foo2234=== PAUSE TestGlobMatch/*bar_foo2235=== RUN TestGlobMatch/foo*bar_foobar2236=== PAUSE TestGlobMatch/foo*bar_foobar2237=== RUN TestGlobMatch/foo*bar_foo123bar2238=== PAUSE TestGlobMatch/foo*bar_foo123bar2239=== RUN TestGlobMatch/foo*bar_foobarbaz2240=== PAUSE TestGlobMatch/foo*bar_foobarbaz2241=== RUN TestGlobMatch/*/*_foo/bar2242=== PAUSE TestGlobMatch/*/*_foo/bar2243=== RUN TestGlobMatch/*/*_foo2244=== PAUSE TestGlobMatch/*/*_foo2245=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2246=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2247=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02248=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02249=== RUN TestGlobMatch/refs/*/main_refs/heads/main2250=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2251=== RUN TestGlobMatch/fo?_foo2252=== PAUSE TestGlobMatch/fo?_foo2253=== RUN TestGlobMatch/fo?_fo2254=== PAUSE TestGlobMatch/fo?_fo2255=== RUN TestGlobMatch/fo?_fooo2256=== PAUSE TestGlobMatch/fo?_fooo2257=== RUN TestGlobMatch/?oo_foo2258=== PAUSE TestGlobMatch/?oo_foo2259=== RUN TestGlobMatch/?oo_boo2260=== PAUSE TestGlobMatch/?oo_boo2261=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2262=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2263=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2264=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2265=== CONT TestGlobMatch/foo_foo2266=== CONT TestGlobMatch/*/*_foo2267=== CONT TestGlobMatch/*/*_foo/bar2268=== CONT TestGlobMatch/foo*bar_foobarbaz2269=== CONT TestGlobMatch/foo*bar_foo123bar2270=== CONT TestGlobMatch/foo*bar_foobar2271=== CONT TestGlobMatch/*bar_foo2272=== CONT TestGlobMatch/*bar_foobar2273=== CONT TestGlobMatch/*bar_bar2274=== CONT TestGlobMatch/foo*_bar2275=== CONT TestGlobMatch/foo*_foobar2276=== CONT TestGlobMatch/foo*_foo2277=== CONT TestGlobMatch/*_anything2278=== CONT TestGlobMatch/*_2279=== CONT TestGlobMatch/foo_bar2280=== CONT TestGlobMatch/fo?_fooo2281=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2282=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2283=== CONT TestGlobMatch/refs/*/main_refs/heads/main2284=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2285=== CONT TestGlobMatch/fo?_fo2286=== CONT TestGlobMatch/fo?_foo2287=== CONT TestGlobMatch/?oo_boo2288=== CONT TestGlobMatch/?oo_foo2289=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02290--- PASS: TestGlobMatch (0.00s)2291 --- PASS: TestGlobMatch/foo_foo (0.00s)2292 --- PASS: TestGlobMatch/*/*_foo (0.00s)2293 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2294 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2295 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2296 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2297 --- PASS: TestGlobMatch/*bar_foo (0.00s)2298 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2299 --- PASS: TestGlobMatch/*bar_bar (0.00s)2300 --- PASS: TestGlobMatch/foo*_bar (0.00s)2301 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2302 --- PASS: TestGlobMatch/foo*_foo (0.00s)2303 --- PASS: TestGlobMatch/*_anything (0.00s)2304 --- PASS: TestGlobMatch/*_ (0.00s)2305 --- PASS: TestGlobMatch/foo_bar (0.00s)2306 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2307 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2308 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2309 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2310 --- PASS: TestGlobMatch/fo?_fo (0.00s)2311 --- PASS: TestGlobMatch/fo?_foo (0.00s)2312 --- PASS: TestGlobMatch/?oo_boo (0.00s)2313 --- PASS: TestGlobMatch/?oo_foo (0.00s)2314 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2315 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)23162026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35319/oidc23172026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45725/oidc2318--- PASS: TestScopes_Rules (0.02s)23192026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40881/oidc2320--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.02s)2321--- PASS: TestValidateToken_WrongAudience (0.02s)23222026/10/20 08:17:33 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:427532323--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)23242026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36305/oidc2325--- PASS: TestValidateToken_Expired (0.05s)23262026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44757/oidc2327--- PASS: TestPins_TopLevelShorthand (0.06s)23282026/10/20 08:17:33 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232329--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)23302026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44987/oidc23312026/10/20 08:17:33 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39925/oidc23322026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36451/oidc23332026/10/20 08:17:33 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:46013/oidc2334--- PASS: TestValidateToken_ValidToken (0.07s)2335--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)2336--- PASS: TestValidateToken_MultipleProviders (0.08s)23372026/10/20 08:17:33 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33891/oidc2338--- PASS: TestValidateToken_NoMatchingProvider (0.10s)23392026/10/20 08:17:33 http: TLS handshake error from 127.0.0.1:39840: remote error: tls: bad certificate2340--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)23412026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36681/oidc2342--- PASS: TestPins_ReservedForMatchingRule (0.13s)23432026/10/20 08:17:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36969/oidc2344--- PASS: TestValidateToken_BoundClaimsMismatch (0.15s)2345PASS2346Running hook tests...2347=== RUN TestSendPathsEmpty2348=== PAUSE TestSendPathsEmpty2349=== RUN TestQueueEnqueueAndFetch2350=== PAUSE TestQueueEnqueueAndFetch2351=== RUN TestQueueDeduplication2352=== PAUSE TestQueueDeduplication2353=== RUN TestQueueRemove2354=== PAUSE TestQueueRemove2355=== RUN TestQueueFetchBatchLimit2356=== PAUSE TestQueueFetchBatchLimit2357=== RUN TestQueueRetryMovesToBack2358=== PAUSE TestQueueRetryMovesToBack2359=== RUN TestQueueFetchRemoveLifecycle2360=== PAUSE TestQueueFetchRemoveLifecycle2361=== RUN TestQueueConcurrentWriters2362=== PAUSE TestQueueConcurrentWriters2363=== RUN TestQueueRemoveLargeClosure2364=== PAUSE TestQueueRemoveLargeClosure2365=== RUN TestServerClientIntegration2366--- PASS: TestServerClientIntegration (0.00s)2367=== RUN TestServerQueueError23682026/10/20 08:17:33 ERROR Failed to queue paths error="permission denied" count=12369--- PASS: TestServerQueueError (0.00s)2370=== RUN TestGetListenerSocketActivation2371 server_test.go:219: === RUN TestGetListenerSocketActivation2372 --- PASS: TestGetListenerSocketActivation (0.00s)2373 PASS2374 2375--- PASS: TestGetListenerSocketActivation (0.01s)2376=== RUN TestDrainIsolatesPoisonPath2377=== PAUSE TestDrainIsolatesPoisonPath2378=== RUN TestRunNotBlockedByPoisonHead2379=== PAUSE TestRunNotBlockedByPoisonHead2380=== RUN TestDrainGivesUpWhenServerDown2381=== PAUSE TestDrainGivesUpWhenServerDown2382=== RUN TestFailedPathPrunedByLaterClosure2383=== PAUSE TestFailedPathPrunedByLaterClosure2384=== RUN TestWorkerUploadsAndRemoves2385=== PAUSE TestWorkerUploadsAndRemoves2386=== RUN TestWorkerSkipsGCdPaths2387=== PAUSE TestWorkerSkipsGCdPaths2388=== RUN TestWorkerPrunesClosureDeps2389=== PAUSE TestWorkerPrunesClosureDeps2390=== RUN TestDrainTimeout2391=== PAUSE TestDrainTimeout2392=== CONT TestSendPathsEmpty2393=== CONT TestDrainTimeout2394--- PASS: TestSendPathsEmpty (0.00s)2395=== CONT TestDrainIsolatesPoisonPath2396=== CONT TestQueueRemoveLargeClosure2397=== CONT TestQueueConcurrentWriters2398=== CONT TestQueueFetchRemoveLifecycle2399=== CONT TestQueueRetryMovesToBack2400=== CONT TestQueueFetchBatchLimit2401=== CONT TestQueueRemove2402=== CONT TestQueueDeduplication2403=== CONT TestQueueEnqueueAndFetch2404=== CONT TestWorkerPrunesClosureDeps2405=== CONT TestFailedPathPrunedByLaterClosure2406=== CONT TestRunNotBlockedByPoisonHead2407=== CONT TestDrainGivesUpWhenServerDown2408=== CONT TestWorkerSkipsGCdPaths2409=== CONT TestWorkerUploadsAndRemoves24102026/10/20 08:17:33 INFO Upload queue status pending=224112026/10/20 08:17:33 INFO Uploading batch count=224122026/10/20 08:17:33 INFO Uploading batch count=124132026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=124142026/10/20 08:17:33 INFO Uploading batch count=224152026/10/20 08:17:33 INFO Uploading batch count=424162026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=424172026/10/20 08:17:33 INFO Upload queue status pending=224182026/10/20 08:17:33 INFO Upload queue status pending=32419--- PASS: TestQueueEnqueueAndFetch (0.02s)24202026/10/20 08:17:33 INFO Uploading batch count=22421--- PASS: TestQueueRemove (0.02s)24222026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=224232026/10/20 08:17:33 INFO Upload queue status pending=224242026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3031825435/002/bbb2425--- PASS: TestQueueFetchBatchLimit (0.02s)24262026/10/20 08:17:33 INFO Uploading batch count=124272026/10/20 08:17:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3482699265/002/nonexistent24282026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3811407870/002/a24292026/10/20 08:17:33 INFO Uploading batch count=124302026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=124312026/10/20 08:17:33 INFO Uploading batch count=12432--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24332026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3811407870/002/b2434--- PASS: TestQueueRetryMovesToBack (0.02s)2435--- PASS: TestQueueDeduplication (0.02s)24362026/10/20 08:17:33 INFO Uploading batch count=124372026/10/20 08:17:33 INFO Uploading batch count=124382026/10/20 08:17:33 INFO Uploading batch count=224392026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=224402026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3811407870/002/c24412026/10/20 08:17:33 INFO Uploading batch count=124422026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=124432026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3811407870/002/d24442026/10/20 08:17:33 INFO Uploading batch count=224452026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=224462026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3811407870/002/e24472026/10/20 08:17:33 INFO Uploading batch count=124482026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=124492026/10/20 08:17:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3811407870/002/f24502026/10/20 08:17:33 INFO Uploading batch count=124512026/10/20 08:17:33 ERROR Upload failed error="upload failed" count=12452--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24532026/10/20 08:17:33 ERROR Drain finished with paths left in queue remaining=1024542026/10/20 08:17:33 ERROR Drain finished with paths left in queue remaining=12455--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2456--- PASS: TestDrainIsolatesPoisonPath (0.03s)2457--- PASS: TestWorkerUploadsAndRemoves (0.04s)2458--- PASS: TestWorkerSkipsGCdPaths (0.04s)2459--- PASS: TestWorkerPrunesClosureDeps (0.04s)2460--- PASS: TestQueueRemoveLargeClosure (0.06s)24612026/10/20 08:17:34 ERROR Upload failed error="context deadline exceeded" count=224622026/10/20 08:17:34 ERROR Drain finished with paths left in queue remaining=42463--- PASS: TestDrainTimeout (0.22s)2464--- PASS: TestQueueConcurrentWriters (0.28s)24652026/10/20 08:17:34 INFO Uploading batch count=124662026/10/20 08:17:34 INFO Uploading batch count=124672026/10/20 08:17:34 INFO Uploading batch count=124682026/10/20 08:17:34 ERROR Upload failed error="upload failed" count=124692026/10/20 08:17:34 INFO Uploading batch count=124702026/10/20 08:17:34 ERROR Upload failed error="upload failed" count=124712026/10/20 08:17:34 INFO Uploading batch count=124722026/10/20 08:17:34 ERROR Upload failed error="upload failed" count=124732026/10/20 08:17:34 INFO Uploading batch count=124742026/10/20 08:17:34 ERROR Upload failed error="upload failed" count=124752026/10/20 08:17:34 ERROR Drain finished with paths left in queue remaining=12476--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2477PASS2478Running signing tests...2479=== RUN TestExternalSigner2480=== PAUSE TestExternalSigner2481=== RUN TestExternalSignerWrongPublicKey2482=== PAUSE TestExternalSignerWrongPublicKey2483=== RUN TestExternalSignerErrors2484=== PAUSE TestExternalSignerErrors2485=== RUN TestExternalSignerRestartsAfterCrash2486=== PAUSE TestExternalSignerRestartsAfterCrash2487=== RUN TestExternalSignerProgramErrorKeepsProcess2488=== PAUSE TestExternalSignerProgramErrorKeepsProcess2489=== RUN TestExternalSignerClose2490=== PAUSE TestExternalSignerClose2491=== RUN TestExternalSignerRejectsInvalidPublicKey2492=== PAUSE TestExternalSignerRejectsInvalidPublicKey2493=== RUN TestExternalSignerCancellation2494=== PAUSE TestExternalSignerCancellation2495=== RUN TestGenerateFingerprint2496=== PAUSE TestGenerateFingerprint2497=== RUN TestParseSigningKey2498=== PAUSE TestParseSigningKey2499=== RUN TestSign2500=== PAUSE TestSign2501=== RUN TestSignBatch2502=== PAUSE TestSignBatch2503=== RUN TestNilKeyPublicKey2504=== PAUSE TestNilKeyPublicKey2505=== RUN TestSignErrors2506=== PAUSE TestSignErrors2507=== CONT TestExternalSigner2508=== CONT TestExternalSignerCancellation2509=== CONT TestExternalSignerProgramErrorKeepsProcess2510=== CONT TestSignBatch2511=== CONT TestSignErrors2512=== CONT TestNilKeyPublicKey2513--- PASS: TestNilKeyPublicKey (0.00s)2514=== CONT TestExternalSignerRejectsInvalidPublicKey2515=== CONT TestExternalSignerClose2516=== RUN TestExternalSignerRejectsInvalidPublicKey/#002517=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002518=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2519=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2520=== CONT TestParseSigningKey2521--- PASS: TestSignBatch (0.00s)2522=== CONT TestGenerateFingerprint2523=== RUN TestParseSigningKey/valid_32-byte_key2524=== PAUSE TestParseSigningKey/valid_32-byte_key2525=== RUN TestGenerateFingerprint/basic_with_references2526=== PAUSE TestGenerateFingerprint/basic_with_references2527=== CONT TestExternalSignerRestartsAfterCrash2528=== CONT TestExternalSignerWrongPublicKey2529=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2530=== RUN TestSignErrors/nil_key2531=== PAUSE TestSignErrors/nil_key2532=== CONT TestSign2533=== CONT TestExternalSignerErrors2534--- PASS: TestSign (0.00s)2535=== RUN TestExternalSignerErrors/wrong_id2536=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2537=== RUN TestGenerateFingerprint/no_references2538=== PAUSE TestGenerateFingerprint/no_references2539=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2540=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2541=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2542=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2543=== RUN TestGenerateFingerprint/invalid_nar_hash_length2544=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2545=== RUN TestGenerateFingerprint/invalid_store_path_prefix2546=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2547=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2548=== RUN TestSignErrors/nil_narinfo2549=== PAUSE TestSignErrors/nil_narinfo2550=== RUN TestSignErrors/invalid_narinfo2551=== PAUSE TestSignErrors/invalid_narinfo2552=== RUN TestSignErrors/canceled2553=== PAUSE TestSignErrors/canceled2554=== CONT TestSignErrors/nil_key2555=== CONT TestSignErrors/nil_narinfo2556=== PAUSE TestExternalSignerErrors/wrong_id2557=== CONT TestSignErrors/invalid_narinfo2558=== CONT TestSignErrors/canceled2559=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2560=== RUN TestGenerateFingerprint/invalid_reference_prefix2561=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2562=== CONT TestGenerateFingerprint/basic_with_references2563=== CONT TestGenerateFingerprint/no_references2564=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2565=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2566=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2567=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2568=== CONT TestGenerateFingerprint/invalid_nar_hash_length2569=== RUN TestExternalSignerErrors/null_signatures2570=== PAUSE TestExternalSignerErrors/null_signatures2571--- PASS: TestSignErrors (0.00s)2572 --- PASS: TestSignErrors/nil_key (0.00s)2573 --- PASS: TestSignErrors/nil_narinfo (0.00s)2574 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2575 --- PASS: TestSignErrors/canceled (0.00s)2576=== RUN TestParseSigningKey/no_colon2577=== PAUSE TestParseSigningKey/no_colon2578=== CONT TestGenerateFingerprint/invalid_reference_prefix2579=== CONT TestGenerateFingerprint/invalid_store_path_prefix2580=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2581=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2582=== CONT TestExternalSignerRejectsInvalidPublicKey/#002583=== RUN TestExternalSignerErrors/missing_signature_name2584=== PAUSE TestExternalSignerErrors/missing_signature_name2585=== RUN TestExternalSignerErrors/wrong_signature_name2586=== PAUSE TestExternalSignerErrors/wrong_signature_name2587=== RUN TestExternalSignerErrors/invalid_signature_base642588=== PAUSE TestExternalSignerErrors/invalid_signature_base642589=== RUN TestExternalSignerErrors/program_error2590=== PAUSE TestExternalSignerErrors/program_error2591=== RUN TestExternalSignerErrors/exit_on_request2592--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2593=== RUN TestParseSigningKey/empty_name2594=== PAUSE TestParseSigningKey/empty_name2595=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2596=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2597=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2598=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2599=== PAUSE TestExternalSignerErrors/exit_on_request2600--- PASS: TestGenerateFingerprint (0.00s)2601 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2602 --- PASS: TestGenerateFingerprint/no_references (0.00s)2603 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2604 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2605 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2606 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2607 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2608=== RUN TestParseSigningKey/invalid_base642609=== RUN TestExternalSignerErrors/missing_signatures2610=== PAUSE TestExternalSignerErrors/missing_signatures2611=== RUN TestExternalSignerErrors/wrong_signatures_shape2612--- PASS: TestExternalSignerClose (0.00s)2613--- PASS: TestExternalSignerWrongPublicKey (0.00s)2614=== PAUSE TestParseSigningKey/invalid_base642615=== RUN TestParseSigningKey/wrong_length2616=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2617=== RUN TestExternalSignerErrors/too_few_signatures2618=== PAUSE TestExternalSignerErrors/too_few_signatures2619=== RUN TestExternalSignerErrors/wrong_signature_length2620=== PAUSE TestExternalSignerErrors/wrong_signature_length2621=== RUN TestExternalSignerErrors/exit_at_startup2622=== PAUSE TestExternalSignerErrors/exit_at_startup2623=== RUN TestExternalSignerErrors/invalid_JSON2624=== PAUSE TestExternalSignerErrors/invalid_JSON2625=== RUN TestExternalSignerErrors/wrong_shape2626=== PAUSE TestExternalSignerErrors/wrong_shape2627=== RUN TestExternalSignerErrors/unrequested_key2628=== PAUSE TestExternalSignerErrors/unrequested_key2629=== RUN TestExternalSignerErrors/null2630=== PAUSE TestExternalSignerErrors/null2631=== CONT TestExternalSignerErrors/wrong_id2632=== CONT TestExternalSignerErrors/wrong_signatures_shape2633--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2634 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2635 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2636 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2637 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2638 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2639=== CONT TestExternalSignerErrors/wrong_shape2640--- PASS: TestExternalSigner (0.01s)2641=== PAUSE TestParseSigningKey/wrong_length2642=== CONT TestParseSigningKey/valid_32-byte_key2643=== CONT TestExternalSignerErrors/null2644=== CONT TestExternalSignerErrors/unrequested_key2645=== CONT TestExternalSignerErrors/missing_signatures2646=== CONT TestExternalSignerErrors/wrong_signature_length2647=== CONT TestExternalSignerErrors/too_few_signatures2648=== CONT TestExternalSignerErrors/invalid_JSON2649=== CONT TestExternalSignerErrors/exit_at_startup2650=== CONT TestExternalSignerErrors/invalid_signature_base642651=== CONT TestExternalSignerErrors/exit_on_request2652=== CONT TestExternalSignerErrors/program_error2653=== CONT TestExternalSignerErrors/null_signatures2654=== CONT TestExternalSignerErrors/missing_signature_name2655=== CONT TestExternalSignerErrors/wrong_signature_name2656=== CONT TestParseSigningKey/empty_name2657=== CONT TestParseSigningKey/wrong_length2658=== CONT TestParseSigningKey/invalid_base642659=== CONT TestParseSigningKey/no_colon2660=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2661--- PASS: TestParseSigningKey (0.00s)2662 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2663 --- PASS: TestParseSigningKey/empty_name (0.00s)2664 --- PASS: TestParseSigningKey/wrong_length (0.00s)2665 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2666 --- PASS: TestParseSigningKey/no_colon (0.00s)2667 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2668--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2669--- PASS: TestExternalSignerErrors (0.00s)2670 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2671 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2672 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2673 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2674 --- PASS: TestExternalSignerErrors/program_error (0.00s)2675 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2676 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)2677 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2678 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2679 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2680 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2681 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2682 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2683 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2684 --- PASS: TestExternalSignerErrors/null (0.01s)2685 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2686--- PASS: TestExternalSignerCancellation (0.02s)2687PASS2688Running OpenBao signer tests...2689=== RUN TestSign2690=== PAUSE TestSign2691=== RUN TestSignErrors2692=== PAUSE TestSignErrors2693=== RUN TestServe2694=== PAUSE TestServe2695=== RUN TestServeRejectsGarbage2696=== PAUSE TestServeRejectsGarbage2697=== CONT TestSign2698=== CONT TestServe2699=== CONT TestServeRejectsGarbage2700=== CONT TestSignErrors2701=== RUN TestSignErrors/invalid_base642702--- PASS: TestServeRejectsGarbage (0.00s)2703=== PAUSE TestSignErrors/invalid_base642704--- PASS: TestServe (0.00s)2705=== RUN TestSignErrors/http_error2706=== PAUSE TestSignErrors/http_error2707=== RUN TestSignErrors/invalid_json2708=== PAUSE TestSignErrors/invalid_json2709=== RUN TestSignErrors/no_prefix2710=== PAUSE TestSignErrors/no_prefix2711=== CONT TestSignErrors/invalid_base642712=== CONT TestSignErrors/invalid_json2713=== CONT TestSignErrors/http_error2714=== CONT TestSignErrors/no_prefix2715--- PASS: TestSign (0.00s)2716--- PASS: TestSignErrors (0.00s)2717 --- PASS: TestSignErrors/http_error (0.00s)2718 --- PASS: TestSignErrors/invalid_base64 (0.00s)2719 --- PASS: TestSignErrors/invalid_json (0.00s)2720 --- PASS: TestSignErrors/no_prefix (0.00s)2721PASS