niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #433
· raw
1tribuchet: building on eliza2Running 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 TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestResolveStorePath117=== CONT TestScriptTokenScriptFails118=== CONT TestDumpPathSingleFile119=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer120--- PASS: TestResolveStorePath (0.00s)121=== CONT TestScriptTokenCachesUntilRefresh122=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess123=== CONT TestRateLimiterFeedback124=== CONT TestPathInfoCACompatibility125=== CONT TestParsePathInfoJSONMultiplePaths126=== CONT TestParsePathInfoJSON127=== CONT TestPathInfoHashCompatibility128=== CONT TestGetStorePathHash129=== CONT TestConvertHashToNix32130=== CONT TestEncodeNixBase32WithRealHash131=== CONT TestScriptTokenEmptyCommand132=== CONT TestEncodeNixBase32133=== CONT TestDumpPathWriterError134=== CONT TestUploadMultipart_PartsInParallel135=== CONT TestFileTokenMissing136=== CONT TestDumpPathMatchesNix137=== CONT TestScriptTokenBadJSON138=== CONT TestSupersededNARStillUploadsListing139=== CONT TestScriptTokenEmptyToken140=== CONT TestUploadMultipart_SupersededByPeer141--- PASS: TestScriptTokenScriptFails (0.00s)142=== CONT TestPartSizeForNAR1432026/10/25 19:06:29 WARN Rate limiter enabled after throttle name=server-test rate=5144=== RUN TestRateLimiterFeedback/429_enables_limiter145=== RUN TestPathInfoCACompatibility/null_ca_field146=== RUN TestPartSizeForNAR/zero_stays_at_minimum147=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths148=== RUN TestParsePathInfoJSON/Nix_format149=== RUN TestGetStorePathHash/valid_store_path150=== PAUSE TestParsePathInfoJSON/Nix_format151=== RUN TestParsePathInfoJSON/Lix_format152=== PAUSE TestParsePathInfoJSON/Lix_format153--- PASS: TestFileTokenMissing (0.00s)154=== RUN TestParsePathInfoJSON/empty_input155=== PAUSE TestParsePathInfoJSON/empty_input156=== RUN TestParsePathInfoJSON/whitespace_only157=== PAUSE TestParsePathInfoJSON/whitespace_only158=== RUN TestParsePathInfoJSON/invalid_JSON159=== PAUSE TestParsePathInfoJSON/invalid_JSON160=== CONT TestScriptTokenNoExpiryRerunsEveryCall161--- PASS: TestEncodeNixBase32WithRealHash (0.00s)162=== CONT TestFileTokenEmpty163=== RUN TestConvertHashToNix32/SRI_format_to_Nix32164=== PAUSE TestGetStorePathHash/valid_store_path165=== CONT TestUploadMultipart_FailedPartBufferNotReused166=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)167=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)168--- PASS: TestScriptTokenEmptyCommand (0.00s)169=== CONT TestStreamPushBatchesUnderLoad170--- PASS: TestFileTokenEmpty (0.00s)171=== RUN TestEncodeNixBase32/test_string_hash172=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon173=== CONT TestSetClientTLSErrors174=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32175=== PAUSE TestRateLimiterFeedback/429_enables_limiter176=== RUN TestRateLimiterFeedback/503_enables_limiter177=== RUN TestGetStorePathHash/basename_without_hyphen_should_error178=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error179=== PAUSE TestPathInfoCACompatibility/null_ca_field180=== PAUSE TestEncodeNixBase32/test_string_hash181=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum182=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths183=== RUN TestEncodeNixBase32/empty_input184=== PAUSE TestEncodeNixBase32/empty_input185=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths186=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon187=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths188=== RUN TestConvertHashToNix32/already_Nix32_format189=== CONT TestStaticToken190=== CONT TestStreamPushReportsSignatures191--- PASS: TestDoServerRequestAttachesToken (0.04s)192=== PAUSE TestRateLimiterFeedback/503_enables_limiter193=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter194=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter195=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter196=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter197=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error198=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error199=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error200=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error201=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun202=== RUN TestPartSizeForNAR/small_stays_at_minimum203=== RUN TestSupersededNARStillUploadsListing/small_NAR204=== CONT TestFilterOversizedClosures205=== CONT TestStreamPushGivesUpOnDeadServer206=== RUN TestUploadMultipart_SupersededByPeer/exists207=== PAUSE TestUploadMultipart_SupersededByPeer/exists208=== CONT TestFileTokenReadsAndCaches2092026/10/25 19:06:29 ERROR Upload failed error=boom count=1210=== CONT TestStreamPushReportsSkippedPaths2112026/10/25 19:06:29 ERROR Upload failed error="connection refused" count=20212=== PAUSE TestConvertHashToNix32/already_Nix32_format2132026/10/25 19:06:29 ERROR Server seems unavailable, giving up on batch untried=17214=== RUN TestConvertHashToNix32/invalid_format215=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI216=== CONT TestRegisterUploadedObjectReusesConnections217=== PAUSE TestConvertHashToNix32/invalid_format218=== RUN TestPathInfoCACompatibility/old_string_format_-_text219=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica220=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text221=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive222=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive223=== CONT TestStreamPushReportsEveryPath224=== RUN TestPathInfoCACompatibility/new_structured_format_-_text225=== PAUSE TestPartSizeForNAR/small_stays_at_minimum226=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum227=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum228=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts229=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts230=== RUN TestPartSizeForNAR/1_TiB231=== PAUSE TestPartSizeForNAR/1_TiB232=== RUN TestPartSizeForNAR/5_TiB_S3_max_object233=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object234=== RUN TestPartSizeForNAR/capped_at_5_GiB235=== PAUSE TestPartSizeForNAR/capped_at_5_GiB236=== RUN TestFilterOversizedClosures/no_limit_keeps_everything237=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything238=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped239=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped240=== RUN TestFilterOversizedClosures/all_closures_skipped241=== PAUSE TestFilterOversizedClosures/all_closures_skipped242=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry243=== RUN TestSetClientTLSErrors/missing_cert_file244=== PAUSE TestSetClientTLSErrors/missing_cert_file2452026/10/25 19:06:29 INFO Garbage collection started246=== RUN TestSetClientTLSErrors/missing_key_file2472026/10/25 19:06:29 INFO Garbage collection started248=== PAUSE TestSetClientTLSErrors/missing_key_file249=== RUN TestSetClientTLSErrors/missing_ca_file250=== PAUSE TestSetClientTLSErrors/missing_ca_file251=== RUN TestSetClientTLSErrors/invalid_ca_file252=== PAUSE TestSetClientTLSErrors/invalid_ca_file253=== CONT TestShellSplitErrors254=== CONT TestDoWithRetry_FinalResponseBodyReadable255=== CONT TestSetClientTLS256=== CONT TestRetryTimeoutOutlastsMaxRetries2572026/10/25 19:06:29 WARN Rate limiter enabled after throttle name=s3-test rate=5258=== RUN TestUploadMultipart_SupersededByPeer/missing2592026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37653260=== PAUSE TestUploadMultipart_SupersededByPeer/missing2612026/10/25 19:06:29 WARN Rate limiter enabled after throttle name=server-test rate=52622026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:44023263=== CONT TestStreamPushIsolatesFailures264=== CONT TestSetClientTLSDoesNotMutateDefaultTransport265=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI266=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512267=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512268--- PASS: TestStaticToken (0.00s)2692026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:40265270--- PASS: TestScriptTokenBadJSON (0.04s)2712026/10/25 19:06:29 WARN Rate limiter backed off name=server-test rate=5272--- PASS: TestScriptTokenEmptyToken (0.04s)273--- PASS: TestDumpPathSingleFile (0.04s)274--- PASS: TestStreamPushReportsSignatures (0.00s)275--- PASS: TestStreamPushReportsSkippedPaths (0.00s)276--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)277--- PASS: TestFileTokenReadsAndCaches (0.00s)278--- PASS: TestStreamPushReportsEveryPath (0.00s)279--- PASS: TestShellSplitErrors (0.00s)280=== CONT TestShellSplit281--- PASS: TestShellSplit (0.00s)282=== CONT TestStreamPushStopsWhenCanceled2832026/10/25 19:06:29 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=0284--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)285--- PASS: TestStreamPushStopsWhenCanceled (0.00s)286=== CONT TestClientSignaturesByStorePath287--- PASS: TestClientSignaturesByStorePath (0.00s)288=== CONT TestParsePathInfoJSON/invalid_JSON289=== CONT TestParsePathInfoJSON/whitespace_only290=== CONT TestParsePathInfoJSON/empty_input291=== CONT TestParsePathInfoJSON/Lix_format2922026/10/25 19:06:29 ERROR Upload failed error="bad path" count=3293=== CONT TestEncodeNixBase32/empty_input294--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)295=== CONT TestDoWithRetry_BodyReplayedViaGetBody296--- PASS: TestStreamPushIsolatesFailures (0.00s)297=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths298=== CONT TestParsePathInfoJSON/Nix_format299--- PASS: TestParsePathInfoJSON (0.00s)300 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)301 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)302 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)303 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)304 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)305=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text306=== CONT TestCaseHackSuffix307=== PAUSE TestSupersededNARStillUploadsListing/small_NAR308=== CONT TestStreamPushRequestLine309=== CONT TestEncodeNixBase32/test_string_hash310=== CONT TestGetStorePathHash/valid_store_path311=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error312=== CONT TestRateLimiterFeedback/503_enables_limiter3132026/10/25 19:06:29 WARN Rate limiter enabled after throttle name=server-test rate=53142026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:44469315=== RUN TestSupersededNARStillUploadsListing/dump_cut_short3162026/10/25 19:06:29 WARN Garbage collection finished on another replica. Its statistics are not available here317=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short318=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails319=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails320=== RUN TestSetClientTLS/rejects_connection_without_client_cert321=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert322=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA323=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA324=== CONT TestGetStorePathHash/basename_without_hyphen_should_error325=== CONT TestConvertHashToNix32/SRI_format_to_Nix32326=== CONT TestConvertHashToNix32/already_Nix32_format327=== CONT TestPartSizeForNAR/zero_stays_at_minimum3282026/10/25 19:06:29 ERROR Upload failed error=boom count=1329=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3302026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:40265331=== RUN TestSetClientTLS/preserves_debug_logging_transport3322026/10/25 19:06:29 WARN Rate limiter backed off name=server-test rate=5333=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3342026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:44469335=== CONT TestConvertHashToNix32/invalid_format336=== CONT TestPartSizeForNAR/5_TiB_S3_max_object337=== CONT TestPartSizeForNAR/1_TiB338=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts339--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)340--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)341--- PASS: TestEncodeNixBase32 (0.04s)342 --- PASS: TestEncodeNixBase32/empty_input (0.00s)343 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)3442026/10/25 19:06:29 WARN Rate limiter enabled after throttle name=server-test rate=5345=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3462026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:43681347=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method348=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method349=== CONT TestFilterOversizedClosures/all_closures_skipped350=== CONT TestSetClientTLSErrors/missing_cert_file3512026/10/25 19:06:29 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=50352--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)353--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)354=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3552026/10/25 19:06:29 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=2000356=== CONT TestSetClientTLSErrors/invalid_ca_file357=== CONT TestSetClientTLSErrors/missing_ca_file3582026/10/25 19:06:29 WARN Rate limiter backed off name=server-test rate=5359=== CONT TestSetClientTLSErrors/missing_key_file360--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)361=== CONT TestUploadMultipart_SupersededByPeer/exists362=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)363=== CONT TestRateLimiterFeedback/429_enables_limiter364=== CONT TestPartSizeForNAR/small_stays_at_minimum365=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI366=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error367=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails368--- PASS: TestGetStorePathHash (0.04s)369 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)370 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)371 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)372 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)373=== CONT TestPartSizeForNAR/capped_at_5_GiB374=== CONT TestSetClientTLS/rejects_connection_without_client_cert375=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum376=== CONT TestSetClientTLS/preserves_debug_logging_transport377--- PASS: TestFilterOversizedClosures (0.00s)378 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)379 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)380 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)381--- PASS: TestSetClientTLSErrors (0.00s)382 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)383 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)384 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)385 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)3862026/10/25 19:06:29 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:40265387--- PASS: TestConvertHashToNix32 (0.04s)388 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)389 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)390 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)391=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon392=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3932026/10/25 19:06:29 INFO Uploading abc-hello (1.0GB)394=== CONT TestSupersededNARStillUploadsListing/small_NAR395=== CONT TestPathInfoCACompatibility/null_ca_field396=== CONT TestPathInfoCACompatibility/new_structured_format_-_text397=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512398=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA399--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)400--- PASS: TestPathInfoHashCompatibility (0.04s)401 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)402 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)403 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)404 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)405--- PASS: TestPartSizeForNAR (0.04s)406 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)407 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)408 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)409 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)410 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)411 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)412 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)413=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter4142026/10/25 19:06:29 INFO Uploading abc-hello (1.0GB)4152026/10/25 19:06:30 WARN Rate limiter enabled after throttle name=server-test rate=5416=== CONT TestUploadMultipart_SupersededByPeer/missing4172026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:383734182026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:402654192026/10/25 19:06:30 WARN Rate limiter backed off name=server-test rate=5420=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths421=== CONT TestPathInfoCACompatibility/old_string_format_-_text422--- PASS: TestParsePathInfoJSONMultiplePaths (0.04s)423 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)424 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)425=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method426=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive427--- PASS: TestPathInfoCACompatibility (0.04s)428 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)429 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)430 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)431 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)432 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)433--- PASS: TestRateLimiterFeedback (0.04s)434 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)435 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)436 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.27s)437 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.26s)438--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)439 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.27s)440 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)4412026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:402654422026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:402654432026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:402654442026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:40265445--- PASS: TestCaseHackSuffix (0.27s)4462026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:402654472026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:402654482026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:402654492026/10/25 19:06:30 http: TLS handshake error from 127.0.0.1:42772: remote error: tls: bad certificate4502026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:40265451--- PASS: TestSetClientTLS (0.00s)452 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.27s)453 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.27s)454 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.28s)455--- PASS: TestRegisterUploadedObjectReusesConnections (0.28s)4562026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:402654572026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:402654582026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:402654592026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:402654602026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:402654612026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:40265462--- PASS: TestStreamPushRequestLine (0.29s)4632026/10/25 19:06:30 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:40265464--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.29s)465--- PASS: TestDumpPathWriterError (0.33s)4662026/10/25 19:06:30 WARN Rate limiter enabled after throttle name=s3-test rate=54672026/10/25 19:06:30 INFO Uploading abc-hello (1.0GB)468--- PASS: TestStreamPushBatchesUnderLoad (0.36s)469--- PASS: TestDumpPathMatchesNix (0.37s)4702026/10/25 19:06:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:41537/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:41537/part/24712026/10/25 19:06:30 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"472--- PASS: TestSupersededNARStillUploadsListing (0.01s)473 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.27s)474 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.27s)475 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.82s)476--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.89s)477--- PASS: TestUploadMultipart_PartsInParallel (0.91s)4782026/10/25 19:06:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46677/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46677/api/uploads/complete4792026/10/25 19:06:30 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4802026/10/25 19:06:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46677/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46677/api/uploads/complete4812026/10/25 19:06:30 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4822026/10/25 19:06:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46677/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46677/api/uploads/complete4832026/10/25 19:06:30 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"484--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)485--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)486PASS487Running server tests...488The files belonging to this database system will be owned by user "nixbld".489This user must also own the server process.490491The database cluster will be initialized with locale "C".492The default database encoding has accordingly been set to "SQL_ASCII".493The default text search configuration will be set to "english".494495Data page checksums are enabled.496497creating directory /build/postgres1484930321/data ... ok498creating subdirectories ... ok499selecting dynamic shared memory implementation ... posix500selecting default "max_connections" ... 100501selecting default "shared_buffers" ... 128MB502selecting default time zone ... UTC503creating configuration files ... ok504running bootstrap script ... ok505performing post-bootstrap initialization ... ok506syncing data to disk ... ok507508initdb: warning: enabling "trust" authentication for local connections509initdb: 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.510511Success. You can now start the database server using:512513 pg_ctl -D /build/postgres1484930321/data -l logfile start514515/build/postgres1484930321:5432 - no response5162026-10-25 19:06:31.588 UTC [127] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5172026-10-25 19:06:31.588 UTC [127] LOG: listening on Unix socket "/build/postgres1484930321/.s.PGSQL.5432"5182026-10-25 19:06:31.592 UTC [134] LOG: database system was shut down at 2026-10-25 19:06:31 UTC5192026-10-25 19:06:31.596 UTC [127] LOG: database system is ready to accept connections520/build/postgres1484930321:5432 - accepting connections521=== RUN TestService_AuthMiddleware522=== PAUSE TestService_AuthMiddleware523=== RUN TestService_AuthMiddleware_MTLSProxyHeader524=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader525=== RUN TestService_AuthMiddleware_MTLSBoundSubjects526=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects527=== RUN TestService_ReadAuthMiddleware528=== PAUSE TestService_ReadAuthMiddleware529=== RUN TestService_AuthMiddleware_OIDC530=== PAUSE TestService_AuthMiddleware_OIDC531=== RUN TestService_RequireScope_OIDC532=== PAUSE TestService_RequireScope_OIDC533=== RUN TestService_ReadScope_PublicByDefault534=== PAUSE TestService_ReadScope_PublicByDefault535=== RUN TestCacheConfigHandler536=== PAUSE TestCacheConfigHandler537=== RUN TestCacheStatsHandler538=== PAUSE TestCacheStatsHandler539=== RUN TestClientCADerivations540=== PAUSE TestClientCADerivations541=== RUN TestClientErrorHandling542=== PAUSE TestClientErrorHandling543=== RUN TestClientIntegration544=== PAUSE TestClientIntegration545=== RUN TestClientMultipleUploads546=== PAUSE TestClientMultipleUploads547=== RUN TestClientWithDependencies548=== PAUSE TestClientWithDependencies549=== RUN TestClientSharedPathCommittedMidPush550=== PAUSE TestClientSharedPathCommittedMidPush551=== RUN TestPinProtectsFromGC552=== PAUSE TestPinProtectsFromGC553=== RUN TestClientPushesUseOnePush554=== PAUSE TestClientPushesUseOnePush555=== RUN TestClientFallsBackToClosures556=== PAUSE TestClientFallsBackToClosures557=== RUN TestDeleteClosuresRacingPins558=== PAUSE TestDeleteClosuresRacingPins559=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock560=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock561=== RUN TestResolveDBConnectionString562=== PAUSE TestResolveDBConnectionString563=== RUN TestConnectWaitsForAPeerMigration564=== PAUSE TestConnectWaitsForAPeerMigration565=== RUN TestLeadElectsOneAndHandsOver566=== PAUSE TestLeadElectsOneAndHandsOver567=== RUN TestLeadIncumbentWinsAfterRestart5682026/10/25 19:06:32 INFO lead: acquired remote=192.0.2.1:12345692026/10/25 19:06:32 INFO lead: released remote=192.0.2.1:12345702026/10/25 19:06:32 INFO lead: acquired remote=192.0.2.1:12345712026/10/25 19:06:33 INFO lead: released remote=192.0.2.1:1234572--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)573=== RUN TestLeadIncumbentAnnouncesAtOnce574=== PAUSE TestLeadIncumbentAnnouncesAtOnce575=== RUN TestLeadEndsOnShutdown576=== PAUSE TestLeadEndsOnShutdown577=== RUN TestLeadEndsWhenItsConnectionHangs5782026/10/25 19:06:33 INFO lead: acquired remote=192.0.2.1:12345792026-10-25 19:06:35.295 UTC [378] FATAL: terminating connection due to administrator command5802026/10/25 19:06:35 INFO lead: acquired remote=192.0.2.1:12345812026/10/25 19:06:36 WARN lead: lock connection lost error="timeout: context deadline exceeded"5822026/10/25 19:06:36 INFO lead: released remote=192.0.2.1:12345832026/10/25 19:06:36 INFO lead: released remote=192.0.2.1:1234584--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)585=== RUN TestGCAdvisoryLockBlocksConcurrentRun586=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun587=== RUN TestGCBugBareHashReferences588=== PAUSE TestGCBugBareHashReferences589=== RUN TestGCMetrics590=== PAUSE TestGCMetrics591=== RUN TestPushDedupSurvivesConcurrentGC592=== PAUSE TestPushDedupSurvivesConcurrentGC593=== RUN TestDeduplicatedObjectsRecordedAsPending594=== PAUSE TestDeduplicatedObjectsRecordedAsPending595=== RUN TestGCSweepSkipsPendingObjects596=== PAUSE TestGCSweepSkipsPendingObjects597=== RUN TestTombstonedObjectOfferedWithoutWaiting598=== PAUSE TestTombstonedObjectOfferedWithoutWaiting599=== RUN TestGCSweepDeliversEachKeyOnce600=== PAUSE TestGCSweepDeliversEachKeyOnce601=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection602=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection603=== RUN TestForceGCDuringPushOffersSweptObject604=== PAUSE TestForceGCDuringPushOffersSweptObject605=== RUN TestFailedS3DeleteKeepsTombstone606=== PAUSE TestFailedS3DeleteKeepsTombstone607=== RUN TestSweepSkipsRowsLockedByPush608=== PAUSE TestSweepSkipsRowsLockedByPush609=== RUN TestRegisterCompletedObjectNeedsPendingRow610=== PAUSE TestRegisterCompletedObjectNeedsPendingRow611=== RUN TestGetExistingObjectsLocksRows612=== PAUSE TestGetExistingObjectsLocksRows613=== RUN TestSweepRechecksPendingAfterLocking614=== PAUSE TestSweepRechecksPendingAfterLocking615=== RUN TestPushWaitsForSweepHoldingRow616=== PAUSE TestPushWaitsForSweepHoldingRow617=== RUN TestCommitRacingPendingCleanupKeepsObjects618=== PAUSE TestCommitRacingPendingCleanupKeepsObjects619=== RUN TestGCEndsOnShutdown620=== PAUSE TestGCEndsOnShutdown621=== RUN TestGCTaskStore_StartNew622=== PAUSE TestGCTaskStore_StartNew623=== RUN TestGCTaskStore_DeduplicateSameParams624=== PAUSE TestGCTaskStore_DeduplicateSameParams625=== RUN TestGCTaskStore_ConflictDifferentParams626=== PAUSE TestGCTaskStore_ConflictDifferentParams627=== RUN TestGCTaskStore_GetEmpty628=== PAUSE TestGCTaskStore_GetEmpty629=== RUN TestGCTaskStore_GetReturnsLatest630=== PAUSE TestGCTaskStore_GetReturnsLatest631=== RUN TestGCTaskStore_CompletedAllowsNewTask632=== PAUSE TestGCTaskStore_CompletedAllowsNewTask633=== RUN TestGCTaskStore_PhaseUpdates634=== PAUSE TestGCTaskStore_PhaseUpdates635=== RUN TestGCTaskStore_Fail636=== PAUSE TestGCTaskStore_Fail637=== RUN TestGracefulShutdownDrainsInflight638=== PAUSE TestGracefulShutdownDrainsInflight639=== RUN TestService_healthCheckHandler640=== PAUSE TestService_healthCheckHandler641=== RUN TestService_readinessHandler642=== PAUSE TestService_readinessHandler643=== RUN TestGenerateLandingPage644=== PAUSE TestGenerateLandingPage645=== RUN TestCacheConfigHandlerMaxNarSize646=== PAUSE TestCacheConfigHandlerMaxNarSize647=== RUN TestCreatePendingClosureRejectsOversizedNAR648=== PAUSE TestCreatePendingClosureRejectsOversizedNAR649=== RUN TestNARDeduplicationMetadataUploadBug650=== PAUSE TestNARDeduplicationMetadataUploadBug651=== RUN TestMetricsInventory652=== PAUSE TestMetricsInventory653=== RUN TestMetricsCommit654=== PAUSE TestMetricsCommit655=== RUN TestService_NativeMTLS656=== PAUSE TestService_NativeMTLS657=== RUN TestServerTLSConfig658=== PAUSE TestServerTLSConfig659=== RUN TestMultipartCleanup660=== PAUSE TestMultipartCleanup661=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded662=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded663=== RUN TestPendingCleanupUsesOneCutoff664=== PAUSE TestPendingCleanupUsesOneCutoff665=== RUN TestObjectStatsTrigger666=== PAUSE TestObjectStatsTrigger667=== RUN TestObjectStatsUpdatedOncePerCommit668=== PAUSE TestObjectStatsUpdatedOncePerCommit669=== RUN TestOrphanedObjectsGC670=== PAUSE TestOrphanedObjectsGC671=== RUN TestOrphanedObjectsGCStressTest672=== PAUSE TestOrphanedObjectsGCStressTest673=== RUN TestCreatePin_ReservedPins674=== PAUSE TestCreatePin_ReservedPins675=== RUN TestPresentReportsOnlyClosureRoots676=== PAUSE TestPresentReportsOnlyClosureRoots677=== RUN TestPresentRefreshesOnlyStaleClosures678=== PAUSE TestPresentRefreshesOnlyStaleClosures679=== RUN TestPresentNotReportedWhileGCDeletesClosure680=== PAUSE TestPresentNotReportedWhileGCDeletesClosure681=== RUN TestParseSingleRange682=== PAUSE TestParseSingleRange683=== RUN TestProxyHeadersOnlyTrustedOnSocket6842026/10/25 19:06:37 INFO Starting HTTP server address=proxy.sock6852026/10/25 19:06:37 INFO Starting HTTP server address=127.0.0.1:389336862026/10/25 19:06:37 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6872026/10/25 19:06:37 INFO Shutdown signal received, draining in-flight requests timeout=10s688--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)689=== RUN TestIsValidCachePath690=== PAUSE TestIsValidCachePath691=== RUN TestReadProxyNarinfo692=== PAUSE TestReadProxyNarinfo693=== RUN TestReadProxyNarinfoAlreadyDecompressed694=== PAUSE TestReadProxyNarinfoAlreadyDecompressed695=== RUN TestReadProxyContentNegotiation696=== PAUSE TestReadProxyContentNegotiation697=== RUN TestReadProxyNarStreaming698=== PAUSE TestReadProxyNarStreaming699=== RUN TestReadProxy404700=== PAUSE TestReadProxy404701=== RUN TestReadProxyInvalidPath702=== PAUSE TestReadProxyInvalidPath703=== RUN TestReadProxyHead704=== PAUSE TestReadProxyHead705=== RUN TestReadProxyOutlastsServerWriteTimeout706=== PAUSE TestReadProxyOutlastsServerWriteTimeout707=== RUN TestReadProxyConditionalGet708=== PAUSE TestReadProxyConditionalGet709=== RUN TestReadProxyRootRedirectsToIndexHTML710=== PAUSE TestReadProxyRootRedirectsToIndexHTML711=== RUN TestReadProxyDisabled712=== PAUSE TestReadProxyDisabled713=== RUN TestReadRedirectNar714=== PAUSE TestReadRedirectNar715=== RUN TestReadRedirectKeepsNarinfoProxied716=== PAUSE TestReadRedirectKeepsNarinfoProxied717=== RUN TestReadProxyRangeRequest718=== PAUSE TestReadProxyRangeRequest719=== RUN TestReadRedirectUsesPublicS3URL720=== PAUSE TestReadRedirectUsesPublicS3URL721=== RUN TestPush_OverlappingRootsStoreOneRowPerKey722=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey723=== RUN TestPush_CompleteCommitsEveryRoot724=== PAUSE TestPush_CompleteCommitsEveryRoot725=== RUN TestPush_RepeatedRootCommitsOnce726=== PAUSE TestPush_RepeatedRootCommitsOnce727=== RUN TestPush_CompleteWaitsForCleanupOfThePush728=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush729=== RUN TestPush_RootsAreLockedInByteOrder730=== PAUSE TestPush_RootsAreLockedInByteOrder731=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit732=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit733=== RUN TestPush_RejectsBadRequests734=== PAUSE TestPush_RejectsBadRequests735=== RUN TestPush_SignsNarinfosOfItsPendingObjects736=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects737=== RUN TestRedundantMultipartUpload738=== PAUSE TestRedundantMultipartUpload739=== RUN TestCompleteMultipartUpload_ErrorButObjectExists740=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists741=== RUN TestCompletedNarNotReofferedAcrossClosures742=== PAUSE TestCompletedNarNotReofferedAcrossClosures743=== RUN TestPresignedUploadRegisteredBeforeCommit744=== PAUSE TestPresignedUploadRegisteredBeforeCommit745=== RUN TestService_Rustfstest746=== PAUSE TestService_Rustfstest747=== RUN TestParseSize748=== PAUSE TestParseSize749=== RUN TestSkippedUploadsHandler750=== PAUSE TestSkippedUploadsHandler751=== RUN TestSystemdListenerNotActivated752--- PASS: TestSystemdListenerNotActivated (0.00s)753=== RUN TestWatchdogBeatsWhenHealthy754--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)755=== RUN TestWatchdogSkipsWhenUnhealthy7562026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 19:06:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"766--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)767=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle768=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle769=== RUN TestProxyWriteTimeout770=== PAUSE TestProxyWriteTimeout771=== RUN TestPendingClosureWriteTimeout772=== PAUSE TestPendingClosureWriteTimeout773=== RUN TestIsValidUploadKey774=== PAUSE TestIsValidUploadKey775=== RUN TestUploadHandlersRejectInvalidKeys776=== PAUSE TestUploadHandlersRejectInvalidKeys777=== RUN TestUploadHandlersRejectOversizedBody778=== PAUSE TestUploadHandlersRejectOversizedBody779=== RUN TestService_cleanupPendingClosuresHandler780=== PAUSE TestService_cleanupPendingClosuresHandler781=== RUN TestService_createPendingClosureHandler782=== PAUSE TestService_createPendingClosureHandler783=== RUN TestService_verifyS3Integrity784=== PAUSE TestService_verifyS3Integrity785=== RUN TestCompleteMultipartUnregistered786=== PAUSE TestCompleteMultipartUnregistered787=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT788=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT789=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle790=== CONT TestService_AuthMiddleware791=== CONT TestSkippedUploadsHandler792=== CONT TestParseSize793=== CONT TestService_Rustfstest794=== CONT TestPresignedUploadRegisteredBeforeCommit795=== CONT TestGCTaskStore_Fail7962026/10/25 19:06:37 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000797=== CONT TestGetExistingObjectsLocksRows798=== CONT TestGCTaskStore_PhaseUpdates799=== CONT TestPush_RootsAreLockedInByteOrder800=== CONT TestGCTaskStore_CompletedAllowsNewTask801=== CONT TestRegisterCompletedObjectNeedsPendingRow802=== CONT TestGCTaskStore_GetReturnsLatest803=== CONT TestPush_CompleteWaitsForCleanupOfThePush804=== CONT TestGCTaskStore_GetEmpty805=== CONT TestGCTaskStore_ConflictDifferentParams806=== CONT TestPush_RepeatedRootCommitsOnce807=== CONT TestGracefulShutdownDrainsInflight808=== CONT TestGCTaskStore_DeduplicateSameParams809=== CONT TestGCTaskStore_StartNew8102026/10/25 19:06:37 INFO Starting HTTP server address=127.0.0.1:43355811=== CONT TestFailedS3DeleteKeepsTombstone812=== CONT TestPush_CompleteCommitsEveryRoot813=== CONT TestGCEndsOnShutdown814=== RUN TestGCEndsOnShutdown/before_the_run815=== PAUSE TestGCEndsOnShutdown/before_the_run816=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete8172026/10/25 19:06:37 INFO Shutdown signal received, draining in-flight requests timeout=10s818=== CONT TestCompleteMultipartUpload_ErrorButObjectExists819=== CONT TestCommitRacingPendingCleanupKeepsObjects820=== CONT TestRedundantMultipartUpload821=== CONT TestPushWaitsForSweepHoldingRow822=== CONT TestPush_SignsNarinfosOfItsPendingObjects823=== CONT TestSweepRechecksPendingAfterLocking824=== CONT TestPush_RejectsBadRequests825--- PASS: TestParseSize (0.00s)826=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit827=== CONT TestSweepSkipsRowsLockedByPush828=== CONT TestCompletedNarNotReofferedAcrossClosures829=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete830=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark831=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark832--- PASS: TestGCTaskStore_Fail (0.00s)833--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)834--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)835--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)836--- PASS: TestGCTaskStore_GetEmpty (0.00s)837--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)838--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)839--- PASS: TestGCTaskStore_StartNew (0.00s)840=== CONT TestForceGCDuringPushOffersSweptObject841=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows842=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows843=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check844=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check845=== CONT TestPush_OverlappingRootsStoreOneRowPerKey846--- PASS: TestSkippedUploadsHandler (0.01s)847=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection848--- PASS: TestGracefulShutdownDrainsInflight (0.07s)849=== CONT TestReadRedirectUsesPublicS3URL8502026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8512026/10/25 19:06:37 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8522026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures853--- PASS: TestService_Rustfstest (0.29s)854=== CONT TestGCSweepDeliversEachKeyOnce855--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.29s)856=== CONT TestCreatePin_ReservedPins8572026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8582026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes8592026/10/25 19:06:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42343/oidc860--- PASS: TestGetExistingObjectsLocksRows (0.36s)861=== CONT TestTombstonedObjectOfferedWithoutWaiting8622026-10-25 19:06:37.603 UTC [490] ERROR: could not obtain lock on row in relation "closures"8632026-10-25 19:06:37.603 UTC [490] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8642026-10-25 19:06:37.603 UTC [490] ERROR: could not obtain lock on row in relation "closures"8652026-10-25 19:06:37.603 UTC [490] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8662026-10-25 19:06:37.603 UTC [490] ERROR: could not obtain lock on row in relation "closures"8672026-10-25 19:06:37.603 UTC [490] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8682026-10-25 19:06:37.603 UTC [490] ERROR: could not obtain lock on row in relation "closures"8692026-10-25 19:06:37.603 UTC [490] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8702026-10-25 19:06:37.604 UTC [490] ERROR: could not obtain lock on row in relation "closures"8712026-10-25 19:06:37.604 UTC [490] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8722026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes873--- PASS: TestPush_RootsAreLockedInByteOrder (0.37s)874=== CONT TestOrphanedObjectsGCStressTest8752026/10/25 19:06:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8762026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8772026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8782026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8792026/10/25 19:06:37 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"880--- PASS: TestService_AuthMiddleware (0.44s)881=== CONT TestGCSweepSkipsPendingObjects8822026/10/25 19:06:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8832026/10/25 19:06:37 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LmI3NGM0MTQ2LTcxNmUtNDhiNy1hNWZiLTVlMzk3MTQ3OGFjNngxNzkyOTU1MTk3NjU0NjY3MDcz8842026/10/25 19:06:37 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LmI3NGM0MTQ2LTcxNmUtNDhiNy1hNWZiLTVlMzk3MTQ3OGFjNngxNzkyOTU1MTk3NjU0NjY3MDcz parts=18852026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures886--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.46s)887=== CONT TestOrphanedObjectsGC888--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.48s)889=== CONT TestDeduplicatedObjectsRecordedAsPending8902026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8912026/10/25 19:06:37 INFO Aborted multipart uploads count=0 kept=08922026/10/25 19:06:37 INFO Aborted multipart uploads count=0 kept=08932026/10/25 19:06:37 WARN Force mode enabled - objects will be deleted immediately without grace period8942026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures8952026/10/25 19:06:37 WARN Force mode enabled - objects will be deleted immediately without grace period8962026/10/25 19:06:37 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=08972026/10/25 19:06:37 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."8982026/10/25 19:06:37 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."8992026/10/25 19:06:37 INFO Vacuumed table table=pending_closures9002026/10/25 19:06:37 INFO Vacuumed table table=pending_objects9012026/10/25 19:06:37 INFO Vacuumed table table=multipart_uploads9022026/10/25 19:06:37 INFO Vacuumed table table=closures903--- PASS: TestFailedS3DeleteKeepsTombstone (0.56s)904=== CONT TestObjectStatsUpdatedOncePerCommit9052026/10/25 19:06:37 INFO Vacuumed table table=objects9062026/10/25 19:06:37 INFO Aborted multipart uploads count=0 kept=09072026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes9082026/10/25 19:06:37 WARN Force mode enabled - objects will be deleted immediately without grace period9092026/10/25 19:06:37 INFO Received complete push request method=POST path=/api/pushes/1/complete9102026/10/25 19:06:37 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=09112026/10/25 19:06:37 INFO Vacuumed table table=pending_closures9122026/10/25 19:06:37 INFO Vacuumed table table=pending_objects9132026/10/25 19:06:37 INFO Vacuumed table table=multipart_uploads9142026/10/25 19:06:37 INFO Vacuumed table table=closures9152026/10/25 19:06:37 INFO Completed push id=1 objects=4 duration=9.054522ms916--- PASS: TestPush_RepeatedRootCommitsOnce (0.60s)917=== CONT TestPushDedupSurvivesConcurrentGC9182026/10/25 19:06:37 INFO Vacuumed table table=objects919--- PASS: TestSweepSkipsRowsLockedByPush (0.59s)920=== CONT TestObjectStatsTrigger9212026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes9222026/10/25 19:06:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9232026/10/25 19:06:37 INFO Signed narinfos id=1 count=19242026/10/25 19:06:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9252026/10/25 19:06:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9262026/10/25 19:06:37 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9272026/10/25 19:06:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9282026/10/25 19:06:37 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9292026/10/25 19:06:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9302026/10/25 19:06:37 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19312026/10/25 19:06:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9322026/10/25 19:06:37 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo933--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.62s)934=== CONT TestGCMetrics9352026/10/25 19:06:37 INFO Aborted multipart uploads count=0 kept=09362026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes9372026/10/25 19:06:37 WARN Force mode enabled - objects will be deleted immediately without grace period9382026/10/25 19:06:37 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=09392026/10/25 19:06:37 INFO Vacuumed table table=pending_closures9402026/10/25 19:06:37 INFO Vacuumed table table=pending_objects9412026/10/25 19:06:37 INFO Vacuumed table table=multipart_uploads9422026/10/25 19:06:37 INFO Vacuumed table table=closures9432026/10/25 19:06:37 INFO Vacuumed table table=objects9442026/10/25 19:06:37 INFO Received complete push request method=POST path=/api/pushes/1/complete945=== RUN TestPush_RejectsBadRequests/no_roots946=== PAUSE TestPush_RejectsBadRequests/no_roots947=== RUN TestPush_RejectsBadRequests/no_objects948=== PAUSE TestPush_RejectsBadRequests/no_objects949=== RUN TestPush_RejectsBadRequests/bad_root950=== PAUSE TestPush_RejectsBadRequests/bad_root951=== RUN TestPush_RejectsBadRequests/root_not_in_objects952=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects953=== CONT TestPresentReportsOnlyClosureRoots954--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.65s)955=== CONT TestGCBugBareHashReferences9562026/10/25 19:06:37 INFO Completed push id=1 objects=6 duration=9.744368ms957--- PASS: TestPush_CompleteCommitsEveryRoot (0.66s)958=== CONT TestReadProxyRangeRequest9592026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes9602026-10-25 19:06:37.924 UTC [501] ERROR: Push does not exist: id=19612026-10-25 19:06:37.924 UTC [501] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9622026-10-25 19:06:37.924 UTC [501] STATEMENT: SELECT commit_push($1)963--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.69s)964=== CONT TestGCAdvisoryLockBlocksConcurrentRun9652026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures9662026/10/25 19:06:37 INFO Received complete push request method=POST path=/api/pushes/1/complete9672026/10/25 19:06:37 INFO Completed push id=1 objects=4 duration=10.390695ms9682026/10/25 19:06:37 INFO Received push request method=POST path=/api/pushes969--- PASS: TestReadRedirectUsesPublicS3URL (0.66s)970=== CONT TestPendingCleanupUsesOneCutoff971--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.75s)972=== CONT TestLeadEndsOnShutdown9732026/10/25 19:06:37 INFO Aborted multipart uploads count=0 kept=09742026/10/25 19:06:38 INFO Received push request method=POST path=/api/pushes9752026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period9762026/10/25 19:06:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9772026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=09782026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period9792026/10/25 19:06:38 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=0980--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.78s)981=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9822026/10/25 19:06:38 INFO Vacuumed table table=pending_closures9832026/10/25 19:06:38 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=09842026/10/25 19:06:38 INFO Vacuumed table table=pending_objects9852026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads9862026/10/25 19:06:38 INFO Vacuumed table table=closures9872026/10/25 19:06:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LmU0MmY2OTIwLThlN2EtNDg4Zi05MDgxLTU5NTBjN2VkM2U0MHgxNzkyOTU1MTk3NjM0MDY4MzI2 parts=129882026/10/25 19:06:38 INFO Vacuumed table table=pending_closures9892026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures9902026/10/25 19:06:38 INFO Vacuumed table table=objects9912026/10/25 19:06:38 INFO Vacuumed table table=pending_objects992--- PASS: TestSweepRechecksPendingAfterLocking (0.79s)993=== CONT TestLeadIncumbentAnnouncesAtOnce9942026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads9952026/10/25 19:06:38 INFO Vacuumed table table=closures9962026/10/25 19:06:38 INFO Vacuumed table table=objects9972026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures9982026/10/25 19:06:38 INFO Received complete push request method=POST path=/api/pushes/2/complete9992026/10/25 19:06:38 INFO Completed push id=2 objects=4 duration=4.110137ms1000--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.80s)1001=== CONT TestMultipartCleanup10022026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=010032026/10/25 19:06:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10042026/10/25 19:06:38 WARN Refused reserved pin name=worker-x86_64-linux10052026/10/25 19:06:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10062026/10/25 19:06:38 INFO Received create pin request method=POST path=/api/pins/my-app10072026/10/25 19:06:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1008--- PASS: TestCreatePin_ReservedPins (0.53s)1009=== CONT TestLeadElectsOneAndHandsOver10102026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period10112026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1012--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.49s)1013=== CONT TestConnectWaitsForAPeerMigration10142026/10/25 19:06:38 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=010152026/10/25 19:06:38 INFO Vacuumed table table=pending_closures10162026/10/25 19:06:38 INFO Vacuumed table table=pending_objects10172026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads10182026/10/25 19:06:38 INFO Vacuumed table table=closures10192026/10/25 19:06:38 INFO Vacuumed table table=objects1020--- PASS: TestGCSweepDeliversEachKeyOnce (0.58s)1021=== CONT TestServerTLSConfig1022=== RUN TestServerTLSConfig/no_client_CA1023=== PAUSE TestServerTLSConfig/no_client_CA1024=== RUN TestServerTLSConfig/missing_CA_file1025=== PAUSE TestServerTLSConfig/missing_CA_file1026=== RUN TestServerTLSConfig/not_a_PEM_file1027=== PAUSE TestServerTLSConfig/not_a_PEM_file1028=== CONT TestResolveDBConnectionString1029=== RUN TestResolveDBConnectionString/flag_wins1030=== PAUSE TestResolveDBConnectionString/flag_wins1031=== RUN TestResolveDBConnectionString/file_when_flag_empty1032=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1033=== RUN TestResolveDBConnectionString/missing_file_is_an_error1034=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1035=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1036=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1037=== RUN TestResolveDBConnectionString/nothing_configured1038=== PAUSE TestResolveDBConnectionString/nothing_configured1039=== CONT TestService_NativeMTLS10402026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures10412026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=010422026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period10432026/10/25 19:06:38 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=010442026/10/25 19:06:38 INFO Vacuumed table table=pending_closures10452026/10/25 19:06:38 INFO Vacuumed table table=pending_objects10462026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads10472026/10/25 19:06:38 INFO Vacuumed table table=closures10482026/10/25 19:06:38 INFO Vacuumed table table=objects1049--- PASS: TestGCSweepSkipsPendingObjects (0.53s)1050=== CONT TestCacheConfigHandlerMaxNarSize1051--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1052=== CONT TestCreatePendingClosureRejectsOversizedNAR10532026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1054--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1055=== CONT TestGenerateLandingPage1056--- PASS: TestGenerateLandingPage (0.00s)1057=== CONT TestMetricsCommit10582026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1059--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.50s)1060=== CONT TestService_readinessHandler1061--- PASS: TestPushWaitsForSweepHoldingRow (1.01s)1062=== CONT TestMetricsInventory1063--- PASS: TestObjectStatsUpdatedOncePerCommit (0.47s)1064=== CONT TestService_healthCheckHandler10652026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1066--- PASS: TestObjectStatsTrigger (0.47s)1067=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock10682026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=010692026/10/25 19:06:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10702026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period10712026/10/25 19:06:38 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=010722026/10/25 19:06:38 INFO Vacuumed table table=pending_closures10732026/10/25 19:06:38 INFO Vacuumed table table=pending_objects10742026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads10752026/10/25 19:06:38 INFO Vacuumed table table=closures10762026/10/25 19:06:38 INFO Vacuumed table table=objects1077--- PASS: TestGCMetrics (0.47s)1078=== CONT TestNARDeduplicationMetadataUploadBug10792026/10/25 19:06:38 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LmQyMzQ3NjI0LWEwN2EtNDYwZi04ZTJiLWM4ZjgxMWNmMTcxN3gxNzkyOTU1MTk3OTM5MDI5MzM0 parts=1210802026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1081--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.10s)1082=== CONT TestDeleteClosuresRacingPins10832026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=01084--- PASS: TestReadProxyRangeRequest (0.47s)1085=== CONT TestClientFallsBackToClosures10862026/10/25 19:06:38 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=010872026/10/25 19:06:38 INFO Vacuumed table table=pending_closures10882026/10/25 19:06:38 INFO Vacuumed table table=pending_objects10892026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads10902026/10/25 19:06:38 INFO Vacuumed table table=closures10912026/10/25 19:06:38 INFO Vacuumed table table=objects10922026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=010932026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period10942026/10/25 19:06:38 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=010952026/10/25 19:06:38 INFO Vacuumed table table=pending_closures1096--- PASS: TestPresentReportsOnlyClosureRoots (0.51s)1097=== CONT TestReadProxy40410982026/10/25 19:06:38 INFO Vacuumed table table=pending_objects10992026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads11002026/10/25 19:06:38 INFO Vacuumed table table=closures11012026/10/25 19:06:38 INFO Vacuumed table table=objects1102--- PASS: TestPushDedupSurvivesConcurrentGC (0.57s)1103=== CONT TestClientPushesUseOnePush11042026/10/25 19:06:38 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"1105--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.49s)1106=== CONT TestReadRedirectKeepsNarinfoProxied11072026/10/25 19:06:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11082026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures11092026/10/25 19:06:38 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LjRlZWExMjMzLTQ5YzAtNGNlMC05ODI4LWJkYjAwM2Y0YzllYngxNzkyOTU1MTk4MDM4ODAyMjM5 error="Get \"http://127.0.0.1:1/bucket10/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11102026/10/25 19:06:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LjllODc2M2U5LThmODQtNDQzYy1iYmQ5LTEzMWZkNmRkNzBkZHgxNzkyOTU1MTk4MDMxOTk1NzU3 parts=1211112026/10/25 19:06:38 INFO Received cleanup request method=DELETE path=/api/pending_closures11122026/10/25 19:06:38 INFO Aborted multipart uploads count=1 kept=011132026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1114--- PASS: TestRedundantMultipartUpload (1.22s)1115=== CONT TestCacheConfigHandler1116=== RUN TestCacheConfigHandler/full_config,_no_issuer1117=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1118=== RUN TestCacheConfigHandler/no_cache_url_configured1119=== PAUSE TestCacheConfigHandler/no_cache_url_configured1120=== RUN TestCacheConfigHandler/no_signing_keys1121=== PAUSE TestCacheConfigHandler/no_signing_keys1122=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1123=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1124=== CONT TestCacheStatsHandler11252026/10/25 19:06:38 INFO lead: acquired remote=192.0.2.1:123411262026/10/25 19:06:38 INFO Received cleanup request method=DELETE path=/api/pending_closures11272026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1128--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.48s)1129=== CONT TestReadProxyNarStreaming11302026/10/25 19:06:38 INFO lead: acquired remote=192.0.2.1:123411312026/10/25 19:06:38 INFO lead: released remote=192.0.2.1:12341132--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.48s)1133=== CONT TestService_ReadScope_PublicByDefault11342026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures1135=== NAME TestOrphanedObjectsGC1136 orphaned_objects_gc_test.go:287: GC Test Summary:1137 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1138 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1139 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1140 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1141 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1142--- PASS: TestOrphanedObjectsGC (0.84s)1143=== CONT TestReadProxyContentNegotiation1144--- PASS: TestGCBugBareHashReferences (0.66s)1145=== CONT TestService_RequireScope_OIDC11462026/10/25 19:06:38 INFO lead: acquired remote=192.0.2.1:123411472026/10/25 19:06:38 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11482026/10/25 19:06:38 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1149--- PASS: TestService_NativeMTLS (0.47s)1150=== CONT TestReadProxyNarinfoAlreadyDecompressed11512026/10/25 19:06:38 INFO Received push request method=POST path=/api/pushes11522026/10/25 19:06:38 INFO Received complete push request method=POST path=/api/pushes/1/complete11532026/10/25 19:06:38 WARN readiness check failed error="closed pool"1154--- PASS: TestService_readinessHandler (0.40s)1155=== CONT TestPinProtectsFromGC11562026/10/25 19:06:38 INFO Completed push id=1 objects=4 duration=9.186424ms11572026/10/25 19:06:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11582026/10/25 19:06:38 INFO Completed upload id=2 objects=2 duration=1.676956ms1159--- PASS: TestMetricsCommit (0.43s)1160=== CONT TestReadProxyNarinfo11612026/10/25 19:06:38 INFO Received cleanup request method=DELETE path=/api/pending_closures11622026/10/25 19:06:38 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket47/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11632026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=111642026/10/25 19:06:38 INFO Received cleanup request method=DELETE path=/api/pending_closures11652026/10/25 19:06:38 INFO Aborted multipart uploads count=1 kept=01166--- PASS: TestMetricsInventory (0.42s)1167=== CONT TestClientSharedPathCommittedMidPush1168--- PASS: TestMultipartCleanup (0.62s)1169=== CONT TestClientWithDependencies1170--- PASS: TestService_healthCheckHandler (0.40s)1171=== CONT TestIsValidCachePath1172=== RUN TestIsValidCachePath/narinfo1173=== PAUSE TestIsValidCachePath/narinfo1174=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1175=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1176=== RUN TestIsValidCachePath/nar_zst1177=== PAUSE TestIsValidCachePath/nar_zst1178=== RUN TestIsValidCachePath/nar_xz1179=== PAUSE TestIsValidCachePath/nar_xz1180=== RUN TestIsValidCachePath/nar_bz21181=== PAUSE TestIsValidCachePath/nar_bz21182=== RUN TestIsValidCachePath/nar_uncompressed1183=== PAUSE TestIsValidCachePath/nar_uncompressed1184=== RUN TestIsValidCachePath/ls1185=== PAUSE TestIsValidCachePath/ls1186=== RUN TestIsValidCachePath/log1187=== PAUSE TestIsValidCachePath/log1188=== RUN TestIsValidCachePath/realisation1189=== PAUSE TestIsValidCachePath/realisation1190=== RUN TestIsValidCachePath/nix-cache-info1191=== PAUSE TestIsValidCachePath/nix-cache-info1192=== RUN TestIsValidCachePath/index.html1193=== PAUSE TestIsValidCachePath/index.html1194=== RUN TestIsValidCachePath/traversal_parent1195=== PAUSE TestIsValidCachePath/traversal_parent1196=== RUN TestIsValidCachePath/traversal_in_middle1197=== PAUSE TestIsValidCachePath/traversal_in_middle1198=== RUN TestIsValidCachePath/invalid_char_e1199=== PAUSE TestIsValidCachePath/invalid_char_e1200=== RUN TestIsValidCachePath/invalid_char_u1201=== PAUSE TestIsValidCachePath/invalid_char_u1202=== RUN TestIsValidCachePath/random_path1203=== PAUSE TestIsValidCachePath/random_path1204=== RUN TestIsValidCachePath/empty1205=== PAUSE TestIsValidCachePath/empty1206=== RUN TestIsValidCachePath/leading_slash1207=== PAUSE TestIsValidCachePath/leading_slash1208=== RUN TestIsValidCachePath/wrong_extension1209=== PAUSE TestIsValidCachePath/wrong_extension1210=== RUN TestIsValidCachePath/short_hash1211=== PAUSE TestIsValidCachePath/short_hash1212=== CONT TestService_AuthMiddleware_OIDC1213=== NAME TestNARDeduplicationMetadataUploadBug1214 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1957016759/001/store/0r30aw129qb1dfzrs0a7yx5x5a499707-file1.txt12152026/10/25 19:06:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44369/oidc1216--- PASS: TestReadProxy404 (0.42s)1217=== CONT TestClientMultipleUploads12182026/10/25 19:06:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35249/oidc1219--- PASS: TestReadRedirectKeepsNarinfoProxied (0.41s)1220=== CONT TestParseSingleRange1221=== RUN TestParseSingleRange/none1222=== PAUSE TestParseSingleRange/none1223=== RUN TestParseSingleRange/unknown_unit1224=== PAUSE TestParseSingleRange/unknown_unit1225=== RUN TestParseSingleRange/multi-range_ignored1226=== PAUSE TestParseSingleRange/multi-range_ignored1227=== RUN TestParseSingleRange/malformed_no_dash1228=== PAUSE TestParseSingleRange/malformed_no_dash1229=== RUN TestParseSingleRange/malformed_both_empty1230=== PAUSE TestParseSingleRange/malformed_both_empty1231=== RUN TestParseSingleRange/malformed_end_before_start1232=== PAUSE TestParseSingleRange/malformed_end_before_start1233=== RUN TestParseSingleRange/closed1234=== PAUSE TestParseSingleRange/closed1235=== RUN TestParseSingleRange/open-ended1236=== PAUSE TestParseSingleRange/open-ended1237=== RUN TestParseSingleRange/end_clamped_to_size1238=== PAUSE TestParseSingleRange/end_clamped_to_size1239=== RUN TestParseSingleRange/suffix1240=== PAUSE TestParseSingleRange/suffix1241=== RUN TestParseSingleRange/suffix_exceeds_size1242=== PAUSE TestParseSingleRange/suffix_exceeds_size1243=== RUN TestParseSingleRange/single_byte1244=== PAUSE TestParseSingleRange/single_byte1245=== RUN TestParseSingleRange/start_past_EOF1246=== PAUSE TestParseSingleRange/start_past_EOF1247=== RUN TestParseSingleRange/start_far_past_EOF1248=== PAUSE TestParseSingleRange/start_far_past_EOF1249=== CONT TestService_ReadAuthMiddleware12502026/10/25 19:06:38 INFO Received push request method=POST path=/api/pushes12512026/10/25 19:06:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12522026/10/25 19:06:38 INFO Uploading 0r30aw129qb1dfzrs0a7yx5x5a499707-file1.txt (160B)12532026/10/25 19:06:38 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12542026/10/25 19:06:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12552026/10/25 19:06:38 WARN Failed to register uploaded object key=0r30aw129qb1dfzrs0a7yx5x5a499707.ls error="server returned 404: 404 page not found\n"12562026/10/25 19:06:38 INFO Signed narinfos id=1 count=112572026/10/25 19:06:38 INFO Uploading 1 narinfos12582026/10/25 19:06:38 INFO Received complete push request method=POST path=/api/pushes/1/complete12592026/10/25 19:06:38 WARN Failed to register uploaded object key=0r30aw129qb1dfzrs0a7yx5x5a499707.narinfo error="server returned 404: 404 page not found\n"12602026/10/25 19:06:38 INFO Completed push id=1 objects=3 duration=9.406626ms12612026/10/25 19:06:38 INFO Upload complete. (69ms)1262--- PASS: TestCacheStatsHandler (0.41s)1263=== CONT TestClientIntegration1264=== NAME TestNARDeduplicationMetadataUploadBug1265 metadata_upload_test.go:54: Retrieved narinfo from S3:1266 StorePath: /build/TestNARDeduplicationMetadataUploadBug1957016759/001/store/0r30aw129qb1dfzrs0a7yx5x5a499707-file1.txt1267 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1268 Compression: zstd1269 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1270 NarSize: 1601271 References: 1272 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1273 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1274 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1275 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1276--- PASS: TestReadProxyNarStreaming (0.37s)1277=== CONT TestPresentNotReportedWhileGCDeletesClosure1278=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1279=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1280=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1281=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1282=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1283--- PASS: TestService_ReadScope_PublicByDefault (0.38s)1284=== CONT TestClientErrorHandling1285=== RUN TestClientErrorHandling/InvalidStorePath1286=== PAUSE TestClientErrorHandling/InvalidStorePath1287=== RUN TestClientErrorHandling/InvalidAuthToken1288=== PAUSE TestClientErrorHandling/InvalidAuthToken1289=== RUN TestClientErrorHandling/ServerNotAvailable1290=== PAUSE TestClientErrorHandling/ServerNotAvailable1291=== CONT TestPresentRefreshesOnlyStaleClosures1292=== NAME TestNARDeduplicationMetadataUploadBug1293 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1957016759/001/store/vbv0k40mjk07a7balzfh7rxyhfp4ycv0-file2.txt12942026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures12952026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures12962026/10/25 19:06:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12972026/10/25 19:06:38 INFO Uploading w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp-shared-dep (136B)12982026/10/25 19:06:38 INFO Uploading rpxyj4vkshp57w26i8z30k1qn16l5gnz-a (216B)12992026/10/25 19:06:38 WARN Failed to register uploaded object key=fzm9s1h7ngl6zk0z8182rk3dv9sp5hpw.ls error="server returned 404: 404 page not found\n"13002026/10/25 19:06:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13012026/10/25 19:06:38 WARN Failed to register uploaded object key=w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp.ls error="server returned 404: 404 page not found\n"13022026/10/25 19:06:38 WARN Failed to register uploaded object key=rpxyj4vkshp57w26i8z30k1qn16l5gnz.ls error="server returned 404: 404 page not found\n"13032026/10/25 19:06:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13042026/10/25 19:06:38 WARN Failed to register uploaded object key=nar/0b7fkqn73yja3sm5rq2i3z1gjxxpbsj4i4m5r9f9vxwjsndfa6x1.nar.zst error="server returned 404: 404 page not found\n"1305--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.37s)1306=== CONT TestReadRedirectNar13072026/10/25 19:06:38 INFO Signed narinfos id=1 count=213082026/10/25 19:06:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13092026/10/25 19:06:38 INFO Signed narinfos id=2 count=213102026/10/25 19:06:38 INFO Uploading 4 narinfos13112026/10/25 19:06:38 WARN Failed to register uploaded object key=rpxyj4vkshp57w26i8z30k1qn16l5gnz.narinfo error="server returned 404: 404 page not found\n"13122026/10/25 19:06:38 WARN Failed to register uploaded object key=w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp.narinfo error="server returned 404: 404 page not found\n"13132026/10/25 19:06:38 WARN Failed to register uploaded object key=fzm9s1h7ngl6zk0z8182rk3dv9sp5hpw.narinfo error="server returned 404: 404 page not found\n"13142026/10/25 19:06:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13152026/10/25 19:06:38 WARN Failed to register uploaded object key=w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp.narinfo error="server returned 404: 404 page not found\n"1316--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.67s)1317=== CONT TestService_AuthMiddleware_MTLSProxyHeader13182026/10/25 19:06:38 INFO Completed upload id=1 objects=6 duration=5.43975ms13192026/10/25 19:06:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13202026/10/25 19:06:38 INFO Completed upload id=2 objects=6 duration=2.562903ms13212026/10/25 19:06:38 INFO Upload complete. (78ms)1322=== NAME TestClientFallsBackToClosures1323 client_pushes_test.go:112: Retrieved narinfo from S3:1324 StorePath: /build/TestClientFallsBackToClosures270989379/001/store/w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp-shared-dep1325 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1326 Compression: zstd1327 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821328 NarSize: 1361329 References: 1330 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13312026/10/25 19:06:38 INFO Received push request method=POST path=/api/pushes1332 client_pushes_test.go:112: Retrieved narinfo from S3:1333 StorePath: /build/TestClientFallsBackToClosures270989379/001/store/rpxyj4vkshp57w26i8z30k1qn16l5gnz-a1334 URL: nar/0b7fkqn73yja3sm5rq2i3z1gjxxpbsj4i4m5r9f9vxwjsndfa6x1.nar.zst1335 Compression: zstd1336 NarHash: sha256:0b7fkqn73yja3sm5rq2i3z1gjxxpbsj4i4m5r9f9vxwjsndfa6x11337 NarSize: 2161338 References: /build/TestClientFallsBackToClosures270989379/001/store/w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp-shared-dep1339 CA: text:sha256:123194kfnbxnrabkrhqnf6zyn5w4l881nky59vd2l8vzjrm5hwr013402026/10/25 19:06:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13412026/10/25 19:06:38 INFO Received push request method=POST path=/api/pushes1342 client_pushes_test.go:112: Retrieved narinfo from S3:1343 StorePath: /build/TestClientFallsBackToClosures270989379/001/store/fzm9s1h7ngl6zk0z8182rk3dv9sp5hpw-b1344 URL: nar/0b7fkqn73yja3sm5rq2i3z1gjxxpbsj4i4m5r9f9vxwjsndfa6x1.nar.zst1345 Compression: zstd1346 NarHash: sha256:0b7fkqn73yja3sm5rq2i3z1gjxxpbsj4i4m5r9f9vxwjsndfa6x11347 NarSize: 2161348 References: /build/TestClientFallsBackToClosures270989379/001/store/w4sx4lcn2bhcgvzkb4z9vd3lc62rq3zp-shared-dep1349 CA: text:sha256:123194kfnbxnrabkrhqnf6zyn5w4l881nky59vd2l8vzjrm5hwr01350--- PASS: TestClientFallsBackToClosures (0.62s)1351=== CONT TestClientCADerivations13522026/10/25 19:06:38 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13532026/10/25 19:06:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13542026/10/25 19:06:38 INFO Uploading 2428df5qsbakpr86kr1jf83plrydfyqf-shared-dep (136B)13552026/10/25 19:06:38 INFO Uploading qrvdpxg4jjcz4zqygmmmq6cm3pal4p3l-b (208B)13562026/10/25 19:06:38 INFO Signed narinfos id=2 count=113572026/10/25 19:06:38 INFO Uploading 1 narinfos13582026/10/25 19:06:38 WARN Failed to register uploaded object key=vbv0k40mjk07a7balzfh7rxyhfp4ycv0.ls error="server returned 404: 404 page not found\n"1359--- PASS: TestReadProxyContentNegotiation (0.45s)1360=== CONT TestReadProxyOutlastsServerWriteTimeout13612026/10/25 19:06:38 WARN Failed to register uploaded object key=0hjp4v58ks71fpcgijmf2qdhjg9lcav0.ls error="server returned 404: 404 page not found\n"13622026/10/25 19:06:38 WARN Failed to register uploaded object key=qrvdpxg4jjcz4zqygmmmq6cm3pal4p3l.ls error="server returned 404: 404 page not found\n"13632026/10/25 19:06:38 WARN Failed to register uploaded object key=nar/062j1ngj6sji042c551i8inz2bxr4gm0kycpyifbbr8xq9d2frv7.nar.zst error="server returned 404: 404 page not found\n"13642026/10/25 19:06:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13652026/10/25 19:06:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13662026/10/25 19:06:38 WARN Failed to register uploaded object key=2428df5qsbakpr86kr1jf83plrydfyqf.ls error="server returned 404: 404 page not found\n"13672026/10/25 19:06:38 INFO Received complete push request method=POST path=/api/pushes/2/complete13682026/10/25 19:06:38 WARN Failed to register uploaded object key=vbv0k40mjk07a7balzfh7rxyhfp4ycv0.narinfo error="server returned 404: 404 page not found\n"13692026/10/25 19:06:38 INFO Signed narinfos id=1 count=313702026/10/25 19:06:38 INFO Uploading 3 narinfos13712026/10/25 19:06:38 INFO Completed push id=2 objects=3 duration=2.842865ms13722026/10/25 19:06:38 INFO Upload complete. (58ms)1373=== NAME TestNARDeduplicationMetadataUploadBug1374 metadata_upload_test.go:76: Retrieved narinfo from S3:1375 StorePath: /build/TestNARDeduplicationMetadataUploadBug1957016759/001/store/vbv0k40mjk07a7balzfh7rxyhfp4ycv0-file2.txt1376 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1377 Compression: zstd1378 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1379 NarSize: 1601380 References: 1381 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13822026/10/25 19:06:38 WARN Failed to register uploaded object key=qrvdpxg4jjcz4zqygmmmq6cm3pal4p3l.narinfo error="server returned 404: 404 page not found\n"13832026/10/25 19:06:38 INFO Received complete push request method=POST path=/api/pushes/1/complete13842026/10/25 19:06:38 WARN Failed to register uploaded object key=0hjp4v58ks71fpcgijmf2qdhjg9lcav0.narinfo error="server returned 404: 404 page not found\n"13852026/10/25 19:06:38 WARN Failed to register uploaded object key=2428df5qsbakpr86kr1jf83plrydfyqf.narinfo error="server returned 404: 404 page not found\n"1386 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1387 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1388 {"version":1,"root":{"type":"regular","size":44}}1389--- PASS: TestNARDeduplicationMetadataUploadBug (0.67s)1390=== CONT TestReadProxyConditionalGet13912026/10/25 19:06:39 INFO Completed push id=1 objects=8 duration=7.004763ms13922026/10/25 19:06:39 INFO Upload complete. (65ms)1393=== NAME TestClientPushesUseOnePush1394 client_pushes_test.go:97: Retrieved narinfo from S3:1395 StorePath: /build/TestClientPushesUseOnePush432748600/001/store/2428df5qsbakpr86kr1jf83plrydfyqf-shared-dep1396 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1397 Compression: zstd1398 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821399 NarSize: 1361400 References: 1401 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1402 client_pushes_test.go:97: Retrieved narinfo from S3:1403 StorePath: /build/TestClientPushesUseOnePush432748600/001/store/0hjp4v58ks71fpcgijmf2qdhjg9lcav0-a1404 URL: nar/062j1ngj6sji042c551i8inz2bxr4gm0kycpyifbbr8xq9d2frv7.nar.zst1405 Compression: zstd1406 NarHash: sha256:062j1ngj6sji042c551i8inz2bxr4gm0kycpyifbbr8xq9d2frv71407 NarSize: 2081408 References: /build/TestClientPushesUseOnePush432748600/001/store/2428df5qsbakpr86kr1jf83plrydfyqf-shared-dep1409 CA: text:sha256:17f0z2xzaapmg4c279yfzan2vwa12q74rgfis2gib68hhspcn9dy1410 client_pushes_test.go:97: Retrieved narinfo from S3:1411 StorePath: /build/TestClientPushesUseOnePush432748600/001/store/qrvdpxg4jjcz4zqygmmmq6cm3pal4p3l-b1412 URL: nar/062j1ngj6sji042c551i8inz2bxr4gm0kycpyifbbr8xq9d2frv7.nar.zst1413 Compression: zstd1414 NarHash: sha256:062j1ngj6sji042c551i8inz2bxr4gm0kycpyifbbr8xq9d2frv71415 NarSize: 2081416 References: /build/TestClientPushesUseOnePush432748600/001/store/2428df5qsbakpr86kr1jf83plrydfyqf-shared-dep1417 CA: text:sha256:17f0z2xzaapmg4c279yfzan2vwa12q74rgfis2gib68hhspcn9dy1418--- PASS: TestClientPushesUseOnePush (0.62s)1419=== CONT TestService_cleanupPendingClosuresHandler1420=== NAME TestPinProtectsFromGC1421 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC575394191/001/store/mwvcdwy3jdbbyaqy5q23dqbiqwwmlb63-pinned-file.txt1422 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC575394191/001/store/87fdhf0fc5igj5vl0lqaqnbdr3dm00j1-unpinned-file.txt1423=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1424=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1425=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1426=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1427=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1428=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1429=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1430=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1431=== CONT TestCompleteMultipartUnregistered14322026/10/25 19:06:39 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1433--- PASS: TestReadProxyNarinfo (0.44s)1434=== CONT TestReadProxyDisabled14352026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes1436=== NAME TestClientMultipleUploads1437 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads8996658/001/store/z6bixlwg34m3h681ckq4skmy7s2gxqnh-test-file-0.txt1438=== NAME TestClientWithDependencies1439 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1192176924/001/store/xb11kdwgvpg4kqrfv0w4adrpqph8px0f-test-script14402026/10/25 19:06:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14412026/10/25 19:06:39 INFO Uploading mwvcdwy3jdbbyaqy5q23dqbiqwwmlb63-pinned-file.txt (128B)1442=== RUN TestService_RequireScope_OIDC/builder_may_write1443=== PAUSE TestService_RequireScope_OIDC/builder_may_write1444=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1445=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1446=== RUN TestService_RequireScope_OIDC/ops_may_admin1447=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1448=== RUN TestService_RequireScope_OIDC/ops_may_not_write1449=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1450=== RUN TestService_RequireScope_OIDC/reader_may_not_write1451--- PASS: TestService_ReadAuthMiddleware (0.32s)1452=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT14532026/10/25 19:06:39 WARN Failed to register uploaded object key=mwvcdwy3jdbbyaqy5q23dqbiqwwmlb63.ls error="server returned 404: 404 page not found\n"14542026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1455=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1456=== RUN TestService_RequireScope_OIDC/static_token_may_admin1457=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1458=== RUN TestService_RequireScope_OIDC/static_token_may_write1459=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1460=== RUN TestService_RequireScope_OIDC/reader_may_read1461=== PAUSE TestService_RequireScope_OIDC/reader_may_read1462=== RUN TestService_RequireScope_OIDC/writer_implies_read1463=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1464=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1465=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1466=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1467=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1468=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1469=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1470=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read14712026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"1472=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1473=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1474=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1475=== CONT TestReadProxyRootRedirectsToIndexHTML14762026/10/25 19:06:39 INFO Signed narinfos id=1 count=114772026/10/25 19:06:39 INFO Uploading 1 narinfos14782026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/1/complete14792026/10/25 19:06:39 WARN Failed to register uploaded object key=mwvcdwy3jdbbyaqy5q23dqbiqwwmlb63.narinfo error="server returned 404: 404 page not found\n"1480=== NAME TestClientWithDependencies1481 client_integration_test.go:615: Found 1 dependencies (including self)14822026/10/25 19:06:39 INFO Completed push id=1 objects=3 duration=12.227191ms14832026/10/25 19:06:39 INFO Upload complete. (85ms)1484=== NAME TestClientMultipleUploads1485 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads8996658/001/store/vfyp1hpd43dnrfbpj88sxax3imirx618-test-file-1.txt14862026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes14872026/10/25 19:06:39 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14882026/10/25 19:06:39 INFO Uploading 2vcac73ikw08gi019j83ccykjiafs63d-shared-dep (136B)14892026/10/25 19:06:39 INFO Uploading c6dnqcwmwjdkliflav015n8aj1ia4wcb-top (224B)14902026/10/25 19:06:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14912026/10/25 19:06:39 WARN mTLS auth: bound subjects configured but subject DN unavailable14922026/10/25 19:06:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1493--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.33s)1494=== CONT TestService_createPendingClosureHandler14952026/10/25 19:06:39 WARN Failed to register uploaded object key=2vcac73ikw08gi019j83ccykjiafs63d.ls error="server returned 404: 404 page not found\n"14962026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/02qj73brkaak6i8mnyfaxb6169y17b41nsygbnkidy6nmm91dfrs.nar.zst error="server returned 404: 404 page not found\n"14972026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14982026/10/25 19:06:39 WARN Failed to register uploaded object key=c6dnqcwmwjdkliflav015n8aj1ia4wcb.ls error="server returned 404: 404 page not found\n"14992026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15002026/10/25 19:06:39 INFO Signed narinfos id=1 count=215012026/10/25 19:06:39 INFO Uploading 2 narinfos15022026/10/25 19:06:39 WARN Failed to register uploaded object key=c6dnqcwmwjdkliflav015n8aj1ia4wcb.narinfo error="server returned 404: 404 page not found\n"15032026/10/25 19:06:39 WARN Failed to register uploaded object key=2vcac73ikw08gi019j83ccykjiafs63d.narinfo error="server returned 404: 404 page not found\n"15042026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15052026/10/25 19:06:39 INFO Completed push id=1 objects=6 duration=7.225885ms15062026/10/25 19:06:39 INFO Upload complete. (81ms)1507=== NAME TestClientSharedPathCommittedMidPush1508 client_integration_test.go:680: Retrieved narinfo from S3:1509 StorePath: /build/TestClientSharedPathCommittedMidPush849590977/001/store/2vcac73ikw08gi019j83ccykjiafs63d-shared-dep1510 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1511 Compression: zstd1512 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821513 NarSize: 1361514 References: 1515 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1516=== NAME TestClientMultipleUploads1517 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads8996658/001/store/kdabvp6i04n0wkj8ls6jb59izq78wr16-test-file-2.txt1518=== NAME TestClientSharedPathCommittedMidPush1519 client_integration_test.go:680: Retrieved narinfo from S3:1520 StorePath: /build/TestClientSharedPathCommittedMidPush849590977/001/store/c6dnqcwmwjdkliflav015n8aj1ia4wcb-top1521 URL: nar/02qj73brkaak6i8mnyfaxb6169y17b41nsygbnkidy6nmm91dfrs.nar.zst1522 Compression: zstd1523 NarHash: sha256:02qj73brkaak6i8mnyfaxb6169y17b41nsygbnkidy6nmm91dfrs1524 NarSize: 2241525 References: /build/TestClientSharedPathCommittedMidPush849590977/001/store/2vcac73ikw08gi019j83ccykjiafs63d-shared-dep1526 CA: text:sha256:0zg320j2nh2rbi987g5pdy80bjcsil26ajcw8xahkl3kc815b30k1527--- PASS: TestClientSharedPathCommittedMidPush (0.57s)1528=== CONT TestService_verifyS3Integrity15292026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes15302026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes15312026/10/25 19:06:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15322026/10/25 19:06:39 INFO Uploading 87fdhf0fc5igj5vl0lqaqnbdr3dm00j1-unpinned-file.txt (128B)15332026/10/25 19:06:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15342026/10/25 19:06:39 INFO Uploading xb11kdwgvpg4kqrfv0w4adrpqph8px0f-test-script (136B)15352026/10/25 19:06:39 WARN Failed to register uploaded object key=87fdhf0fc5igj5vl0lqaqnbdr3dm00j1.ls error="server returned 404: 404 page not found\n"15362026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15372026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15382026/10/25 19:06:39 INFO Signed narinfos id=2 count=115392026/10/25 19:06:39 INFO Uploading 1 narinfos15402026/10/25 19:06:39 WARN Failed to register uploaded object key=xb11kdwgvpg4kqrfv0w4adrpqph8px0f.ls error="server returned 404: 404 page not found\n"15412026/10/25 19:06:39 WARN Failed to register uploaded object key=log/s6ffns5cwplj4n3wp8bzy8qhzb77g5im-test-script.drv error="server returned 404: 404 page not found\n"15422026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15432026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15442026/10/25 19:06:39 INFO Signed narinfos id=1 count=115452026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/2/complete15462026/10/25 19:06:39 WARN Failed to register uploaded object key=87fdhf0fc5igj5vl0lqaqnbdr3dm00j1.narinfo error="server returned 404: 404 page not found\n"15472026/10/25 19:06:39 INFO Uploading 1 narinfos15482026/10/25 19:06:39 INFO Completed push id=2 objects=3 duration=3.521612ms15492026/10/25 19:06:39 INFO Upload complete. (56ms)15502026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15512026/10/25 19:06:39 WARN Failed to register uploaded object key=xb11kdwgvpg4kqrfv0w4adrpqph8px0f.narinfo error="server returned 404: 404 page not found\n"1552--- PASS: TestPresentRefreshesOnlyStaleClosures (0.38s)1553=== CONT TestReadProxyInvalidPath15542026/10/25 19:06:39 INFO Completed push id=1 objects=4 duration=7.182565ms15552026/10/25 19:06:39 INFO Upload complete. (65ms)1556=== NAME TestClientIntegration1557 client_integration_test.go:286: Created store path: /build/TestClientIntegration1091036429/002/store/i5w2z6lwvcgh80b3f90ifw6vsk0l0882-test-file.txt1558=== NAME TestClientWithDependencies1559 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1192176924/001/store) requires matching store prefix1560--- PASS: TestClientWithDependencies (0.61s)1561=== CONT TestUploadHandlersRejectInvalidKeys1562=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1563=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1564=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1565=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1566=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1567=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1568=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1569=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1570=== CONT TestIsValidUploadKey1571=== RUN TestIsValidUploadKey/narinfo1572=== PAUSE TestIsValidUploadKey/narinfo1573=== RUN TestIsValidUploadKey/nar_zst1574=== PAUSE TestIsValidUploadKey/nar_zst1575=== RUN TestIsValidUploadKey/nar_xz1576=== PAUSE TestIsValidUploadKey/nar_xz1577=== RUN TestIsValidUploadKey/nar_plain1578=== PAUSE TestIsValidUploadKey/nar_plain1579=== RUN TestIsValidUploadKey/listing1580=== PAUSE TestIsValidUploadKey/listing1581=== RUN TestIsValidUploadKey/build_log1582=== PAUSE TestIsValidUploadKey/build_log1583=== RUN TestIsValidUploadKey/build_log_home-manager_file1584=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1585=== RUN TestIsValidUploadKey/build_log_plus_in_name1586=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1587=== RUN TestIsValidUploadKey/build_log_question_mark1588=== PAUSE TestIsValidUploadKey/build_log_question_mark1589=== RUN TestIsValidUploadKey/build_log_equals1590=== PAUSE TestIsValidUploadKey/build_log_equals1591=== RUN TestIsValidUploadKey/realisation1592=== PAUSE TestIsValidUploadKey/realisation1593=== RUN TestIsValidUploadKey/realisation_plus_in_output1594=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1595=== RUN TestIsValidUploadKey/nix-cache-info1596=== PAUSE TestIsValidUploadKey/nix-cache-info1597=== RUN TestIsValidUploadKey/index.html1598=== PAUSE TestIsValidUploadKey/index.html1599=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1600=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1601=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1602=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1603=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1604=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1605=== RUN TestIsValidUploadKey/traversal1606=== PAUSE TestIsValidUploadKey/traversal1607=== RUN TestIsValidUploadKey/traversal_nar1608=== PAUSE TestIsValidUploadKey/traversal_nar1609=== RUN TestIsValidUploadKey/absolute1610=== PAUSE TestIsValidUploadKey/absolute1611=== RUN TestIsValidUploadKey/empty_key1612=== PAUSE TestIsValidUploadKey/empty_key1613=== RUN TestIsValidUploadKey/unknown_type1614=== PAUSE TestIsValidUploadKey/unknown_type1615=== CONT TestPendingClosureWriteTimeout1616=== RUN TestPendingClosureWriteTimeout/empty1617=== PAUSE TestPendingClosureWriteTimeout/empty1618=== RUN TestPendingClosureWriteTimeout/400_objects1619=== PAUSE TestPendingClosureWriteTimeout/400_objects1620=== RUN TestPendingClosureWriteTimeout/670k_objects1621=== PAUSE TestPendingClosureWriteTimeout/670k_objects1622=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1623=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1624=== CONT TestProxyWriteTimeout1625=== RUN TestProxyWriteTimeout/narinfo1626=== PAUSE TestProxyWriteTimeout/narinfo1627=== RUN TestProxyWriteTimeout/1_GiB_nar1628=== PAUSE TestProxyWriteTimeout/1_GiB_nar1629=== RUN TestProxyWriteTimeout/10_GiB_nar1630=== PAUSE TestProxyWriteTimeout/10_GiB_nar1631=== RUN TestProxyWriteTimeout/unknown_size1632=== PAUSE TestProxyWriteTimeout/unknown_size1633=== CONT TestUploadHandlersRejectOversizedBody1634--- PASS: TestReadRedirectNar (0.33s)1635=== CONT TestReadProxyHead16362026/10/25 19:06:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures16372026/10/25 19:06:39 INFO Garbage collection started16382026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes1639--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.34s)1640=== CONT TestGCEndsOnShutdown/before_the_run16412026/10/25 19:06:39 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16422026/10/25 19:06:39 INFO Uploading z6bixlwg34m3h681ckq4skmy7s2gxqnh-test-file-0.txt (160B)16432026/10/25 19:06:39 INFO Uploading vfyp1hpd43dnrfbpj88sxax3imirx618-test-file-1.txt (160B)16442026/10/25 19:06:39 INFO Uploading kdabvp6i04n0wkj8ls6jb59izq78wr16-test-file-2.txt (160B)16452026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=016462026/10/25 19:06:39 WARN Failed to register uploaded object key=kdabvp6i04n0wkj8ls6jb59izq78wr16.ls error="server returned 404: 404 page not found\n"16472026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16482026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16492026/10/25 19:06:39 WARN Failed to register uploaded object key=vfyp1hpd43dnrfbpj88sxax3imirx618.ls error="server returned 404: 404 page not found\n"16502026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16512026/10/25 19:06:39 WARN Failed to register uploaded object key=z6bixlwg34m3h681ckq4skmy7s2gxqnh.ls error="server returned 404: 404 page not found\n"16522026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16532026/10/25 19:06:39 INFO Signed narinfos id=1 count=316542026/10/25 19:06:39 INFO Uploading 3 narinfos16552026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period16562026/10/25 19:06:39 WARN Failed to register uploaded object key=vfyp1hpd43dnrfbpj88sxax3imirx618.narinfo error="server returned 404: 404 page not found\n"16572026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/1/complete16582026/10/25 19:06:39 WARN Failed to register uploaded object key=z6bixlwg34m3h681ckq4skmy7s2gxqnh.narinfo error="server returned 404: 404 page not found\n"16592026/10/25 19:06:39 WARN Failed to register uploaded object key=kdabvp6i04n0wkj8ls6jb59izq78wr16.narinfo error="server returned 404: 404 page not found\n"16602026/10/25 19:06:39 INFO Completed push id=1 objects=9 duration=35.634323ms16612026/10/25 19:06:39 INFO Upload complete. (100ms)1662=== NAME TestClientMultipleUploads1663 client_integration_test.go:369: Uploaded 3 paths in 134.814543ms16642026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes16652026/10/25 19:06:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16662026/10/25 19:06:39 INFO Uploading i5w2z6lwvcgh80b3f90ifw6vsk0l0882-test-file.txt (152B)1667--- PASS: TestClientMultipleUploads (0.55s)1668=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows16692026/10/25 19:06:39 WARN Failed to register uploaded object key=i5w2z6lwvcgh80b3f90ifw6vsk0l0882.ls error="server returned 404: 404 page not found\n"16702026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16712026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16722026/10/25 19:06:39 INFO Signed narinfos id=1 count=116732026/10/25 19:06:39 INFO Uploading 1 narinfos16742026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/1/complete16752026/10/25 19:06:39 WARN Failed to register uploaded object key=i5w2z6lwvcgh80b3f90ifw6vsk0l0882.narinfo error="server returned 404: 404 page not found\n"16762026/10/25 19:06:39 INFO Completed push id=1 objects=3 duration=6.940683ms16772026/10/25 19:06:39 INFO Upload complete. (83ms)16782026/10/25 19:06:39 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=016792026/10/25 19:06:39 INFO Vacuumed table table=pending_closures16802026/10/25 19:06:39 INFO Vacuumed table table=pending_objects16812026/10/25 19:06:39 INFO Vacuumed table table=multipart_uploads16822026/10/25 19:06:39 INFO Vacuumed table table=closures16832026/10/25 19:06:39 INFO Vacuumed table table=objects16842026/10/25 19:06:39 INFO All 1 paths already cached1685=== NAME TestClientIntegration1686 client_integration_test.go:312: Retrieved narinfo from S3:1687 StorePath: /build/TestClientIntegration1091036429/002/store/i5w2z6lwvcgh80b3f90ifw6vsk0l0882-test-file.txt1688 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1689 Compression: zstd1690 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11691 NarSize: 1521692 References: 1693 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11694 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1695 client_integration_test.go:313: Decompressed .ls content (64 bytes):1696 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1697 client_integration_test.go:316: Testing garbage collection...16982026/10/25 19:06:39 INFO Received cleanup request method=DELETE path=/api/pending_closures1699--- PASS: TestReadProxyConditionalGet (0.43s)1700=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17012026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=017022026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures17032026/10/25 19:06:39 INFO Received cleanup request method=DELETE path=/api/pending_closures17042026/10/25 19:06:39 INFO Aborted multipart uploads count=1 kept=017052026/10/25 19:06:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17062026-10-25 19:06:39.446 UTC [1088] ERROR: Closure does not exist: id=117072026-10-25 19:06:39.446 UTC [1088] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE17082026-10-25 19:06:39.446 UTC [1088] STATEMENT: -- name: CommitPendingClosure :one1709 SELECT commit_pending_closure($1::bigint)::bigint1710 1711--- PASS: TestService_cleanupPendingClosuresHandler (0.43s)1712=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17132026/10/25 19:06:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1714=== NAME TestClientCADerivations1715 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1837379835/001/store/8ir90r8q26n4pwkxzjffjv68sya846ld-ca-test17162026/10/25 19:06:39 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1717--- PASS: TestCompleteMultipartUnregistered (0.38s)1718=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1719=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1720=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1721=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1722=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1723=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1724=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1725=== CONT TestPush_RejectsBadRequests/no_roots17262026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes1727=== CONT TestPush_RejectsBadRequests/bad_root17282026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes1729=== CONT TestPush_RejectsBadRequests/root_not_in_objects17302026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes1731=== CONT TestPush_RejectsBadRequests/no_objects17322026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes1733=== CONT TestServerTLSConfig/no_client_CA1734=== CONT TestServerTLSConfig/not_a_PEM_file1735--- PASS: TestPush_RejectsBadRequests (0.65s)1736 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1737 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1738 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1739 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1740=== CONT TestServerTLSConfig/missing_CA_file1741--- PASS: TestServerTLSConfig (0.00s)1742 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1743 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1744 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1745=== CONT TestResolveDBConnectionString/flag_wins1746=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1747=== CONT TestResolveDBConnectionString/missing_file_is_an_error1748=== CONT TestResolveDBConnectionString/file_when_flag_empty1749=== CONT TestResolveDBConnectionString/nothing_configured1750=== CONT TestCacheConfigHandler/full_config,_no_issuer1751=== CONT TestCacheConfigHandler/no_signing_keys1752=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1753=== CONT TestCacheConfigHandler/no_cache_url_configured1754=== CONT TestIsValidCachePath/narinfo1755=== CONT TestIsValidCachePath/index.html1756=== CONT TestIsValidCachePath/short_hash1757=== CONT TestIsValidCachePath/wrong_extension1758=== CONT TestIsValidCachePath/leading_slash1759=== CONT TestIsValidCachePath/empty1760=== CONT TestIsValidCachePath/traversal_in_middle1761=== CONT TestIsValidCachePath/traversal_parent1762=== CONT TestIsValidCachePath/nar_uncompressed1763=== CONT TestIsValidCachePath/nix-cache-info1764=== CONT TestIsValidCachePath/realisation1765=== CONT TestIsValidCachePath/invalid_char_e1766--- PASS: TestResolveDBConnectionString (0.00s)1767 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1768 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1769 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1770 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1771 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1772=== CONT TestIsValidCachePath/random_path1773=== CONT TestIsValidCachePath/invalid_char_u1774=== CONT TestIsValidCachePath/ls1775=== CONT TestIsValidCachePath/nar_xz1776=== CONT TestIsValidCachePath/nar_bz21777=== CONT TestIsValidCachePath/nar_zst1778=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1779=== CONT TestIsValidCachePath/log1780=== CONT TestParseSingleRange/none1781=== CONT TestParseSingleRange/open-ended1782--- PASS: TestCacheConfigHandler (0.00s)1783 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1784 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1785 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1786 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1787=== CONT TestParseSingleRange/start_far_past_EOF1788=== CONT TestParseSingleRange/start_past_EOF1789=== CONT TestParseSingleRange/single_byte1790=== CONT TestParseSingleRange/suffix_exceeds_size1791=== CONT TestParseSingleRange/suffix1792--- PASS: TestIsValidCachePath (0.00s)1793 --- PASS: TestIsValidCachePath/narinfo (0.00s)1794 --- PASS: TestIsValidCachePath/index.html (0.00s)1795 --- PASS: TestIsValidCachePath/short_hash (0.00s)1796 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1797 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1798 --- PASS: TestIsValidCachePath/empty (0.00s)1799 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1800 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1801 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1802 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1803 --- PASS: TestIsValidCachePath/realisation (0.00s)1804 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1805 --- PASS: TestIsValidCachePath/random_path (0.00s)1806 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1807 --- PASS: TestIsValidCachePath/ls (0.00s)1808 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1809 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1810 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1811 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1812 --- PASS: TestIsValidCachePath/log (0.00s)1813=== CONT TestParseSingleRange/end_clamped_to_size1814=== CONT TestParseSingleRange/malformed_both_empty1815=== CONT TestParseSingleRange/closed1816=== CONT TestParseSingleRange/malformed_end_before_start1817=== CONT TestParseSingleRange/multi-range_ignored1818=== CONT TestParseSingleRange/malformed_no_dash1819=== CONT TestParseSingleRange/unknown_unit1820--- PASS: TestParseSingleRange (0.00s)1821 --- PASS: TestParseSingleRange/none (0.00s)1822 --- PASS: TestParseSingleRange/open-ended (0.00s)1823 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1824 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1825 --- PASS: TestParseSingleRange/single_byte (0.00s)1826 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1827 --- PASS: TestParseSingleRange/suffix (0.00s)1828 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1829 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1830 --- PASS: TestParseSingleRange/closed (0.00s)1831 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1832 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1833 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1834 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1835=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18362026/10/25 19:06:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures18372026/10/25 19:06:39 INFO Garbage collection started1838--- PASS: TestReadProxyDisabled (0.40s)1839=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18402026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=01841=== NAME TestClientCADerivations1842 client_ca_test.go:139: Found 1 dependencies (including self)18432026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period18442026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures18452026/10/25 19:06:39 INFO lead: released remote=192.0.2.1:12341846--- PASS: TestLeadEndsOnShutdown (1.52s)1847=== CONT TestClientErrorHandling/InvalidStorePath1848--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.37s)1849=== CONT TestClientErrorHandling/ServerNotAvailable18502026/10/25 19:06:39 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=018512026/10/25 19:06:39 INFO Vacuumed table table=pending_closures1852--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.38s)1853=== CONT TestClientErrorHandling/InvalidAuthToken18542026/10/25 19:06:39 INFO Vacuumed table table=pending_objects18552026/10/25 19:06:39 INFO Vacuumed table table=multipart_uploads18562026/10/25 19:06:39 INFO Vacuumed table table=closures18572026/10/25 19:06:39 INFO Vacuumed table table=objects18582026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures18592026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures18602026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures18612026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures18622026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes18632026/10/25 19:06:39 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/present18642026/10/25 19:06:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18652026/10/25 19:06:39 INFO Uploading 8ir90r8q26n4pwkxzjffjv68sya846ld-ca-test (144B)1866--- PASS: TestReadProxyInvalidPath (0.34s)1867=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token18682026/10/25 19:06:39 WARN Failed to register uploaded object key=8ir90r8q26n4pwkxzjffjv68sya846ld.ls error="server returned 404: 404 page not found\n"18692026/10/25 19:06:39 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18702026/10/25 19:06:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18712026/10/25 19:06:39 WARN Failed to register uploaded object key=log/03g11p0rbwcf5pq95jvf7ana0iynwzxi-ca-test.drv error="server returned 404: 404 page not found\n"18722026/10/25 19:06:39 INFO Signed narinfos id=1 count=118732026/10/25 19:06:39 INFO Uploading 1 narinfos1874=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18752026/10/25 19:06:39 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]1876=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1877=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18782026/10/25 19:06:39 WARN Authentication failed token_preview=eyJhbGciOi...PYx_I2-7Bw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1879=== CONT TestService_RequireScope_OIDC/builder_may_write1880--- PASS: TestService_AuthMiddleware_OIDC (0.40s)1881 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1882 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1883 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1884 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)18852026/10/25 19:06:39 INFO Received complete push request method=POST path=/api/pushes/1/complete1886=== CONT TestService_RequireScope_OIDC/reader_may_read18872026/10/25 19:06:39 WARN Failed to register uploaded object key=8ir90r8q26n4pwkxzjffjv68sya846ld.narinfo error="server returned 404: 404 page not found\n"1888=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1889=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read18902026/10/25 19:06:39 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]1891=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1892=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1893=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1894=== CONT TestService_RequireScope_OIDC/writer_implies_read1895=== CONT TestService_RequireScope_OIDC/static_token_may_write1896=== CONT TestService_RequireScope_OIDC/ops_may_admin1897=== CONT TestService_RequireScope_OIDC/ops_may_not_write1898=== CONT TestService_RequireScope_OIDC/reader_may_not_write1899=== CONT TestService_RequireScope_OIDC/static_token_may_admin1900=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1901=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19022026/10/25 19:06:39 INFO Received uploads request method=POST path=/1903=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19042026/10/25 19:06:39 INFO Received complete multipart upload request method=POST path=/1905=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19062026/10/25 19:06:39 INFO Received request for more parts method=POST path=/1907=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19082026/10/25 19:06:39 INFO Received uploads request method=POST path=/1909--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1910 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1911 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1912 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1913 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1914--- PASS: TestService_RequireScope_OIDC (0.59s)1915 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1916 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1917 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1918 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1919 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1920 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1921 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1922 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1923 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1924 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1925 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1926 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1927 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1928 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1929=== CONT TestIsValidUploadKey/narinfo1930=== CONT TestIsValidUploadKey/realisation_plus_in_output1931=== CONT TestIsValidUploadKey/unknown_type1932=== CONT TestIsValidUploadKey/empty_key1933=== CONT TestIsValidUploadKey/absolute1934=== CONT TestIsValidUploadKey/traversal_nar1935=== CONT TestIsValidUploadKey/traversal1936=== CONT TestIsValidUploadKey/index.html1937=== CONT TestIsValidUploadKey/nix-cache-info1938=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1939=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1940=== CONT TestIsValidUploadKey/build_log_home-manager_file1941=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1942=== CONT TestIsValidUploadKey/realisation1943=== CONT TestIsValidUploadKey/build_log_equals1944=== CONT TestIsValidUploadKey/nar_plain1945=== CONT TestIsValidUploadKey/build_log_question_mark1946=== CONT TestIsValidUploadKey/build_log1947=== CONT TestIsValidUploadKey/build_log_plus_in_name1948=== CONT TestIsValidUploadKey/listing1949=== CONT TestIsValidUploadKey/nar_xz1950=== CONT TestIsValidUploadKey/nar_zst1951=== CONT TestPendingClosureWriteTimeout/empty1952=== CONT TestPendingClosureWriteTimeout/670k_objects1953=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1954--- PASS: TestIsValidUploadKey (0.00s)1955 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1956 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1957 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1958 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1959 --- PASS: TestIsValidUploadKey/absolute (0.00s)1960 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1961 --- PASS: TestIsValidUploadKey/traversal (0.00s)1962 --- PASS: TestIsValidUploadKey/index.html (0.00s)1963 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1964 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1965 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1966 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1967 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1968 --- PASS: TestIsValidUploadKey/realisation (0.00s)1969 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1970 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1971 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1972 --- PASS: TestIsValidUploadKey/build_log (0.00s)1973 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1974 --- PASS: TestIsValidUploadKey/listing (0.00s)1975 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1976 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)19772026/10/25 19:06:39 INFO Completed push id=1 objects=4 duration=4.735363ms19782026/10/25 19:06:39 INFO Upload complete. (98ms)1979=== NAME TestClientCADerivations1980 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1837379835/001/store/8ir90r8q26n4pwkxzjffjv68sya846ld-ca-test1981 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1982 Compression: zstd1983 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1984 NarSize: 1441985 References: 1986 Deriver: /build/TestClientCADerivations1837379835/001/store/03g11p0rbwcf5pq95jvf7ana0iynwzxi-ca-test.drv1987 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1988 client_ca_test.go:185: Checking for realisation files in S3...1989 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1990 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1991--- PASS: TestReadProxyHead (0.35s)1992=== CONT TestPendingClosureWriteTimeout/400_objects1993=== CONT TestProxyWriteTimeout/narinfo1994=== CONT TestProxyWriteTimeout/10_GiB_nar1995=== CONT TestProxyWriteTimeout/unknown_size1996=== CONT TestProxyWriteTimeout/1_GiB_nar1997--- PASS: TestProxyWriteTimeout (0.00s)1998 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1999 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2000 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2001 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2002=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20032026/10/25 19:06:39 INFO Received uploads request method=POST path=/2004=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20052026/10/25 19:06:39 INFO Received complete multipart upload request method=POST path=/20062026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures20072026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=020082026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period20092026/10/25 19:06:39 WARN Request failed, retrying attempt=2 backoff=218.579253ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2010=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20112026/10/25 19:06:39 INFO Received request for more parts method=POST path=/20122026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=02013=== NAME TestClientCADerivations2014 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2015 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2016 error: binary cache 's3://bucket79?endpoint=http://localhost:43507®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1837379835/001/store'2017 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12018--- PASS: TestClientCADerivations (0.73s)20192026/10/25 19:06:39 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=020202026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period20212026/10/25 19:06:39 INFO Vacuumed table table=pending_closures20222026/10/25 19:06:39 INFO Vacuumed table table=pending_objects20232026/10/25 19:06:39 INFO Vacuumed table table=multipart_uploads20242026/10/25 19:06:39 INFO Vacuumed table table=closures20252026/10/25 19:06:39 INFO Vacuumed table table=objects20262026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=020272026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period20282026/10/25 19:06:39 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:43507/bucket94/?delete=\": context canceled"20292026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures2030--- PASS: TestGCEndsOnShutdown (0.00s)2031 --- PASS: TestGCEndsOnShutdown/before_the_run (0.35s)2032 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.30s)2033 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.29s)20342026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=020352026/10/25 19:06:39 INFO lead: released remote=192.0.2.1:123420362026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period20372026/10/25 19:06:39 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=020382026/10/25 19:06:39 INFO Vacuumed table table=pending_closures20392026/10/25 19:06:39 INFO Vacuumed table table=pending_objects20402026/10/25 19:06:39 INFO Vacuumed table table=multipart_uploads20412026/10/25 19:06:39 INFO Vacuumed table table=closures20422026/10/25 19:06:39 INFO Vacuumed table table=objects2043--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2044 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.37s)2045 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.33s)20462026/10/25 19:06:39 INFO lead: acquired remote=192.0.2.1:123420472026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures20482026/10/25 19:06:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20492026/10/25 19:06:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20502026/10/25 19:06:39 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LmZmMjQ2OWJhLWJkODYtNDMwOC04YjJiLWQxMzVmZmNkMzdjM3gxNzkyOTU1MTk5NTU2NDM0Njcw parts=1020512026/10/25 19:06:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20522026/10/25 19:06:39 INFO Completed upload id=1 objects=2 duration=2.061979ms20532026/10/25 19:06:39 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000020542026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures20552026/10/25 19:06:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures20562026/10/25 19:06:39 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWNlYTkzMzYtZTAyMC00Yzg2LWFmZDItMjUzODJlNDgwMDQ1LmY1ODNhMTYwLTEwNjAtNGFjNy1iYmZlLWQ1ZGNlNGRiZjQ5Y3gxNzkyOTU1MTk5NTgyNzY5MDUw parts=1020572026/10/25 19:06:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20582026/10/25 19:06:39 INFO Completed upload id=1 objects=2 duration=1.880977ms20592026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=020602026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures20612026/10/25 19:06:39 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20622026/10/25 19:06:39 INFO Received uploads request method=POST path=/api/pending_closures20632026/10/25 19:06:39 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo20642026/10/25 19:06:39 WARN Found objects in DB but missing from S3, will re-upload count=12065--- PASS: TestService_verifyS3Integrity (0.67s)20662026/10/25 19:06:39 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=020672026/10/25 19:06:39 INFO Vacuumed table table=pending_closures20682026/10/25 19:06:39 INFO Vacuumed table table=pending_objects20692026/10/25 19:06:39 INFO Vacuumed table table=multipart_uploads20702026/10/25 19:06:39 INFO Vacuumed table table=closures20712026/10/25 19:06:39 INFO Vacuumed table table=objects20722026/10/25 19:06:39 WARN Request failed, retrying attempt=3 backoff=397.433013ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20732026/10/25 19:06:39 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20742026/10/25 19:06:39 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002075--- PASS: TestService_createPendingClosureHandler (0.73s)2076=== NAME TestOrphanedObjectsGCStressTest2077 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2078 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2079--- PASS: TestDeleteClosuresRacingPins (1.65s)2080--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2081 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.81s)2082 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.81s)20832026/10/25 19:06:40 WARN Request failed, retrying attempt=4 backoff=860.747312ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2084--- PASS: TestUploadHandlersRejectOversizedBody (0.18s)2085 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2086 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2087 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.84s)2088=== NAME TestOrphanedObjectsGCStressTest2089 orphaned_objects_gc_test.go:503: Stress test completed successfully:2090 orphaned_objects_gc_test.go:504: - Active objects preserved: 202091 orphaned_objects_gc_test.go:505: - Objects deleted: 2102092 orphaned_objects_gc_test.go:506: - Total GC'd: 2102093--- PASS: TestOrphanedObjectsGCStressTest (2.98s)2094--- PASS: TestPendingClosureWriteTimeout (0.00s)2095 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2096 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2097 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2098 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.03s)20992026/10/25 19:06:40 INFO lead: released remote=192.0.2.1:12342100--- PASS: TestLeadElectsOneAndHandsOver (2.85s)21012026/10/25 19:06:41 WARN Request failed, retrying attempt=5 backoff=1.496655528s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21022026/10/25 19:06:41 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021032026/10/25 19:06:41 INFO Received create pin request method=POST path=/api/pins/myapp21042026/10/25 19:06:41 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC575394191/001/store/mwvcdwy3jdbbyaqy5q23dqbiqwwmlb63-pinned-file.txt narinfo_key=mwvcdwy3jdbbyaqy5q23dqbiqwwmlb63.narinfo21052026/10/25 19:06:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures21062026/10/25 19:06:41 INFO Garbage collection started21072026/10/25 19:06:41 INFO Aborted multipart uploads count=0 kept=021082026/10/25 19:06:41 WARN Force mode enabled - objects will be deleted immediately without grace period21092026/10/25 19:06:41 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=021102026/10/25 19:06:41 INFO Vacuumed table table=pending_closures21112026/10/25 19:06:41 INFO Vacuumed table table=pending_objects21122026/10/25 19:06:41 INFO Vacuumed table table=multipart_uploads21132026/10/25 19:06:41 INFO Vacuumed table table=closures21142026/10/25 19:06:41 INFO Vacuumed table table=objects21152026/10/25 19:06:41 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02116=== NAME TestClientIntegration2117 client_integration_test.go:323: Objects in database after GC:2118 client_integration_test.go:323: Successfully deleted all objects with GC --force2119--- PASS: TestClientIntegration (2.61s)21202026/10/25 19:06:42 WARN Rate limiter enabled after throttle name=s3-test rate=521212026/10/25 19:06:42 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2122=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2123 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102124 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002125--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.18s)21262026/10/25 19:06:42 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-config21272026/10/25 19:06:42 WARN Request failed, retrying attempt=2 backoff=212.954043ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21282026/10/25 19:06:43 WARN Request failed, retrying attempt=3 backoff=422.514164ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2129--- PASS: TestConnectWaitsForAPeerMigration (5.14s)2130=== NAME TestPinProtectsFromGC2131 client_integration_test.go:840: Pin successfully protected closure from garbage collection2132--- PASS: TestPinProtectsFromGC (4.70s)21332026/10/25 19:06:43 WARN Request failed, retrying attempt=4 backoff=807.962958ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2134--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.62s)21352026/10/25 19:06:44 WARN Request failed, retrying attempt=5 backoff=1.547872233s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/10/25 19:06:44 INFO Aborted multipart uploads count=1 kept=021372026/10/25 19:06:44 INFO Received cleanup request method=DELETE path=/api/pending_closures21382026/10/25 19:06:44 INFO Aborted multipart uploads count=1 kept=02139--- PASS: TestPendingCleanupUsesOneCutoff (6.50s)21402026/10/25 19:06:45 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"21412026/10/25 19:06:45 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-config21422026/10/25 19:06:45 WARN Request failed, retrying attempt=2 backoff=195.729202ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/10/25 19:06:46 WARN Request failed, retrying attempt=3 backoff=385.250629ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21442026/10/25 19:06:46 WARN Request failed, retrying attempt=4 backoff=811.173748ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/10/25 19:06:47 WARN Request failed, retrying attempt=5 backoff=1.446513749s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/10/25 19:06:48 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_closures21472026/10/25 19:06:48 WARN Request failed, retrying attempt=2 backoff=192.393685ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21482026/10/25 19:06:49 WARN Request failed, retrying attempt=3 backoff=361.874356ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21492026/10/25 19:06:49 WARN Request failed, retrying attempt=4 backoff=836.960627ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21502026/10/25 19:06:50 WARN Request failed, retrying attempt=5 backoff=1.647295366s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2151--- PASS: TestClientErrorHandling (0.00s)2152 --- PASS: TestClientErrorHandling/InvalidStorePath (0.32s)2153 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.40s)2154 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.39s)2155PASS21562026-10-25 19:06:52.119 UTC [127] LOG: received smart shutdown request21572026-10-25 19:06:52.124 UTC [127] LOG: background worker "logical replication launcher" (PID 137) exited with exit code 121582026-10-25 19:06:52.135 UTC [132] LOG: shutting down21592026-10-25 19:06:52.136 UTC [132] LOG: checkpoint starting: shutdown immediate21602026-10-25 19:06:53.084 UTC [132] LOG: checkpoint complete: wrote 10585 buffers (64.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.195 s, sync=0.719 s, total=0.949 s; sync files=34045, longest=0.002 s, average=0.001 s; distance=493979 kB, estimate=493979 kB; lsn=0/1F9CC950, redo lsn=0/1F9CC95021612026-10-25 19:06:53.168 UTC [127] LOG: database system is shut down2162Running OIDC tests...2163=== RUN TestAudienceForIssuer2164=== PAUSE TestAudienceForIssuer2165=== RUN TestGlobMatch2166=== PAUSE TestGlobMatch2167=== RUN TestValidateToken_ValidToken2168=== PAUSE TestValidateToken_ValidToken2169=== RUN TestValidateToken_WrongAudience2170=== PAUSE TestValidateToken_WrongAudience2171=== RUN TestValidateToken_Expired2172=== PAUSE TestValidateToken_Expired2173=== RUN TestValidateToken_BoundClaimsMismatch2174=== PAUSE TestValidateToken_BoundClaimsMismatch2175=== RUN TestValidateToken_BoundSubjectMismatch2176=== PAUSE TestValidateToken_BoundSubjectMismatch2177=== RUN TestValidateToken_MultipleProviders2178=== PAUSE TestValidateToken_MultipleProviders2179=== RUN TestValidateToken_NoMatchingProvider2180=== PAUSE TestValidateToken_NoMatchingProvider2181=== RUN TestValidateToken_KubernetesServiceAccount2182=== PAUSE TestValidateToken_KubernetesServiceAccount2183=== RUN TestNewValidator_KubernetesRequiresCA2184=== PAUSE TestNewValidator_KubernetesRequiresCA2185=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2186=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2187=== RUN TestPins_ReservedForMatchingRule2188=== PAUSE TestPins_ReservedForMatchingRule2189=== RUN TestPins_TopLevelShorthand2190=== PAUSE TestPins_TopLevelShorthand2191=== RUN TestPins_ConfigValidation2192=== PAUSE TestPins_ConfigValidation2193=== RUN TestScopes_LegacyProviderDefaultsToWrite2194=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2195=== RUN TestScopes_Rules2196=== PAUSE TestScopes_Rules2197=== RUN TestScopes_ConfigValidation2198=== PAUSE TestScopes_ConfigValidation2199=== CONT TestAudienceForIssuer2200=== CONT TestValidateToken_KubernetesServiceAccount2201--- PASS: TestAudienceForIssuer (0.00s)2202=== CONT TestScopes_ConfigValidation2203=== CONT TestScopes_LegacyProviderDefaultsToWrite2204=== CONT TestValidateToken_NoMatchingProvider2205=== CONT TestValidateToken_MultipleProviders2206=== CONT TestValidateToken_BoundSubjectMismatch2207=== CONT TestValidateToken_BoundClaimsMismatch2208=== CONT TestValidateToken_Expired2209=== CONT TestValidateToken_WrongAudience2210=== CONT TestValidateToken_ValidToken2211=== CONT TestGlobMatch2212=== RUN TestGlobMatch/foo_foo2213=== PAUSE TestGlobMatch/foo_foo2214=== RUN TestGlobMatch/foo_bar2215=== PAUSE TestGlobMatch/foo_bar2216=== RUN TestGlobMatch/*_2217=== PAUSE TestGlobMatch/*_2218=== RUN TestGlobMatch/*_anything2219=== PAUSE TestGlobMatch/*_anything2220=== RUN TestGlobMatch/foo*_foo2221=== PAUSE TestGlobMatch/foo*_foo2222=== RUN TestGlobMatch/foo*_foobar2223=== PAUSE TestGlobMatch/foo*_foobar2224=== CONT TestPins_ConfigValidation2225=== CONT TestPins_ReservedForMatchingRule2226=== CONT TestPins_TopLevelShorthand2227=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2228=== CONT TestNewValidator_KubernetesRequiresCA2229=== CONT TestScopes_Rules2230--- PASS: TestScopes_ConfigValidation (0.00s)2231=== RUN TestGlobMatch/foo*_bar2232=== PAUSE TestGlobMatch/foo*_bar2233=== RUN TestGlobMatch/*bar_bar2234=== PAUSE TestGlobMatch/*bar_bar2235=== RUN TestGlobMatch/*bar_foobar2236=== PAUSE TestGlobMatch/*bar_foobar2237=== RUN TestGlobMatch/*bar_foo2238=== PAUSE TestGlobMatch/*bar_foo2239=== RUN TestGlobMatch/foo*bar_foobar2240=== PAUSE TestGlobMatch/foo*bar_foobar2241=== RUN TestGlobMatch/foo*bar_foo123bar2242=== PAUSE TestGlobMatch/foo*bar_foo123bar2243=== RUN TestGlobMatch/foo*bar_foobarbaz2244=== PAUSE TestGlobMatch/foo*bar_foobarbaz2245=== RUN TestGlobMatch/*/*_foo/bar2246=== PAUSE TestGlobMatch/*/*_foo/bar2247=== RUN TestGlobMatch/*/*_foo2248=== PAUSE TestGlobMatch/*/*_foo2249=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2250=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2251=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02252=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02253=== RUN TestGlobMatch/refs/*/main_refs/heads/main2254=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2255=== RUN TestGlobMatch/fo?_foo2256=== PAUSE TestGlobMatch/fo?_foo2257=== RUN TestGlobMatch/fo?_fo2258=== PAUSE TestGlobMatch/fo?_fo2259=== RUN TestGlobMatch/fo?_fooo2260=== PAUSE TestGlobMatch/fo?_fooo2261=== RUN TestGlobMatch/?oo_foo2262=== PAUSE TestGlobMatch/?oo_foo2263=== RUN TestGlobMatch/?oo_boo2264=== PAUSE TestGlobMatch/?oo_boo2265=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2266=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2267=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2268=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2269=== CONT TestGlobMatch/foo_foo2270=== CONT TestGlobMatch/*/*_foo/bar2271=== CONT TestGlobMatch/fo?_fo2272=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2273=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2274=== CONT TestGlobMatch/?oo_boo2275=== CONT TestGlobMatch/?oo_foo2276=== CONT TestGlobMatch/fo?_fooo2277=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02278=== CONT TestGlobMatch/fo?_foo2279=== CONT TestGlobMatch/refs/*/main_refs/heads/main2280=== CONT TestGlobMatch/*/*_foo2281=== CONT TestGlobMatch/*bar_bar2282=== CONT TestGlobMatch/foo*bar_foobarbaz2283=== CONT TestGlobMatch/foo*bar_foo123bar2284=== CONT TestGlobMatch/foo*bar_foobar2285=== CONT TestGlobMatch/*bar_foo2286=== CONT TestGlobMatch/*bar_foobar2287=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2288=== CONT TestGlobMatch/foo*_foo2289=== CONT TestGlobMatch/foo*_bar2290=== CONT TestGlobMatch/foo*_foobar2291=== CONT TestGlobMatch/*_2292=== CONT TestGlobMatch/*_anything2293=== CONT TestGlobMatch/foo_bar2294--- PASS: TestGlobMatch (0.00s)2295 --- PASS: TestGlobMatch/foo_foo (0.00s)2296 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2297 --- PASS: TestGlobMatch/fo?_fo (0.00s)2298 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2299 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2300 --- PASS: TestGlobMatch/?oo_boo (0.00s)2301 --- PASS: TestGlobMatch/?oo_foo (0.00s)2302 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2303 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2304 --- PASS: TestGlobMatch/fo?_foo (0.00s)2305 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2306 --- PASS: TestGlobMatch/*/*_foo (0.00s)2307 --- PASS: TestGlobMatch/*bar_bar (0.00s)2308 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2309 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2310 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2311 --- PASS: TestGlobMatch/*bar_foo (0.00s)2312 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2313 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2314 --- PASS: TestGlobMatch/foo*_foo (0.00s)2315 --- PASS: TestGlobMatch/foo*_bar (0.00s)2316 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2317 --- PASS: TestGlobMatch/*_ (0.00s)2318 --- PASS: TestGlobMatch/*_anything (0.00s)2319 --- PASS: TestGlobMatch/foo_bar (0.00s)2320--- PASS: TestPins_ConfigValidation (0.00s)23212026/10/25 19:06:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42957/oidc2322--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)23232026/10/25 19:06:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34909/oidc2324--- PASS: TestValidateToken_WrongAudience (0.06s)23252026/10/25 19:06:54 http: TLS handshake error from 127.0.0.1:44468: remote error: tls: bad certificate2326--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)23272026/10/25 19:06:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42659/oidc2328--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.12s)23292026/10/25 19:06:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38773/oidc2330--- PASS: TestValidateToken_NoMatchingProvider (0.16s)23312026/10/25 19:06:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35683/oidc2332--- PASS: TestValidateToken_ValidToken (0.20s)23332026/10/25 19:06:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41121/oidc2334--- PASS: TestPins_ReservedForMatchingRule (0.21s)23352026/10/25 19:06:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43151/oidc2336--- PASS: TestValidateToken_BoundSubjectMismatch (0.24s)23372026/10/25 19:06:55 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232338--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.25s)23392026/10/25 19:06:55 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:39985/oidc23402026/10/25 19:06:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38189/oidc23412026/10/25 19:06:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36851/oidc2342--- PASS: TestValidateToken_MultipleProviders (0.27s)2343--- PASS: TestValidateToken_Expired (0.27s)23442026/10/25 19:06:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43455/oidc23452026/10/25 19:06:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40579/oidc2346--- PASS: TestPins_TopLevelShorthand (0.29s)2347--- PASS: TestScopes_Rules (0.29s)23482026/10/25 19:06:55 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:424232349--- PASS: TestValidateToken_KubernetesServiceAccount (0.48s)2350PASS2351Running hook tests...2352=== RUN TestSendPathsEmpty2353=== PAUSE TestSendPathsEmpty2354=== RUN TestQueueEnqueueAndFetch2355=== PAUSE TestQueueEnqueueAndFetch2356=== RUN TestQueueDeduplication2357=== PAUSE TestQueueDeduplication2358=== RUN TestQueueRemove2359=== PAUSE TestQueueRemove2360=== RUN TestQueueFetchBatchLimit2361=== PAUSE TestQueueFetchBatchLimit2362=== RUN TestQueueRetryMovesToBack2363=== PAUSE TestQueueRetryMovesToBack2364=== RUN TestQueueFetchRemoveLifecycle2365=== PAUSE TestQueueFetchRemoveLifecycle2366=== RUN TestQueueConcurrentWriters2367=== PAUSE TestQueueConcurrentWriters2368=== RUN TestQueueRemoveLargeClosure2369=== PAUSE TestQueueRemoveLargeClosure2370=== RUN TestServerClientIntegration2371--- PASS: TestServerClientIntegration (0.00s)2372=== RUN TestServerQueueError23732026/10/25 19:06:55 ERROR Failed to queue paths error="permission denied" count=12374--- PASS: TestServerQueueError (0.00s)2375=== RUN TestGetListenerSocketActivation2376 server_test.go:218: === RUN TestGetListenerSocketActivation2377 --- PASS: TestGetListenerSocketActivation (0.00s)2378 PASS2379 2380--- PASS: TestGetListenerSocketActivation (0.01s)2381=== RUN TestServerStalledClientDoesNotBlockShutdown2382=== PAUSE TestServerStalledClientDoesNotBlockShutdown2383=== RUN TestServerBacksOffOnAcceptErrors2384=== PAUSE TestServerBacksOffOnAcceptErrors2385=== RUN TestDrainIsolatesPoisonPath2386=== PAUSE TestDrainIsolatesPoisonPath2387=== RUN TestRunNotBlockedByPoisonHead2388=== PAUSE TestRunNotBlockedByPoisonHead2389=== RUN TestDrainGivesUpWhenServerDown2390=== PAUSE TestDrainGivesUpWhenServerDown2391=== RUN TestFailedPathPrunedByLaterClosure2392=== PAUSE TestFailedPathPrunedByLaterClosure2393=== RUN TestWorkerUploadsAndRemoves2394=== PAUSE TestWorkerUploadsAndRemoves2395=== RUN TestWorkerSkipsGCdPaths2396=== PAUSE TestWorkerSkipsGCdPaths2397=== RUN TestWorkerPrunesClosureDeps2398=== PAUSE TestWorkerPrunesClosureDeps2399=== RUN TestDrainTimeout2400=== PAUSE TestDrainTimeout2401=== RUN TestWorkerRemoveFailureIsNotProgress2402=== PAUSE TestWorkerRemoveFailureIsNotProgress2403=== RUN TestWorkerKeepsPathItCannotStat2404=== PAUSE TestWorkerKeepsPathItCannotStat2405=== CONT TestSendPathsEmpty2406=== CONT TestDrainTimeout2407=== CONT TestWorkerPrunesClosureDeps2408=== CONT TestWorkerKeepsPathItCannotStat2409=== CONT TestWorkerRemoveFailureIsNotProgress2410--- PASS: TestSendPathsEmpty (0.00s)2411=== CONT TestQueueRemoveLargeClosure2412=== CONT TestServerStalledClientDoesNotBlockShutdown2413=== CONT TestQueueConcurrentWriters2414=== CONT TestQueueFetchRemoveLifecycle2415=== CONT TestQueueRetryMovesToBack2416=== CONT TestQueueFetchBatchLimit2417=== CONT TestQueueRemove2418=== CONT TestWorkerSkipsGCdPaths2419=== CONT TestQueueDeduplication2420=== CONT TestWorkerUploadsAndRemoves2421=== CONT TestQueueEnqueueAndFetch2422=== CONT TestFailedPathPrunedByLaterClosure2423=== CONT TestDrainIsolatesPoisonPath2424=== CONT TestServerBacksOffOnAcceptErrors24252026/10/25 19:06:55 ERROR Accept failed error="too many open files"2426=== CONT TestRunNotBlockedByPoisonHead2427=== CONT TestDrainGivesUpWhenServerDown24282026/10/25 19:06:55 ERROR Accept failed error="too many open files"24292026/10/25 19:06:55 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2598587568/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2598587568/002/locked/aaa: permission denied"24302026/10/25 19:06:55 INFO Uploading batch count=224312026/10/25 19:06:55 INFO Uploading batch count=424322026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=42433--- PASS: TestQueueFetchBatchLimit (0.01s)2434--- PASS: TestQueueEnqueueAndFetch (0.01s)24352026/10/25 19:06:55 INFO Uploading batch count=224362026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=224372026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3463430784/002/a24382026/10/25 19:06:55 INFO Uploading batch count=12439--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24402026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=124412026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3463430784/002/b24422026/10/25 19:06:55 INFO Upload queue status pending=224432026/10/25 19:06:55 INFO Uploading batch count=124442026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2508177298/002/bbb24452026/10/25 19:06:55 INFO Upload queue status pending=224462026/10/25 19:06:55 INFO Upload queue status pending=22447--- PASS: TestQueueDeduplication (0.01s)24482026/10/25 19:06:55 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2598587568/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2598587568/002/locked/aaa: permission denied"24492026/10/25 19:06:55 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2969669066/002/nonexistent24502026/10/25 19:06:55 INFO Uploading batch count=124512026/10/25 19:06:55 INFO Uploading batch count=22452--- PASS: TestQueueRemove (0.02s)24532026/10/25 19:06:55 INFO Uploading batch count=224542026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=224552026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3463430784/002/c24562026/10/25 19:06:55 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2598587568/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2598587568/002/locked/aaa: permission denied"24572026/10/25 19:06:55 INFO Upload queue status pending=324582026/10/25 19:06:55 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1597873827/002/nonexistent24592026/10/25 19:06:55 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124602026/10/25 19:06:55 INFO Uploading batch count=124612026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3463430784/002/d24622026/10/25 19:06:55 INFO Uploading batch count=124632026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=124642026/10/25 19:06:55 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1597873827/002/nonexistent2465--- PASS: TestQueueRetryMovesToBack (0.02s)24662026/10/25 19:06:55 INFO Uploading batch count=124672026/10/25 19:06:55 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124682026/10/25 19:06:55 ERROR Drain finished with paths left in queue remaining=124692026/10/25 19:06:55 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1597873827/002/nonexistent24702026/10/25 19:06:55 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124712026/10/25 19:06:55 INFO Uploading batch count=224722026/10/25 19:06:55 ERROR Drain finished with paths left in queue remaining=124732026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=224742026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3463430784/002/e24752026/10/25 19:06:55 ERROR Accept failed error="too many open files"24762026/10/25 19:06:55 INFO Uploading batch count=124772026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=12478--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)24792026/10/25 19:06:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3463430784/002/f24802026/10/25 19:06:55 INFO Uploading batch count=124812026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=12482--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2483--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24842026/10/25 19:06:55 ERROR Drain finished with paths left in queue remaining=1024852026/10/25 19:06:55 INFO Uploading batch count=124862026/10/25 19:06:55 ERROR Upload failed error="upload failed" count=124872026/10/25 19:06:55 ERROR Drain finished with paths left in queue remaining=12488--- PASS: TestDrainIsolatesPoisonPath (0.02s)2489--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2490--- PASS: TestWorkerSkipsGCdPaths (0.03s)2491--- PASS: TestWorkerUploadsAndRemoves (0.03s)2492--- PASS: TestWorkerPrunesClosureDeps (0.04s)24932026/10/25 19:06:55 ERROR Accept failed error="too many open files"24942026/10/25 19:06:55 ERROR Accept failed error="too many open files"2495--- PASS: TestQueueRemoveLargeClosure (0.11s)24962026/10/25 19:06:55 ERROR Accept failed error="too many open files"24972026/10/25 19:06:55 ERROR Failed to decode request error="read unix /build/hook3509872068/test.sock->@: i/o timeout"24982026/10/25 19:06:55 ERROR Failed to write response error="write unix /build/hook3509872068/test.sock->@: i/o timeout"2499--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)2500--- PASS: TestQueueConcurrentWriters (0.21s)25012026/10/25 19:06:55 ERROR Upload failed error="context deadline exceeded" count=225022026/10/25 19:06:55 ERROR Drain finished with paths left in queue remaining=42503--- PASS: TestDrainTimeout (0.22s)25042026/10/25 19:06:55 ERROR Accept failed error="too many open files"25052026/10/25 19:06:56 ERROR Accept failed error="too many open files"2506--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25072026/10/25 19:06:56 INFO Uploading batch count=125082026/10/25 19:06:56 INFO Uploading batch count=125092026/10/25 19:06:56 INFO Uploading batch count=125102026/10/25 19:06:56 ERROR Upload failed error="upload failed" count=125112026/10/25 19:06:56 INFO Uploading batch count=125122026/10/25 19:06:56 ERROR Upload failed error="upload failed" count=125132026/10/25 19:06:56 INFO Uploading batch count=125142026/10/25 19:06:56 ERROR Upload failed error="upload failed" count=125152026/10/25 19:06:56 INFO Uploading batch count=125162026/10/25 19:06:56 ERROR Upload failed error="upload failed" count=125172026/10/25 19:06:56 ERROR Drain finished with paths left in queue remaining=12518--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2519PASS2520Running signing tests...2521=== RUN TestExternalSigner2522=== PAUSE TestExternalSigner2523=== RUN TestExternalSignerWrongPublicKey2524=== PAUSE TestExternalSignerWrongPublicKey2525=== RUN TestExternalSignerErrors2526=== PAUSE TestExternalSignerErrors2527=== RUN TestExternalSignerRestartsAfterCrash2528=== PAUSE TestExternalSignerRestartsAfterCrash2529=== RUN TestExternalSignerProgramErrorKeepsProcess2530=== PAUSE TestExternalSignerProgramErrorKeepsProcess2531=== RUN TestExternalSignerClose2532=== PAUSE TestExternalSignerClose2533=== RUN TestExternalSignerRejectsInvalidPublicKey2534=== PAUSE TestExternalSignerRejectsInvalidPublicKey2535=== RUN TestExternalSignerCancellation2536=== PAUSE TestExternalSignerCancellation2537=== RUN TestGenerateFingerprint2538=== PAUSE TestGenerateFingerprint2539=== RUN TestParseSigningKey2540=== PAUSE TestParseSigningKey2541=== RUN TestSign2542=== PAUSE TestSign2543=== RUN TestSignBatch2544=== PAUSE TestSignBatch2545=== RUN TestNilKeyPublicKey2546=== PAUSE TestNilKeyPublicKey2547=== RUN TestSignErrors2548=== PAUSE TestSignErrors2549=== CONT TestExternalSigner2550=== CONT TestExternalSignerCancellation2551=== CONT TestSign2552=== CONT TestSignBatch2553=== CONT TestParseSigningKey2554=== CONT TestSignErrors2555=== CONT TestExternalSignerProgramErrorKeepsProcess2556=== CONT TestNilKeyPublicKey2557--- PASS: TestNilKeyPublicKey (0.00s)2558=== CONT TestGenerateFingerprint2559=== RUN TestGenerateFingerprint/basic_with_references2560=== PAUSE TestGenerateFingerprint/basic_with_references2561=== RUN TestGenerateFingerprint/no_references2562=== PAUSE TestGenerateFingerprint/no_references2563=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2564=== RUN TestParseSigningKey/valid_32-byte_key2565=== PAUSE TestParseSigningKey/valid_32-byte_key2566=== CONT TestExternalSignerClose2567=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2568=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2569=== RUN TestParseSigningKey/no_colon2570=== PAUSE TestParseSigningKey/no_colon2571=== RUN TestParseSigningKey/empty_name2572=== CONT TestExternalSignerErrors2573=== CONT TestExternalSignerRestartsAfterCrash2574=== CONT TestExternalSignerWrongPublicKey2575=== CONT TestExternalSignerRejectsInvalidPublicKey2576=== RUN TestExternalSignerRejectsInvalidPublicKey/#002577=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2578=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002579=== PAUSE TestParseSigningKey/empty_name2580=== RUN TestExternalSignerErrors/missing_signatures2581=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2582=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2583=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2584=== RUN TestParseSigningKey/invalid_base642585=== PAUSE TestParseSigningKey/invalid_base642586=== RUN TestParseSigningKey/wrong_length2587=== PAUSE TestParseSigningKey/wrong_length2588=== CONT TestParseSigningKey/valid_32-byte_key2589=== CONT TestParseSigningKey/no_colon2590=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2591=== RUN TestGenerateFingerprint/invalid_nar_hash_length2592=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2593=== RUN TestGenerateFingerprint/invalid_store_path_prefix2594=== CONT TestParseSigningKey/empty_name2595=== CONT TestParseSigningKey/invalid_base642596=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2597=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2598=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2599=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2600=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2601=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2602=== CONT TestExternalSignerRejectsInvalidPublicKey/#002603=== PAUSE TestExternalSignerErrors/missing_signatures2604=== RUN TestExternalSignerErrors/too_few_signatures2605=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2606=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2607=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2608=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2609=== RUN TestGenerateFingerprint/invalid_reference_prefix2610=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2611=== CONT TestGenerateFingerprint/basic_with_references2612=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2613=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2614=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2615=== CONT TestGenerateFingerprint/invalid_store_path_prefix2616=== CONT TestParseSigningKey/wrong_length2617=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2618--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2619 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2620 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2621 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2622 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2623 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2624=== PAUSE TestExternalSignerErrors/too_few_signatures2625=== RUN TestExternalSignerErrors/wrong_signature_length2626=== CONT TestGenerateFingerprint/invalid_reference_prefix2627=== CONT TestGenerateFingerprint/invalid_nar_hash_length2628=== CONT TestGenerateFingerprint/no_references2629--- PASS: TestGenerateFingerprint (0.00s)2630 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2631 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2632 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2633 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2634 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2635 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2636 --- PASS: TestGenerateFingerprint/no_references (0.00s)2637=== PAUSE TestExternalSignerErrors/wrong_signature_length2638=== RUN TestExternalSignerErrors/exit_on_request2639=== PAUSE TestExternalSignerErrors/exit_on_request2640=== RUN TestExternalSignerErrors/invalid_JSON2641=== PAUSE TestExternalSignerErrors/invalid_JSON2642=== RUN TestExternalSignerErrors/wrong_shape2643=== PAUSE TestExternalSignerErrors/wrong_shape2644=== RUN TestExternalSignerErrors/wrong_id2645=== PAUSE TestExternalSignerErrors/wrong_id2646=== RUN TestExternalSignerErrors/null_signatures2647=== PAUSE TestExternalSignerErrors/null_signatures2648=== RUN TestExternalSignerErrors/missing_signature_name2649=== PAUSE TestExternalSignerErrors/missing_signature_name2650=== RUN TestExternalSignerErrors/program_error2651=== PAUSE TestExternalSignerErrors/program_error2652=== RUN TestExternalSignerErrors/null2653=== PAUSE TestExternalSignerErrors/null2654=== RUN TestExternalSignerErrors/invalid_signature_base642655=== PAUSE TestExternalSignerErrors/invalid_signature_base642656=== RUN TestExternalSignerErrors/wrong_signatures_shape2657=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2658=== RUN TestExternalSignerErrors/unrequested_key2659=== PAUSE TestExternalSignerErrors/unrequested_key2660=== RUN TestSignErrors/nil_key2661=== PAUSE TestSignErrors/nil_key2662=== RUN TestExternalSignerErrors/wrong_signature_name2663=== PAUSE TestExternalSignerErrors/wrong_signature_name2664--- PASS: TestSign (0.00s)2665=== RUN TestExternalSignerErrors/exit_at_startup2666=== RUN TestSignErrors/nil_narinfo2667=== PAUSE TestSignErrors/nil_narinfo2668=== PAUSE TestExternalSignerErrors/exit_at_startup2669--- PASS: TestParseSigningKey (0.00s)2670 --- PASS: TestParseSigningKey/no_colon (0.00s)2671 --- PASS: TestParseSigningKey/empty_name (0.00s)2672 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2673 --- PASS: TestParseSigningKey/wrong_length (0.00s)2674 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2675 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2676=== CONT TestExternalSignerErrors/wrong_signature_length2677=== CONT TestExternalSignerErrors/unrequested_key2678=== CONT TestExternalSignerErrors/missing_signatures2679=== CONT TestExternalSignerErrors/exit_at_startup2680--- PASS: TestSignBatch (0.00s)2681=== CONT TestExternalSignerErrors/wrong_signature_name2682=== CONT TestExternalSignerErrors/wrong_id2683=== CONT TestExternalSignerErrors/wrong_shape2684=== CONT TestExternalSignerErrors/invalid_JSON2685=== CONT TestExternalSignerErrors/null_signatures2686=== CONT TestExternalSignerErrors/exit_on_request2687=== RUN TestSignErrors/invalid_narinfo2688=== CONT TestExternalSignerErrors/program_error2689=== CONT TestExternalSignerErrors/too_few_signatures2690=== CONT TestExternalSignerErrors/missing_signature_name2691=== CONT TestExternalSignerErrors/null2692--- PASS: TestExternalSignerClose (0.00s)2693=== CONT TestExternalSignerErrors/wrong_signatures_shape2694=== CONT TestExternalSignerErrors/invalid_signature_base642695=== PAUSE TestSignErrors/invalid_narinfo2696--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2697=== RUN TestSignErrors/canceled2698=== PAUSE TestSignErrors/canceled2699=== CONT TestSignErrors/nil_key2700=== CONT TestSignErrors/invalid_narinfo2701=== CONT TestSignErrors/nil_narinfo2702=== CONT TestSignErrors/canceled2703--- PASS: TestSignErrors (0.01s)2704 --- PASS: TestSignErrors/nil_key (0.00s)2705 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2706 --- PASS: TestSignErrors/nil_narinfo (0.00s)2707 --- PASS: TestSignErrors/canceled (0.00s)2708--- PASS: TestExternalSignerWrongPublicKey (0.01s)2709--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2710--- PASS: TestExternalSigner (0.01s)2711--- PASS: TestExternalSignerErrors (0.00s)2712 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2713 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2714 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2715 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2716 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2717 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2718 --- PASS: TestExternalSignerErrors/null (0.00s)2719 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2720 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2721 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2722 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2723 --- PASS: TestExternalSignerErrors/program_error (0.01s)2724 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2725 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2726 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2727 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2728--- PASS: TestExternalSignerCancellation (0.02s)2729PASS2730Running OpenBao signer tests...2731=== RUN TestSign2732=== PAUSE TestSign2733=== RUN TestSignErrors2734=== PAUSE TestSignErrors2735=== RUN TestServe2736=== PAUSE TestServe2737=== RUN TestServeRejectsGarbage2738=== PAUSE TestServeRejectsGarbage2739=== CONT TestSign2740=== CONT TestServeRejectsGarbage2741=== CONT TestServe2742=== CONT TestSignErrors2743=== RUN TestSignErrors/http_error2744=== PAUSE TestSignErrors/http_error2745=== RUN TestSignErrors/invalid_json2746=== PAUSE TestSignErrors/invalid_json2747=== RUN TestSignErrors/no_prefix2748=== PAUSE TestSignErrors/no_prefix2749=== RUN TestSignErrors/invalid_base642750=== PAUSE TestSignErrors/invalid_base642751--- PASS: TestServeRejectsGarbage (0.00s)2752=== CONT TestSignErrors/http_error2753=== CONT TestSignErrors/invalid_json2754--- PASS: TestServe (0.00s)2755=== CONT TestSignErrors/invalid_base642756=== CONT TestSignErrors/no_prefix2757--- PASS: TestSign (0.00s)2758--- PASS: TestSignErrors (0.00s)2759 --- PASS: TestSignErrors/invalid_json (0.00s)2760 --- PASS: TestSignErrors/no_prefix (0.00s)2761 --- PASS: TestSignErrors/http_error (0.00s)2762 --- PASS: TestSignErrors/invalid_base64 (0.00s)2763PASS