niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #425
· 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.04s)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 TestScriptTokenEmptyCommand117=== CONT TestScriptTokenEmptyToken118=== CONT TestStreamPushReportsSignatures1192026/10/25 16:05:22 ERROR Upload failed error=boom count=1120=== CONT TestPathInfoHashCompatibility121=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)122=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)123=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon124=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon125=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI126=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI127=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512128=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512129=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1302026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=server-test rate=5131=== CONT TestScriptTokenScriptFails132=== CONT TestRateLimiterFeedback133=== RUN TestRateLimiterFeedback/429_enables_limiter134=== CONT TestScriptTokenBadJSON135=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer136=== CONT TestScriptTokenCachesUntilRefresh137=== CONT TestStreamPushRequestLine138=== CONT TestStreamPushGivesUpOnDeadServer139=== CONT TestPathInfoCACompatibility140=== CONT TestStreamPushIsolatesFailures141=== CONT TestStreamPushBatchesUnderLoad142=== CONT TestStreamPushReportsEveryPath143=== CONT TestShellSplitErrors144=== CONT TestShellSplit1452026/10/25 16:05:22 ERROR Upload failed error=boom count=11462026/10/25 16:05:22 ERROR Upload failed error="bad path" count=3147=== CONT TestDoWithRetry_FinalResponseBodyReadable1482026/10/25 16:05:22 ERROR Upload failed error="connection refused" count=20149=== CONT TestRetryTimeoutOutlastsMaxRetries150=== CONT TestDoWithRetry_BodyReplayedViaGetBody1512026/10/25 16:05:22 ERROR Server seems unavailable, giving up on batch untried=17152=== CONT TestSetClientTLSDoesNotMutateDefaultTransport153=== CONT TestResolveStorePath154=== CONT TestSetClientTLSErrors155=== CONT TestFileTokenEmpty156=== CONT TestFileTokenMissing157=== CONT TestFileTokenReadsAndCaches1582026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33329159--- PASS: TestScriptTokenEmptyCommand (0.00s)160--- PASS: TestStreamPushReportsSignatures (0.00s)161--- PASS: TestDoServerRequestAttachesToken (0.00s)1622026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=server-test rate=5163=== CONT TestStaticToken1642026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:44325165=== CONT TestClientSignaturesByStorePath166=== CONT TestUploadMultipart_PartsInParallel1672026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=server-test rate=5168=== PAUSE TestRateLimiterFeedback/429_enables_limiter1692026/10/25 16:05:22 WARN Rate limiter backed off name=server-test rate=51702026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:34461171=== RUN TestPathInfoCACompatibility/null_ca_field172=== PAUSE TestPathInfoCACompatibility/null_ca_field173=== CONT TestParsePathInfoJSONMultiplePaths174=== CONT TestParsePathInfoJSON175=== CONT TestStreamPushStopsWhenCanceled176=== CONT TestScriptTokenNoExpiryRerunsEveryCall177=== CONT TestEncodeNixBase32WithRealHash178=== CONT TestConvertHashToNix32179=== CONT TestSetClientTLS180=== CONT TestGetStorePathHash181--- PASS: TestScriptTokenScriptFails (0.00s)182--- PASS: TestShellSplitErrors (0.00s)183--- PASS: TestStreamPushReportsEveryPath (0.00s)184=== CONT TestDumpPathMatchesNix185=== RUN TestRateLimiterFeedback/503_enables_limiter186=== PAUSE TestRateLimiterFeedback/503_enables_limiter187=== CONT TestSupersededNARStillUploadsListing188=== CONT TestUploadMultipart_SupersededByPeer189=== RUN TestUploadMultipart_SupersededByPeer/exists190=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter191=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths192=== CONT TestEncodeNixBase32193=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths194=== RUN TestPathInfoCACompatibility/old_string_format_-_text195=== RUN TestConvertHashToNix32/SRI_format_to_Nix32196=== RUN TestSupersededNARStillUploadsListing/small_NAR197=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text198=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32199=== RUN TestParsePathInfoJSON/Nix_format2002026/10/25 16:05:22 WARN Rate limiter backed off name=server-test rate=5201=== PAUSE TestUploadMultipart_SupersededByPeer/exists2022026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:344612032026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33329204=== RUN TestGetStorePathHash/valid_store_path205=== PAUSE TestGetStorePathHash/valid_store_path206=== CONT TestStreamPushReportsSkippedPaths207=== CONT TestDumpPathWriterError208=== CONT TestUploadMultipart_FailedPartBufferNotReused209=== RUN TestGetStorePathHash/basename_without_hyphen_should_error210=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter211--- PASS: TestShellSplit (0.00s)212--- PASS: TestStreamPushIsolatesFailures (0.00s)213--- PASS: TestScriptTokenEmptyToken (0.01s)214--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)215=== RUN TestSetClientTLSErrors/missing_cert_file216=== CONT TestPartSizeForNAR217=== PAUSE TestParsePathInfoJSON/Nix_format218=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths219=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive220=== RUN TestEncodeNixBase32/test_string_hash221=== RUN TestConvertHashToNix32/already_Nix32_format222--- PASS: TestScriptTokenBadJSON (0.01s)223--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)224--- PASS: TestStaticToken (0.00s)225=== RUN TestUploadMultipart_SupersededByPeer/missing226=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun227=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error228=== CONT TestFilterOversizedClosures229=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter230=== PAUSE TestConvertHashToNix32/already_Nix32_format231=== PAUSE TestSupersededNARStillUploadsListing/small_NAR232=== RUN TestFilterOversizedClosures/no_limit_keeps_everything233=== RUN TestPartSizeForNAR/zero_stays_at_minimum234--- PASS: TestClientSignaturesByStorePath (0.00s)235--- PASS: TestFileTokenMissing (0.00s)236--- PASS: TestFileTokenEmpty (0.00s)237--- PASS: TestResolveStorePath (0.00s)238--- PASS: TestStreamPushStopsWhenCanceled (0.00s)239=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive240=== RUN TestParsePathInfoJSON/Lix_format241=== RUN TestPathInfoCACompatibility/new_structured_format_-_text242=== PAUSE TestSetClientTLSErrors/missing_cert_file243=== PAUSE TestEncodeNixBase32/test_string_hash244=== RUN TestSetClientTLSErrors/missing_key_file245=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error246--- PASS: TestEncodeNixBase32WithRealHash (0.00s)247--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)248--- PASS: TestFileTokenReadsAndCaches (0.03s)249--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)250=== RUN TestEncodeNixBase32/empty_input251--- PASS: TestStreamPushReportsSkippedPaths (0.00s)252--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)253=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths254=== RUN TestConvertHashToNix32/invalid_format255=== CONT TestCaseHackSuffix256=== PAUSE TestConvertHashToNix32/invalid_format257=== RUN TestSupersededNARStillUploadsListing/dump_cut_short258=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short259=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything260=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped261=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped262=== RUN TestFilterOversizedClosures/all_closures_skipped263=== PAUSE TestFilterOversizedClosures/all_closures_skipped264=== CONT TestRegisterUploadedObjectReusesConnections265=== PAUSE TestParsePathInfoJSON/Lix_format266=== RUN TestParsePathInfoJSON/empty_input267=== PAUSE TestParsePathInfoJSON/empty_input268=== RUN TestParsePathInfoJSON/whitespace_only269=== PAUSE TestParsePathInfoJSON/whitespace_only270=== RUN TestParsePathInfoJSON/invalid_JSON271=== PAUSE TestParsePathInfoJSON/invalid_JSON272=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text273=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method274=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum275=== RUN TestPartSizeForNAR/small_stays_at_minimum276=== PAUSE TestPartSizeForNAR/small_stays_at_minimum277=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum278=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum279=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts280=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts281=== RUN TestPartSizeForNAR/1_TiB282=== PAUSE TestPartSizeForNAR/1_TiB283=== RUN TestPartSizeForNAR/5_TiB_S3_max_object284=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object285=== RUN TestPartSizeForNAR/capped_at_5_GiB286=== PAUSE TestPartSizeForNAR/capped_at_5_GiB287=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica288=== RUN TestSetClientTLS/rejects_connection_without_client_cert289=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert290=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA291=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA292=== RUN TestSetClientTLS/preserves_debug_logging_transport293=== PAUSE TestSetClientTLS/preserves_debug_logging_transport294=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails295=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry296=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error297=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error298=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error299=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method300=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)301=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails302=== PAUSE TestEncodeNixBase32/empty_input303=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI304=== PAUSE TestSetClientTLSErrors/missing_key_file305=== RUN TestSetClientTLSErrors/missing_ca_file306=== PAUSE TestSetClientTLSErrors/missing_ca_file307=== RUN TestSetClientTLSErrors/invalid_ca_file308=== PAUSE TestSetClientTLSErrors/invalid_ca_file309=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512310=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths311=== CONT TestConvertHashToNix32/already_Nix32_format312=== CONT TestFilterOversizedClosures/no_limit_keeps_everything313=== CONT TestDumpPathSingleFile314=== CONT TestParsePathInfoJSON/invalid_JSON315=== CONT TestParsePathInfoJSON/whitespace_only316=== CONT TestParsePathInfoJSON/empty_input317=== CONT TestParsePathInfoJSON/Lix_format318=== CONT TestPartSizeForNAR/zero_stays_at_minimum319=== CONT TestConvertHashToNix32/invalid_format320=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped321=== CONT TestFilterOversizedClosures/all_closures_skipped322=== CONT TestConvertHashToNix32/SRI_format_to_Nix32323=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths324=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon325=== CONT TestParsePathInfoJSON/Nix_format326--- PASS: TestPathInfoHashCompatibility (0.00s)327 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)328 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)329 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)330 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)331=== CONT TestGetStorePathHash/valid_store_path332=== CONT TestPathInfoCACompatibility/null_ca_field333--- PASS: TestParsePathInfoJSON (0.04s)334 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)335 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)336 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)337 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)338 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)339=== CONT TestSupersededNARStillUploadsListing/small_NAR340--- PASS: TestParsePathInfoJSONMultiplePaths (0.07s)341 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)342 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)343=== CONT TestEncodeNixBase32/test_string_hash344=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA345=== CONT TestSetClientTLS/rejects_connection_without_client_cert346=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error347=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error348=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter349=== PAUSE TestUploadMultipart_SupersededByPeer/missing350=== CONT TestGetStorePathHash/basename_without_hyphen_should_error3512026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:333293522026/10/25 16:05:22 INFO Garbage collection started353=== CONT TestPartSizeForNAR/5_TiB_S3_max_object354=== CONT TestPartSizeForNAR/1_TiB355--- PASS: TestConvertHashToNix32 (0.04s)356 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)357 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)358 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)3592026/10/25 16:05:22 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=20003602026/10/25 16:05:22 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=503612026/10/25 16:05:22 INFO Garbage collection started3622026/10/25 16:05:22 INFO Uploading abc-hello (1.0GB)363--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)364--- PASS: TestGetStorePathHash (0.04s)365 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)366 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)367 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)368 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)369=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts370--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)371=== CONT TestSetClientTLSErrors/missing_ca_file372--- PASS: TestFilterOversizedClosures (0.03s)373 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)374 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)375 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)3762026/10/25 16:05:22 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=03772026/10/25 16:05:22 WARN Garbage collection finished on another replica. Its statistics are not available here378--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)379=== CONT TestSetClientTLSErrors/missing_key_file380=== CONT TestPathInfoCACompatibility/new_structured_format_-_text381=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive382=== CONT TestPathInfoCACompatibility/old_string_format_-_text383=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3842026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:333293852026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=s3-test rate=53862026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:40879387=== CONT TestEncodeNixBase32/empty_input388--- PASS: TestEncodeNixBase32 (0.04s)389 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)390 --- PASS: TestEncodeNixBase32/empty_input (0.00s)391=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails392--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)3932026/10/25 16:05:22 INFO Uploading abc-hello (1.0GB)394=== CONT TestRateLimiterFeedback/429_enables_limiter3952026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:333293962026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=server-test rate=53972026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:440553982026/10/25 16:05:22 WARN Rate limiter backed off name=server-test rate=5399=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter400--- PASS: TestPathInfoCACompatibility (0.08s)401 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)402 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)403 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)404 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)405 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.01s)4062026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:33329407=== CONT TestSupersededNARStillUploadsListing/dump_cut_short408=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter4092026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:33329410=== CONT TestRateLimiterFeedback/503_enables_limiter411=== CONT TestUploadMultipart_SupersededByPeer/exists412=== CONT TestUploadMultipart_SupersededByPeer/missing413=== CONT TestSetClientTLSErrors/invalid_ca_file414=== CONT TestPartSizeForNAR/capped_at_5_GiB415=== CONT TestSetClientTLS/preserves_debug_logging_transport416=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum417=== CONT TestSetClientTLSErrors/missing_cert_file418=== CONT TestPartSizeForNAR/small_stays_at_minimum419--- PASS: TestPartSizeForNAR (0.03s)420 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)421 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)422 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)423 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)424 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)425 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)426 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)4272026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:333294282026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=server-test rate=54292026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:361914302026/10/25 16:05:22 WARN Rate limiter backed off name=server-test rate=5431--- PASS: TestRateLimiterFeedback (0.08s)432 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)433 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)434 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)435 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.26s)436--- PASS: TestSetClientTLSErrors (0.07s)437 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)438 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)439 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.26s)440 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.26s)441--- PASS: TestUploadMultipart_SupersededByPeer (0.05s)442 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.26s)443 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.27s)4442026/10/25 16:05:22 http: TLS handshake error from 127.0.0.1:54272: remote error: tls: bad certificate445--- PASS: TestSetClientTLS (0.04s)446 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)447 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.27s)448 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.28s)4492026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:33329450--- PASS: TestStreamPushBatchesUnderLoad (0.36s)451--- PASS: TestDumpPathSingleFile (0.29s)452--- PASS: TestCaseHackSuffix (0.29s)4532026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:333294542026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:333294552026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:33329456--- PASS: TestRegisterUploadedObjectReusesConnections (0.29s)4572026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:333294582026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:333294592026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:333294602026/10/25 16:05:22 WARN Rate limiter enabled after throttle name=s3-test rate=54612026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:333294622026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:33329463--- PASS: TestDumpPathWriterError (0.34s)4642026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:333294652026/10/25 16:05:22 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:33329466--- PASS: TestStreamPushRequestLine (0.38s)467--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.38s)4682026/10/25 16:05:22 INFO Uploading abc-hello (1.0GB)469--- PASS: TestDumpPathMatchesNix (0.41s)4702026/10/25 16:05:22 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43621/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43621/part/24712026/10/25 16:05:22 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43621/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43621/part/34722026/10/25 16:05:22 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43621/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43621/part/44732026/10/25 16:05:22 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"474--- PASS: TestSupersededNARStillUploadsListing (0.04s)475 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.00s)476 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.28s)477 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.83s)478--- PASS: TestUploadMultipart_PartsInParallel (0.92s)479--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.89s)480--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4812026/10/25 16:05:23 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:42121/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:42121/api/uploads/complete4822026/10/25 16:05:23 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 16:05:23 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:42121/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:42121/api/uploads/complete4842026/10/25 16:05:23 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4852026/10/25 16:05:23 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:42121/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:42121/api/uploads/complete4862026/10/25 16:05:23 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"487--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)488PASS489Running server tests...490The files belonging to this database system will be owned by user "nixbld".491This user must also own the server process.492493The database cluster will be initialized with locale "C".494The default database encoding has accordingly been set to "SQL_ASCII".495The default text search configuration will be set to "english".496497Data page checksums are enabled.498499creating directory /build/postgres2694958272/data ... ok500creating subdirectories ... ok501selecting dynamic shared memory implementation ... posix502selecting default "max_connections" ... 100503selecting default "shared_buffers" ... 128MB504selecting default time zone ... UTC505creating configuration files ... ok506running bootstrap script ... ok507performing post-bootstrap initialization ... ok508syncing data to disk ... ok509510initdb: warning: enabling "trust" authentication for local connections511initdb: 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.512513Success. You can now start the database server using:514515 pg_ctl -D /build/postgres2694958272/data -l logfile start516517/build/postgres2694958272:5432 - no response5182026-10-25 16:05:24.089 UTC [127] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5192026-10-25 16:05:24.092 UTC [127] LOG: listening on Unix socket "/build/postgres2694958272/.s.PGSQL.5432"5202026-10-25 16:05:24.097 UTC [134] LOG: database system was shut down at 2026-10-25 16:05:23 UTC5212026-10-25 16:05:24.102 UTC [127] LOG: database system is ready to accept connections522/build/postgres2694958272:5432 - accepting connections523=== RUN TestService_AuthMiddleware524=== PAUSE TestService_AuthMiddleware525=== RUN TestService_AuthMiddleware_MTLSProxyHeader526=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader527=== RUN TestService_AuthMiddleware_MTLSBoundSubjects528=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects529=== RUN TestService_ReadAuthMiddleware530=== PAUSE TestService_ReadAuthMiddleware531=== RUN TestService_AuthMiddleware_OIDC532=== PAUSE TestService_AuthMiddleware_OIDC533=== RUN TestService_RequireScope_OIDC534=== PAUSE TestService_RequireScope_OIDC535=== RUN TestService_ReadScope_PublicByDefault536=== PAUSE TestService_ReadScope_PublicByDefault537=== RUN TestCacheConfigHandler538=== PAUSE TestCacheConfigHandler539=== RUN TestCacheStatsHandler540=== PAUSE TestCacheStatsHandler541=== RUN TestClientCADerivations542=== PAUSE TestClientCADerivations543=== RUN TestClientErrorHandling544=== PAUSE TestClientErrorHandling545=== RUN TestClientIntegration546=== PAUSE TestClientIntegration547=== RUN TestClientMultipleUploads548=== PAUSE TestClientMultipleUploads549=== RUN TestClientWithDependencies550=== PAUSE TestClientWithDependencies551=== RUN TestClientSharedPathCommittedMidPush552=== PAUSE TestClientSharedPathCommittedMidPush553=== RUN TestPinProtectsFromGC554=== PAUSE TestPinProtectsFromGC555=== RUN TestClientPushesUseOnePush556=== PAUSE TestClientPushesUseOnePush557=== RUN TestClientFallsBackToClosures558=== PAUSE TestClientFallsBackToClosures559=== RUN TestDeleteClosuresRacingPins560=== PAUSE TestDeleteClosuresRacingPins561=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock562=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock563=== RUN TestResolveDBConnectionString564=== PAUSE TestResolveDBConnectionString565=== RUN TestConnectWaitsForAPeerMigration566=== PAUSE TestConnectWaitsForAPeerMigration567=== RUN TestLeadElectsOneAndHandsOver568=== PAUSE TestLeadElectsOneAndHandsOver569=== RUN TestLeadIncumbentWinsAfterRestart5702026/10/25 16:05:24 INFO lead: acquired remote=192.0.2.1:12345712026/10/25 16:05:25 INFO lead: released remote=192.0.2.1:12345722026/10/25 16:05:25 INFO lead: acquired remote=192.0.2.1:12345732026/10/25 16:05:26 INFO lead: released remote=192.0.2.1:1234574--- PASS: TestLeadIncumbentWinsAfterRestart (1.92s)575=== RUN TestLeadIncumbentAnnouncesAtOnce576=== PAUSE TestLeadIncumbentAnnouncesAtOnce577=== RUN TestLeadEndsOnShutdown578=== PAUSE TestLeadEndsOnShutdown579=== RUN TestLeadEndsWhenItsConnectionHangs5802026/10/25 16:05:26 INFO lead: acquired remote=192.0.2.1:12345812026-10-25 16:05:27.852 UTC [386] FATAL: terminating connection due to administrator command5822026/10/25 16:05:28 INFO lead: acquired remote=192.0.2.1:12345832026/10/25 16:05:29 WARN lead: lock connection lost error="timeout: context deadline exceeded"5842026/10/25 16:05:29 INFO lead: released remote=192.0.2.1:12345852026/10/25 16:05:29 INFO lead: released remote=192.0.2.1:1234586--- PASS: TestLeadEndsWhenItsConnectionHangs (2.93s)587=== RUN TestGCAdvisoryLockBlocksConcurrentRun588=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun589=== RUN TestGCBugBareHashReferences590=== PAUSE TestGCBugBareHashReferences591=== RUN TestGCMetrics592=== PAUSE TestGCMetrics593=== RUN TestPushDedupSurvivesConcurrentGC594=== PAUSE TestPushDedupSurvivesConcurrentGC595=== RUN TestDeduplicatedObjectsRecordedAsPending596=== PAUSE TestDeduplicatedObjectsRecordedAsPending597=== RUN TestGCSweepSkipsPendingObjects598=== PAUSE TestGCSweepSkipsPendingObjects599=== RUN TestTombstonedObjectOfferedWithoutWaiting600=== PAUSE TestTombstonedObjectOfferedWithoutWaiting601=== RUN TestGCSweepDeliversEachKeyOnce602=== PAUSE TestGCSweepDeliversEachKeyOnce603=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection604=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection605=== RUN TestForceGCDuringPushOffersSweptObject606=== PAUSE TestForceGCDuringPushOffersSweptObject607=== RUN TestFailedS3DeleteKeepsTombstone608=== PAUSE TestFailedS3DeleteKeepsTombstone609=== RUN TestSweepSkipsRowsLockedByPush610=== PAUSE TestSweepSkipsRowsLockedByPush611=== RUN TestRegisterCompletedObjectNeedsPendingRow612=== PAUSE TestRegisterCompletedObjectNeedsPendingRow613=== RUN TestGetExistingObjectsLocksRows614=== PAUSE TestGetExistingObjectsLocksRows615=== RUN TestSweepRechecksPendingAfterLocking616=== PAUSE TestSweepRechecksPendingAfterLocking617=== RUN TestPushWaitsForSweepHoldingRow618=== PAUSE TestPushWaitsForSweepHoldingRow619=== RUN TestCommitRacingPendingCleanupKeepsObjects620=== PAUSE TestCommitRacingPendingCleanupKeepsObjects621=== RUN TestGCEndsOnShutdown622=== PAUSE TestGCEndsOnShutdown623=== RUN TestGCTaskStore_StartNew624=== PAUSE TestGCTaskStore_StartNew625=== RUN TestGCTaskStore_DeduplicateSameParams626=== PAUSE TestGCTaskStore_DeduplicateSameParams627=== RUN TestGCTaskStore_ConflictDifferentParams628=== PAUSE TestGCTaskStore_ConflictDifferentParams629=== RUN TestGCTaskStore_GetEmpty630=== PAUSE TestGCTaskStore_GetEmpty631=== RUN TestGCTaskStore_GetReturnsLatest632=== PAUSE TestGCTaskStore_GetReturnsLatest633=== RUN TestGCTaskStore_CompletedAllowsNewTask634=== PAUSE TestGCTaskStore_CompletedAllowsNewTask635=== RUN TestGCTaskStore_PhaseUpdates636=== PAUSE TestGCTaskStore_PhaseUpdates637=== RUN TestGCTaskStore_Fail638=== PAUSE TestGCTaskStore_Fail639=== RUN TestGracefulShutdownDrainsInflight640=== PAUSE TestGracefulShutdownDrainsInflight641=== RUN TestService_healthCheckHandler642=== PAUSE TestService_healthCheckHandler643=== RUN TestService_readinessHandler644=== PAUSE TestService_readinessHandler645=== RUN TestGenerateLandingPage646=== PAUSE TestGenerateLandingPage647=== RUN TestCacheConfigHandlerMaxNarSize648=== PAUSE TestCacheConfigHandlerMaxNarSize649=== RUN TestCreatePendingClosureRejectsOversizedNAR650=== PAUSE TestCreatePendingClosureRejectsOversizedNAR651=== RUN TestNARDeduplicationMetadataUploadBug652=== PAUSE TestNARDeduplicationMetadataUploadBug653=== RUN TestMetricsInventory654=== PAUSE TestMetricsInventory655=== RUN TestMetricsCommit656=== PAUSE TestMetricsCommit657=== RUN TestService_NativeMTLS658=== PAUSE TestService_NativeMTLS659=== RUN TestServerTLSConfig660=== PAUSE TestServerTLSConfig661=== RUN TestMultipartCleanup662=== PAUSE TestMultipartCleanup663=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded664=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded665=== RUN TestPendingCleanupUsesOneCutoff666=== PAUSE TestPendingCleanupUsesOneCutoff667=== RUN TestObjectStatsTrigger668=== PAUSE TestObjectStatsTrigger669=== RUN TestObjectStatsUpdatedOncePerCommit670=== PAUSE TestObjectStatsUpdatedOncePerCommit671=== RUN TestOrphanedObjectsGC672=== PAUSE TestOrphanedObjectsGC673=== RUN TestOrphanedObjectsGCStressTest674=== PAUSE TestOrphanedObjectsGCStressTest675=== RUN TestCreatePin_ReservedPins676=== PAUSE TestCreatePin_ReservedPins677=== RUN TestPresentReportsOnlyClosureRoots678=== PAUSE TestPresentReportsOnlyClosureRoots679=== RUN TestPresentRefreshesOnlyStaleClosures680=== PAUSE TestPresentRefreshesOnlyStaleClosures681=== RUN TestPresentNotReportedWhileGCDeletesClosure682=== PAUSE TestPresentNotReportedWhileGCDeletesClosure683=== RUN TestParseSingleRange684=== PAUSE TestParseSingleRange685=== RUN TestProxyHeadersOnlyTrustedOnSocket6862026/10/25 16:05:29 INFO Starting HTTP server address=proxy.sock6872026/10/25 16:05:29 INFO Starting HTTP server address=127.0.0.1:356736882026/10/25 16:05:29 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6892026/10/25 16:05:29 INFO Shutdown signal received, draining in-flight requests timeout=10s690--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)691=== RUN TestIsValidCachePath692=== PAUSE TestIsValidCachePath693=== RUN TestReadProxyNarinfo694=== PAUSE TestReadProxyNarinfo695=== RUN TestReadProxyNarinfoAlreadyDecompressed696=== PAUSE TestReadProxyNarinfoAlreadyDecompressed697=== RUN TestReadProxyContentNegotiation698=== PAUSE TestReadProxyContentNegotiation699=== RUN TestReadProxyNarStreaming700=== PAUSE TestReadProxyNarStreaming701=== RUN TestReadProxy404702=== PAUSE TestReadProxy404703=== RUN TestReadProxyInvalidPath704=== PAUSE TestReadProxyInvalidPath705=== RUN TestReadProxyHead706=== PAUSE TestReadProxyHead707=== RUN TestReadProxyOutlastsServerWriteTimeout708=== PAUSE TestReadProxyOutlastsServerWriteTimeout709=== RUN TestReadProxyConditionalGet710=== PAUSE TestReadProxyConditionalGet711=== RUN TestReadProxyRootRedirectsToIndexHTML712=== PAUSE TestReadProxyRootRedirectsToIndexHTML713=== RUN TestReadProxyDisabled714=== PAUSE TestReadProxyDisabled715=== RUN TestReadRedirectNar716=== PAUSE TestReadRedirectNar717=== RUN TestReadRedirectKeepsNarinfoProxied718=== PAUSE TestReadRedirectKeepsNarinfoProxied719=== RUN TestReadProxyRangeRequest720=== PAUSE TestReadProxyRangeRequest721=== RUN TestReadRedirectUsesPublicS3URL722=== PAUSE TestReadRedirectUsesPublicS3URL723=== RUN TestPush_OverlappingRootsStoreOneRowPerKey724=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey725=== RUN TestPush_CompleteCommitsEveryRoot726=== PAUSE TestPush_CompleteCommitsEveryRoot727=== RUN TestPush_RepeatedRootCommitsOnce728=== PAUSE TestPush_RepeatedRootCommitsOnce729=== RUN TestPush_CompleteWaitsForCleanupOfThePush730=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush731=== RUN TestPush_RootsAreLockedInByteOrder732=== PAUSE TestPush_RootsAreLockedInByteOrder733=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit734=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit735=== RUN TestPush_RejectsBadRequests736=== PAUSE TestPush_RejectsBadRequests737=== RUN TestPush_SignsNarinfosOfItsPendingObjects738=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects739=== RUN TestRedundantMultipartUpload740=== PAUSE TestRedundantMultipartUpload741=== RUN TestCompleteMultipartUpload_ErrorButObjectExists742=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists743=== RUN TestCompletedNarNotReofferedAcrossClosures744=== PAUSE TestCompletedNarNotReofferedAcrossClosures745=== RUN TestPresignedUploadRegisteredBeforeCommit746=== PAUSE TestPresignedUploadRegisteredBeforeCommit747=== RUN TestService_Rustfstest748=== PAUSE TestService_Rustfstest749=== RUN TestParseSize750=== PAUSE TestParseSize751=== RUN TestSkippedUploadsHandler752=== PAUSE TestSkippedUploadsHandler753=== RUN TestSystemdListenerNotActivated754--- PASS: TestSystemdListenerNotActivated (0.00s)755=== RUN TestWatchdogBeatsWhenHealthy756--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)757=== RUN TestWatchdogSkipsWhenUnhealthy7582026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 16:05:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"768--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)769=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle770=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle771=== RUN TestProxyWriteTimeout772=== PAUSE TestProxyWriteTimeout773=== RUN TestPendingClosureWriteTimeout774=== PAUSE TestPendingClosureWriteTimeout775=== RUN TestIsValidUploadKey776=== PAUSE TestIsValidUploadKey777=== RUN TestUploadHandlersRejectInvalidKeys778=== PAUSE TestUploadHandlersRejectInvalidKeys779=== RUN TestUploadHandlersRejectOversizedBody780=== PAUSE TestUploadHandlersRejectOversizedBody781=== RUN TestService_cleanupPendingClosuresHandler782=== PAUSE TestService_cleanupPendingClosuresHandler783=== RUN TestService_createPendingClosureHandler784=== PAUSE TestService_createPendingClosureHandler785=== RUN TestService_verifyS3Integrity786=== PAUSE TestService_verifyS3Integrity787=== RUN TestCompleteMultipartUnregistered788=== PAUSE TestCompleteMultipartUnregistered789=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT790=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT791=== CONT TestService_AuthMiddleware792=== CONT TestMetricsInventory793=== CONT TestDeduplicatedObjectsRecordedAsPending794=== CONT TestGCEndsOnShutdown795=== RUN TestGCEndsOnShutdown/before_the_run796=== PAUSE TestGCEndsOnShutdown/before_the_run797=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete798=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete799=== CONT TestGCTaskStore_DeduplicateSameParams800--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)801=== CONT TestRegisterCompletedObjectNeedsPendingRow802=== CONT TestNARDeduplicationMetadataUploadBug803=== CONT TestCreatePendingClosureRejectsOversizedNAR804=== CONT TestCacheConfigHandlerMaxNarSize805=== CONT TestGenerateLandingPage806=== CONT TestService_readinessHandler807=== CONT TestService_healthCheckHandler8082026/10/25 16:05:29 INFO Received uploads request method=POST path=/api/pending_closures809=== CONT TestGracefulShutdownDrainsInflight810=== CONT TestGCTaskStore_Fail811=== CONT TestFailedS3DeleteKeepsTombstone812=== CONT TestForceGCDuringPushOffersSweptObject813=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows814=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows815=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check816=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check817=== CONT TestTombstonedObjectOfferedWithoutWaiting8182026/10/25 16:05:29 INFO Starting HTTP server address=127.0.0.1:36935819=== CONT TestGCTaskStore_PhaseUpdates820=== CONT TestGCSweepDeliversEachKeyOnce821=== CONT TestGCTaskStore_CompletedAllowsNewTask822=== CONT TestReadRedirectKeepsNarinfoProxied823=== CONT TestGCTaskStore_GetReturnsLatest824=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT825=== CONT TestGCTaskStore_GetEmpty826=== CONT TestGCTaskStore_ConflictDifferentParams827=== CONT TestCommitRacingPendingCleanupKeepsObjects828=== CONT TestGCTaskStore_StartNew829=== CONT TestPushWaitsForSweepHoldingRow830=== CONT TestCompleteMultipartUnregistered831=== CONT TestService_verifyS3Integrity8322026/10/25 16:05:29 INFO Shutdown signal received, draining in-flight requests timeout=10s833=== CONT TestService_createPendingClosureHandler834=== CONT TestGetExistingObjectsLocksRows835=== CONT TestSweepRechecksPendingAfterLocking836=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection837=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark838=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark839=== CONT TestSweepSkipsRowsLockedByPush840=== CONT TestService_cleanupPendingClosuresHandler841=== CONT TestUploadHandlersRejectOversizedBody842--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)843--- PASS: TestGCTaskStore_Fail (0.00s)844--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)845--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)846--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)847--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)848--- PASS: TestGCTaskStore_GetEmpty (0.00s)849--- PASS: TestGCTaskStore_StartNew (0.00s)850--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)851--- PASS: TestGenerateLandingPage (0.01s)852--- PASS: TestGracefulShutdownDrainsInflight (0.08s)853=== CONT TestUploadHandlersRejectInvalidKeys854=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info855=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info856=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal857=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal858=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key859=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key860=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key861=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key862=== CONT TestIsValidUploadKey863=== RUN TestIsValidUploadKey/narinfo864=== PAUSE TestIsValidUploadKey/narinfo865=== RUN TestIsValidUploadKey/nar_zst866=== PAUSE TestIsValidUploadKey/nar_zst867=== RUN TestIsValidUploadKey/nar_xz868=== PAUSE TestIsValidUploadKey/nar_xz869=== RUN TestIsValidUploadKey/nar_plain870=== PAUSE TestIsValidUploadKey/nar_plain871=== RUN TestIsValidUploadKey/listing872=== PAUSE TestIsValidUploadKey/listing873=== RUN TestIsValidUploadKey/build_log874=== PAUSE TestIsValidUploadKey/build_log875=== RUN TestIsValidUploadKey/build_log_home-manager_file876=== PAUSE TestIsValidUploadKey/build_log_home-manager_file877=== RUN TestIsValidUploadKey/build_log_plus_in_name878=== PAUSE TestIsValidUploadKey/build_log_plus_in_name879=== RUN TestIsValidUploadKey/build_log_question_mark880=== PAUSE TestIsValidUploadKey/build_log_question_mark881=== RUN TestIsValidUploadKey/build_log_equals882=== PAUSE TestIsValidUploadKey/build_log_equals883=== RUN TestIsValidUploadKey/realisation884=== PAUSE TestIsValidUploadKey/realisation885=== RUN TestIsValidUploadKey/realisation_plus_in_output886=== PAUSE TestIsValidUploadKey/realisation_plus_in_output887=== RUN TestIsValidUploadKey/nix-cache-info888=== PAUSE TestIsValidUploadKey/nix-cache-info889=== RUN TestIsValidUploadKey/index.html890=== PAUSE TestIsValidUploadKey/index.html891=== RUN TestIsValidUploadKey/narinfo_key,_nar_type892=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type893=== RUN TestIsValidUploadKey/nar_key,_narinfo_type894=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type895=== RUN TestIsValidUploadKey/listing_key,_narinfo_type896=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type897=== RUN TestIsValidUploadKey/traversal898=== PAUSE TestIsValidUploadKey/traversal899=== RUN TestIsValidUploadKey/traversal_nar900=== PAUSE TestIsValidUploadKey/traversal_nar901=== RUN TestIsValidUploadKey/absolute902=== PAUSE TestIsValidUploadKey/absolute903=== RUN TestIsValidUploadKey/empty_key904=== PAUSE TestIsValidUploadKey/empty_key905=== RUN TestIsValidUploadKey/unknown_type906=== PAUSE TestIsValidUploadKey/unknown_type907=== CONT TestPendingClosureWriteTimeout908=== RUN TestPendingClosureWriteTimeout/empty909=== PAUSE TestPendingClosureWriteTimeout/empty910=== RUN TestPendingClosureWriteTimeout/400_objects911=== PAUSE TestPendingClosureWriteTimeout/400_objects912=== RUN TestPendingClosureWriteTimeout/670k_objects913=== PAUSE TestPendingClosureWriteTimeout/670k_objects914=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline915=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline916=== CONT TestProxyWriteTimeout917=== RUN TestProxyWriteTimeout/narinfo918=== PAUSE TestProxyWriteTimeout/narinfo919=== RUN TestProxyWriteTimeout/1_GiB_nar920=== PAUSE TestProxyWriteTimeout/1_GiB_nar921=== RUN TestProxyWriteTimeout/10_GiB_nar922=== PAUSE TestProxyWriteTimeout/10_GiB_nar923=== RUN TestProxyWriteTimeout/unknown_size924=== PAUSE TestProxyWriteTimeout/unknown_size925=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle926=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure927=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure928=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart929=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart930=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts931=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts932=== CONT TestSkippedUploadsHandler9332026/10/25 16:05:29 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000934--- PASS: TestSkippedUploadsHandler (0.00s)935=== CONT TestParseSize936--- PASS: TestParseSize (0.00s)937=== CONT TestService_Rustfstest9382026/10/25 16:05:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9392026/10/25 16:05:30 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst940--- PASS: TestCompleteMultipartUnregistered (0.41s)941=== CONT TestPresignedUploadRegisteredBeforeCommit9422026/10/25 16:05:30 WARN readiness check failed error="closed pool"943--- PASS: TestService_readinessHandler (0.44s)944=== CONT TestCompletedNarNotReofferedAcrossClosures945--- PASS: TestService_healthCheckHandler (0.50s)946=== CONT TestCompleteMultipartUpload_ErrorButObjectExists947=== NAME TestNARDeduplicationMetadataUploadBug948 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug392356389/001/store/9mg6cy32irwrwmphkwlif4rb5d0psgfd-file1.txt9492026/10/25 16:05:30 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"950--- PASS: TestService_AuthMiddleware (0.53s)951=== CONT TestRedundantMultipartUpload952--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.57s)953=== CONT TestPush_SignsNarinfosOfItsPendingObjects9542026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures9552026/10/25 16:05:30 INFO Received push request method=POST path=/api/pushes9562026/10/25 16:05:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9572026/10/25 16:05:30 INFO Uploading 9mg6cy32irwrwmphkwlif4rb5d0psgfd-file1.txt (160B)9582026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures9592026/10/25 16:05:30 WARN Failed to register uploaded object key=9mg6cy32irwrwmphkwlif4rb5d0psgfd.ls error="server returned 404: 404 page not found\n"9602026/10/25 16:05:30 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"9612026/10/25 16:05:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9622026/10/25 16:05:30 INFO Signed narinfos id=1 count=19632026/10/25 16:05:30 INFO Uploading 1 narinfos9642026/10/25 16:05:30 INFO Received complete push request method=POST path=/api/pushes/1/complete9652026/10/25 16:05:30 WARN Failed to register uploaded object key=9mg6cy32irwrwmphkwlif4rb5d0psgfd.narinfo error="server returned 404: 404 page not found\n"9662026/10/25 16:05:30 INFO Completed push id=1 objects=3 duration=7.194286ms9672026/10/25 16:05:30 INFO Upload complete. (82ms)968=== NAME TestNARDeduplicationMetadataUploadBug969 metadata_upload_test.go:54: Retrieved narinfo from S3:970 StorePath: /build/TestNARDeduplicationMetadataUploadBug392356389/001/store/9mg6cy32irwrwmphkwlif4rb5d0psgfd-file1.txt971 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst972 Compression: zstd973 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf974 NarSize: 160975 References: 976 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf977 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)978 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):979 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}980 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug392356389/001/store/xbdgjx4gr74bg8dd9l0hxc28nz13h7xi-file2.txt9812026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=09822026/10/25 16:05:30 WARN Force mode enabled - objects will be deleted immediately without grace period9832026/10/25 16:05:30 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=09842026/10/25 16:05:30 INFO Vacuumed table table=pending_closures9852026/10/25 16:05:30 INFO Vacuumed table table=pending_objects9862026/10/25 16:05:30 INFO Vacuumed table table=multipart_uploads9872026/10/25 16:05:30 INFO Vacuumed table table=closures9882026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=09892026/10/25 16:05:30 INFO Vacuumed table table=objects990--- PASS: TestGCSweepDeliversEachKeyOnce (0.73s)991=== CONT TestPush_RejectsBadRequests9922026/10/25 16:05:30 WARN Force mode enabled - objects will be deleted immediately without grace period993--- PASS: TestReadRedirectKeepsNarinfoProxied (0.74s)994=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9952026/10/25 16:05:30 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=09962026/10/25 16:05:30 INFO Vacuumed table table=pending_closures9972026/10/25 16:05:30 INFO Vacuumed table table=pending_objects9982026/10/25 16:05:30 INFO Vacuumed table table=multipart_uploads9992026/10/25 16:05:30 INFO Vacuumed table table=closures10002026/10/25 16:05:30 INFO Vacuumed table table=objects10012026/10/25 16:05:30 INFO Received push request method=POST path=/api/pushes1002--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.76s)1003=== CONT TestPush_RootsAreLockedInByteOrder10042026/10/25 16:05:30 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10052026/10/25 16:05:30 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign1006--- PASS: TestGetExistingObjectsLocksRows (0.77s)1007=== CONT TestPush_CompleteWaitsForCleanupOfThePush10082026/10/25 16:05:30 INFO Signed narinfos id=2 count=110092026/10/25 16:05:30 WARN Failed to register uploaded object key=xbdgjx4gr74bg8dd9l0hxc28nz13h7xi.ls error="server returned 404: 404 page not found\n"10102026/10/25 16:05:30 INFO Uploading 1 narinfos10112026/10/25 16:05:30 INFO Received complete push request method=POST path=/api/pushes/2/complete10122026/10/25 16:05:30 WARN Failed to register uploaded object key=xbdgjx4gr74bg8dd9l0hxc28nz13h7xi.narinfo error="server returned 404: 404 page not found\n"10132026/10/25 16:05:30 INFO Completed push id=2 objects=3 duration=3.148889ms10142026/10/25 16:05:30 INFO Upload complete. (58ms)1015=== NAME TestNARDeduplicationMetadataUploadBug1016 metadata_upload_test.go:76: Retrieved narinfo from S3:1017 StorePath: /build/TestNARDeduplicationMetadataUploadBug392356389/001/store/xbdgjx4gr74bg8dd9l0hxc28nz13h7xi-file2.txt1018 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1019 Compression: zstd1020 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1021 NarSize: 1601022 References: 1023 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1024 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1025 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1026 {"version":1,"root":{"type":"regular","size":44}}1027--- PASS: TestNARDeduplicationMetadataUploadBug (0.80s)1028=== CONT TestPush_RepeatedRootCommitsOnce1029--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.81s)1030=== CONT TestPush_CompleteCommitsEveryRoot1031--- PASS: TestMetricsInventory (0.82s)1032=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10332026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures1034--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.83s)1035=== CONT TestReadRedirectUsesPublicS3URL10362026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures1037--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.86s)1038=== CONT TestReadProxyRangeRequest10392026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures1040--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.90s)1041=== CONT TestGCSweepSkipsPendingObjects10422026/10/25 16:05:30 INFO Received cleanup request method=DELETE path=/api/pending_closures10432026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=010442026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10452026/10/25 16:05:30 INFO Received cleanup request method=DELETE path=/api/pending_closures10462026/10/25 16:05:30 INFO Aborted multipart uploads count=1 kept=010472026/10/25 16:05:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10482026-10-25 16:05:30.592 UTC [481] ERROR: Closure does not exist: id=110492026-10-25 16:05:30.592 UTC [481] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10502026-10-25 16:05:30.592 UTC [481] STATEMENT: -- name: CommitPendingClosure :one1051 SELECT commit_pending_closure($1::bigint)::bigint1052 1053--- PASS: TestService_cleanupPendingClosuresHandler (0.94s)1054=== CONT TestParseSingleRange1055=== RUN TestParseSingleRange/none1056=== PAUSE TestParseSingleRange/none1057=== RUN TestParseSingleRange/unknown_unit1058=== PAUSE TestParseSingleRange/unknown_unit1059=== RUN TestParseSingleRange/multi-range_ignored1060=== PAUSE TestParseSingleRange/multi-range_ignored1061=== RUN TestParseSingleRange/malformed_no_dash1062=== PAUSE TestParseSingleRange/malformed_no_dash1063=== RUN TestParseSingleRange/malformed_both_empty1064=== PAUSE TestParseSingleRange/malformed_both_empty1065=== RUN TestParseSingleRange/malformed_end_before_start1066=== PAUSE TestParseSingleRange/malformed_end_before_start1067=== RUN TestParseSingleRange/closed1068=== PAUSE TestParseSingleRange/closed1069=== RUN TestParseSingleRange/open-ended1070=== PAUSE TestParseSingleRange/open-ended1071=== RUN TestParseSingleRange/end_clamped_to_size1072=== PAUSE TestParseSingleRange/end_clamped_to_size1073=== RUN TestParseSingleRange/suffix1074=== PAUSE TestParseSingleRange/suffix1075=== RUN TestParseSingleRange/suffix_exceeds_size1076=== PAUSE TestParseSingleRange/suffix_exceeds_size1077=== RUN TestParseSingleRange/single_byte1078=== PAUSE TestParseSingleRange/single_byte1079=== RUN TestParseSingleRange/start_past_EOF1080=== PAUSE TestParseSingleRange/start_past_EOF1081=== RUN TestParseSingleRange/start_far_past_EOF1082=== PAUSE TestParseSingleRange/start_far_past_EOF1083=== CONT TestReadRedirectNar10842026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10852026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10862026/10/25 16:05:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10872026/10/25 16:05:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LmI1YzkzNjNkLTA0NWMtNGQ0YS04ZTQ2LWQ3OTA2MTE1MDhjMXgxNzkyOTQ0MzMwMjc5NDMyMDY0 parts=1010882026/10/25 16:05:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10892026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10902026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10912026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10922026/10/25 16:05:30 INFO Completed upload id=1 objects=2 duration=2.530123ms10932026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10942026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures10952026/10/25 16:05:30 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10962026/10/25 16:05:30 WARN Found objects in DB but missing from S3, will re-upload count=11097--- PASS: TestService_verifyS3Integrity (1.02s)1098=== CONT TestReadProxyDisabled10992026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures11002026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=011012026/10/25 16:05:30 WARN Force mode enabled - objects will be deleted immediately without grace period11022026/10/25 16:05:30 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11032026/10/25 16:05:30 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."11042026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=01105--- PASS: TestService_Rustfstest (0.92s)1106=== CONT TestReadProxyRootRedirectsToIndexHTML1107--- PASS: TestFailedS3DeleteKeepsTombstone (1.10s)1108=== CONT TestReadProxyConditionalGet11092026/10/25 16:05:30 WARN Force mode enabled - objects will be deleted immediately without grace period11102026/10/25 16:05:30 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=011112026/10/25 16:05:30 INFO Vacuumed table table=pending_closures11122026/10/25 16:05:30 INFO Vacuumed table table=pending_objects11132026/10/25 16:05:30 INFO Vacuumed table table=multipart_uploads11142026/10/25 16:05:30 INFO Vacuumed table table=closures11152026/10/25 16:05:30 INFO Vacuumed table table=objects11162026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=011172026/10/25 16:05:30 WARN Force mode enabled - objects will be deleted immediately without grace period11182026/10/25 16:05:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11192026/10/25 16:05:30 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=011202026/10/25 16:05:30 INFO Vacuumed table table=pending_closures11212026/10/25 16:05:30 INFO Vacuumed table table=pending_objects11222026/10/25 16:05:30 INFO Vacuumed table table=multipart_uploads11232026/10/25 16:05:30 INFO Vacuumed table table=closures11242026/10/25 16:05:30 INFO Vacuumed table table=objects1125--- PASS: TestSweepSkipsRowsLockedByPush (1.14s)1126=== CONT TestReadProxyOutlastsServerWriteTimeout11272026/10/25 16:05:30 INFO Aborted multipart uploads count=0 kept=011282026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures11292026/10/25 16:05:30 WARN Force mode enabled - objects will be deleted immediately without grace period11302026/10/25 16:05:30 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=011312026/10/25 16:05:30 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11322026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures11332026/10/25 16:05:30 INFO Vacuumed table table=pending_closures11342026/10/25 16:05:30 INFO Vacuumed table table=pending_objects1135--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.84s)1136=== CONT TestReadProxyHead11372026/10/25 16:05:30 INFO Vacuumed table table=multipart_uploads11382026/10/25 16:05:30 INFO Vacuumed table table=closures11392026/10/25 16:05:30 INFO Vacuumed table table=objects11402026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures1141--- PASS: TestSweepRechecksPendingAfterLocking (1.26s)1142=== CONT TestReadProxyInvalidPath11432026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures11442026/10/25 16:05:30 INFO Received uploads request method=POST path=/api/pending_closures11452026/10/25 16:05:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11462026/10/25 16:05:31 INFO Received uploads request method=POST path=/api/pending_closures11472026/10/25 16:05:31 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LjFlMTBmOTIyLWRlYzEtNDQ0Zi1iYWNiLTM5M2U5MDllYzJiY3gxNzkyOTQ0MzMwOTc4OTE0NjU511482026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes11492026/10/25 16:05:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LjFlMTBmOTIyLWRlYzEtNDQ0Zi1iYWNiLTM5M2U5MDllYzJiY3gxNzkyOTQ0MzMwOTc4OTE0NjU5 parts=11150--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.89s)1151=== CONT TestReadProxy40411522026/10/25 16:05:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11532026/10/25 16:05:31 INFO Signed narinfos id=1 count=111542026/10/25 16:05:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11552026/10/25 16:05:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11562026/10/25 16:05:31 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11572026/10/25 16:05:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11582026/10/25 16:05:31 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11592026/10/25 16:05:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11602026/10/25 16:05:31 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111612026/10/25 16:05:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11622026/10/25 16:05:31 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1163--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.84s)1164=== CONT TestReadProxyNarStreaming1165=== RUN TestPush_RejectsBadRequests/no_roots1166=== PAUSE TestPush_RejectsBadRequests/no_roots1167=== RUN TestPush_RejectsBadRequests/no_objects1168=== PAUSE TestPush_RejectsBadRequests/no_objects1169=== RUN TestPush_RejectsBadRequests/bad_root1170=== PAUSE TestPush_RejectsBadRequests/bad_root1171=== RUN TestPush_RejectsBadRequests/root_not_in_objects1172=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1173=== CONT TestReadProxyContentNegotiation11742026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes1175--- PASS: TestPushWaitsForSweepHoldingRow (1.47s)1176=== CONT TestReadProxyNarinfoAlreadyDecompressed11772026/10/25 16:05:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11782026/10/25 16:05:31 INFO Received complete push request method=POST path=/api/pushes/1/complete11792026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes11802026/10/25 16:05:31 INFO Completed push id=1 objects=4 duration=23.845097ms11812026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes11822026/10/25 16:05:31 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LmVlOWU1ZDVkLTJjMTctNDk3OS04NTU2LTM1NTg2YTdmYTI5MHgxNzkyOTQ0MzMwNjcyODA1ODA5 parts=1011832026/10/25 16:05:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11842026/10/25 16:05:31 INFO Completed upload id=1 objects=2 duration=8.135154ms11852026/10/25 16:05:31 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011862026/10/25 16:05:31 INFO Received uploads request method=POST path=/api/pending_closures11872026/10/25 16:05:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures11882026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes11892026/10/25 16:05:31 INFO Aborted multipart uploads count=0 kept=011902026-10-25 16:05:31.214 UTC [709] ERROR: could not obtain lock on row in relation "closures"11912026-10-25 16:05:31.214 UTC [709] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11922026/10/25 16:05:31 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=011932026-10-25 16:05:31.215 UTC [709] ERROR: could not obtain lock on row in relation "closures"11942026-10-25 16:05:31.215 UTC [709] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11952026-10-25 16:05:31.216 UTC [709] ERROR: could not obtain lock on row in relation "closures"11962026-10-25 16:05:31.216 UTC [709] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11972026-10-25 16:05:31.216 UTC [709] ERROR: could not obtain lock on row in relation "closures"11982026-10-25 16:05:31.216 UTC [709] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11992026-10-25 16:05:31.216 UTC [709] ERROR: could not obtain lock on row in relation "closures"12002026-10-25 16:05:31.216 UTC [709] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12012026/10/25 16:05:31 INFO Vacuumed table table=pending_closures1202--- PASS: TestPush_RootsAreLockedInByteOrder (0.81s)1203=== CONT TestReadProxyNarinfo12042026/10/25 16:05:31 INFO Vacuumed table table=pending_objects12052026/10/25 16:05:31 INFO Vacuumed table table=multipart_uploads12062026/10/25 16:05:31 INFO Aborted multipart uploads count=0 kept=012072026/10/25 16:05:31 INFO Vacuumed table table=closures12082026/10/25 16:05:31 INFO Vacuumed table table=objects12092026/10/25 16:05:31 WARN Force mode enabled - objects will be deleted immediately without grace period12102026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes12112026/10/25 16:05:31 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=012122026/10/25 16:05:31 INFO Vacuumed table table=pending_closures12132026/10/25 16:05:31 INFO Vacuumed table table=pending_objects12142026/10/25 16:05:31 INFO Vacuumed table table=multipart_uploads12152026/10/25 16:05:31 INFO Vacuumed table table=closures12162026/10/25 16:05:31 INFO Vacuumed table table=objects12172026/10/25 16:05:31 INFO Received complete push request method=POST path=/api/pushes/2/complete12182026/10/25 16:05:31 INFO Completed push id=2 objects=4 duration=3.35037ms1219--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.88s)1220=== CONT TestIsValidCachePath1221=== RUN TestIsValidCachePath/narinfo1222=== PAUSE TestIsValidCachePath/narinfo1223=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1224=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1225=== RUN TestIsValidCachePath/nar_zst1226=== PAUSE TestIsValidCachePath/nar_zst1227=== RUN TestIsValidCachePath/nar_xz1228=== PAUSE TestIsValidCachePath/nar_xz1229=== RUN TestIsValidCachePath/nar_bz21230=== PAUSE TestIsValidCachePath/nar_bz21231=== RUN TestIsValidCachePath/nar_uncompressed1232=== PAUSE TestIsValidCachePath/nar_uncompressed1233=== RUN TestIsValidCachePath/ls1234=== PAUSE TestIsValidCachePath/ls1235=== RUN TestIsValidCachePath/log1236=== PAUSE TestIsValidCachePath/log1237=== RUN TestIsValidCachePath/realisation1238=== PAUSE TestIsValidCachePath/realisation1239=== RUN TestIsValidCachePath/nix-cache-info1240=== PAUSE TestIsValidCachePath/nix-cache-info1241=== RUN TestIsValidCachePath/index.html1242=== PAUSE TestIsValidCachePath/index.html1243=== RUN TestIsValidCachePath/traversal_parent1244=== PAUSE TestIsValidCachePath/traversal_parent1245=== RUN TestIsValidCachePath/traversal_in_middle1246=== PAUSE TestIsValidCachePath/traversal_in_middle1247=== RUN TestIsValidCachePath/invalid_char_e1248=== PAUSE TestIsValidCachePath/invalid_char_e1249=== RUN TestIsValidCachePath/invalid_char_u1250=== PAUSE TestIsValidCachePath/invalid_char_u1251=== RUN TestIsValidCachePath/random_path1252=== PAUSE TestIsValidCachePath/random_path1253=== RUN TestIsValidCachePath/empty1254=== PAUSE TestIsValidCachePath/empty1255=== RUN TestIsValidCachePath/leading_slash1256=== PAUSE TestIsValidCachePath/leading_slash1257=== RUN TestIsValidCachePath/wrong_extension1258=== PAUSE TestIsValidCachePath/wrong_extension1259=== RUN TestIsValidCachePath/short_hash1260=== PAUSE TestIsValidCachePath/short_hash1261=== CONT TestCacheStatsHandler12622026/10/25 16:05:31 INFO Received complete push request method=POST path=/api/pushes/1/complete12632026/10/25 16:05:31 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001264--- PASS: TestService_createPendingClosureHandler (1.63s)1265=== CONT TestClientSharedPathCommittedMidPush12662026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes12672026/10/25 16:05:31 INFO Completed push id=1 objects=4 duration=13.338962ms1268--- PASS: TestPush_RepeatedRootCommitsOnce (0.84s)1269=== CONT TestClientWithDependencies12702026/10/25 16:05:31 INFO Received complete push request method=POST path=/api/pushes/1/complete12712026/10/25 16:05:31 INFO Received push request method=POST path=/api/pushes12722026/10/25 16:05:31 INFO Completed push id=1 objects=6 duration=12.865718ms1273--- PASS: TestPush_CompleteCommitsEveryRoot (0.88s)1274=== CONT TestClientMultipleUploads1275--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.89s)1276=== CONT TestClientIntegration12772026/10/25 16:05:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1278--- PASS: TestReadRedirectUsesPublicS3URL (0.90s)1279=== CONT TestClientErrorHandling1280=== RUN TestClientErrorHandling/InvalidStorePath1281=== PAUSE TestClientErrorHandling/InvalidStorePath1282=== RUN TestClientErrorHandling/InvalidAuthToken1283=== PAUSE TestClientErrorHandling/InvalidAuthToken1284=== RUN TestClientErrorHandling/ServerNotAvailable1285=== PAUSE TestClientErrorHandling/ServerNotAvailable1286=== CONT TestClientCADerivations12872026/10/25 16:05:31 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LjY1ZjRjM2Q4LWViODUtNDJiYy1iMzFlLTNjZTliMDg3YjU3NngxNzkyOTQ0MzMwOTE5ODM1MDgx parts=1212882026/10/25 16:05:31 INFO Received uploads request method=POST path=/api/pending_closures1289--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.33s)1290=== CONT TestObjectStatsUpdatedOncePerCommit1291--- PASS: TestReadProxyRangeRequest (0.92s)1292=== CONT TestPresentNotReportedWhileGCDeletesClosure1293=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1294=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1295=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1296=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1297=== CONT TestPresentRefreshesOnlyStaleClosures12982026/10/25 16:05:31 INFO Received uploads request method=POST path=/api/pending_closures12992026/10/25 16:05:31 INFO Aborted multipart uploads count=0 kept=013002026/10/25 16:05:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13012026/10/25 16:05:31 WARN Force mode enabled - objects will be deleted immediately without grace period13022026/10/25 16:05:31 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=013032026-10-25 16:05:31.528 UTC [712] ERROR: Push does not exist: id=113042026-10-25 16:05:31.528 UTC [712] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13052026-10-25 16:05:31.528 UTC [712] STATEMENT: SELECT commit_push($1)1306--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.11s)1307=== CONT TestPresentReportsOnlyClosureRoots13082026/10/25 16:05:31 INFO Vacuumed table table=pending_closures13092026/10/25 16:05:31 INFO Vacuumed table table=pending_objects13102026/10/25 16:05:31 INFO Vacuumed table table=multipart_uploads13112026/10/25 16:05:31 INFO Vacuumed table table=closures13122026/10/25 16:05:31 INFO Vacuumed table table=objects1313--- PASS: TestGCSweepSkipsPendingObjects (1.05s)1314=== CONT TestCreatePin_ReservedPins1315--- PASS: TestReadRedirectNar (1.01s)1316=== CONT TestOrphanedObjectsGCStressTest13172026/10/25 16:05:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LmI0MDhhMGI5LWE5MTktNGQ3OS04ODFjLTI4Y2YyMTliY2YxOHgxNzkyOTQ0MzMxMDA5NzIwMDc5 parts=1213182026/10/25 16:05:31 INFO Received uploads request method=POST path=/api/pending_closures1319--- PASS: TestReadProxyDisabled (0.99s)1320=== CONT TestOrphanedObjectsGC13212026/10/25 16:05:31 INFO Received uploads request method=POST path=/api/pending_closures13222026/10/25 16:05:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44853/oidc1323--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.97s)1324=== CONT TestService_AuthMiddleware_OIDC1325--- PASS: TestObjectStatsUpdatedOncePerCommit (0.34s)1326=== CONT TestPinProtectsFromGC1327--- PASS: TestReadProxyConditionalGet (1.03s)1328=== CONT TestPushDedupSurvivesConcurrentGC1329--- PASS: TestReadProxyHead (0.93s)1330=== CONT TestGCMetrics1331--- PASS: TestReadProxyInvalidPath (0.94s)1332=== CONT TestGCBugBareHashReferences13332026/10/25 16:05:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46685/oidc1334--- PASS: TestReadProxy404 (0.87s)1335=== CONT TestCacheConfigHandler1336=== RUN TestCacheConfigHandler/full_config,_no_issuer1337=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1338=== RUN TestCacheConfigHandler/no_cache_url_configured1339=== PAUSE TestCacheConfigHandler/no_cache_url_configured1340=== RUN TestCacheConfigHandler/no_signing_keys1341=== PAUSE TestCacheConfigHandler/no_signing_keys1342=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1343=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1344=== CONT TestGCAdvisoryLockBlocksConcurrentRun1345--- PASS: TestReadProxyNarStreaming (0.89s)1346=== CONT TestService_ReadScope_PublicByDefault1347--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.86s)1348=== CONT TestLeadEndsOnShutdown1349--- PASS: TestReadProxyContentNegotiation (0.93s)1350=== CONT TestService_RequireScope_OIDC1351--- PASS: TestCacheStatsHandler (0.80s)1352=== CONT TestLeadIncumbentAnnouncesAtOnce13532026/10/25 16:05:32 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1354--- PASS: TestReadProxyNarinfo (0.86s)1355=== CONT TestLeadElectsOneAndHandsOver13562026/10/25 16:05:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43653/oidc13572026/10/25 16:05:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13582026/10/25 16:05:32 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LmQ2OWE2M2E0LTBiMjItNGEyYy1hZTFkLWY1NjY3YjZlZmFmYngxNzkyOTQ0MzMxNjc4Mjk3MTUy error="Get \"http://127.0.0.1:1/bucket31/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13592026/10/25 16:05:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzcxYjk5ZGYtZDNjMi00OWY5LWEyZjAtZTg0OGUxMTY0YzU0LjIxZDcwYThmLTY3MWUtNDY0Mi1hMzA3LWNmYzVmMDYzY2RhMngxNzkyOTQ0MzMxNjY4NDE0NjAy parts=1213602026/10/25 16:05:32 INFO Received cleanup request method=DELETE path=/api/pending_closures13612026/10/25 16:05:32 INFO Aborted multipart uploads count=1 kept=01362--- PASS: TestRedundantMultipartUpload (2.03s)1363=== CONT TestMultipartCleanup1364=== NAME TestClientMultipleUploads1365 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3542352186/001/store/w0dj6qipv17w4l1vns3q8amvpz67w991-test-file-0.txt13662026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes13672026/10/25 16:05:32 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)13682026/10/25 16:05:32 INFO Uploading flg524bzfp9k61dq6hz42q5n8w1n5k9v-top (224B)13692026/10/25 16:05:32 INFO Uploading 7nxpb6f27ccgixnpgbp4mrhf85ddfd72-shared-dep (136B)13702026/10/25 16:05:32 WARN Failed to register uploaded object key=flg524bzfp9k61dq6hz42q5n8w1n5k9v.ls error="server returned 404: 404 page not found\n"1371=== NAME TestClientWithDependencies1372 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies341408526/001/store/vidp3c3m509i3cjpd8nl5fqxsx93fjkq-test-script13732026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13742026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/1gjlk5a03y1cqa3fva57xzq5cijjcr7rwbd8mgq9yz68jfqflw2z.nar.zst error="server returned 404: 404 page not found\n"13752026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13762026/10/25 16:05:32 WARN Failed to register uploaded object key=7nxpb6f27ccgixnpgbp4mrhf85ddfd72.ls error="server returned 404: 404 page not found\n"13772026/10/25 16:05:32 INFO Signed narinfos id=1 count=21378=== NAME TestClientIntegration13792026/10/25 16:05:32 INFO Uploading 2 narinfos1380 client_integration_test.go:286: Created store path: /build/TestClientIntegration2734921694/002/store/55iydb8phiv4w986k2x9zf52gwsnyvnq-test-file.txt13812026/10/25 16:05:32 WARN Failed to register uploaded object key=flg524bzfp9k61dq6hz42q5n8w1n5k9v.narinfo error="server returned 404: 404 page not found\n"13822026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/1/complete13832026/10/25 16:05:32 WARN Failed to register uploaded object key=7nxpb6f27ccgixnpgbp4mrhf85ddfd72.narinfo error="server returned 404: 404 page not found\n"1384=== NAME TestClientMultipleUploads1385 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3542352186/001/store/11fvmp5awzld62g5r3w8qcxqq7apvhpc-test-file-1.txt13862026/10/25 16:05:32 INFO Completed push id=1 objects=6 duration=8.614699ms13872026/10/25 16:05:32 INFO Upload complete. (78ms)1388=== NAME TestClientSharedPathCommittedMidPush1389 client_integration_test.go:680: Retrieved narinfo from S3:1390 StorePath: /build/TestClientSharedPathCommittedMidPush2666857843/001/store/7nxpb6f27ccgixnpgbp4mrhf85ddfd72-shared-dep1391 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1392 Compression: zstd1393 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821394 NarSize: 1361395 References: 1396 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1397--- PASS: TestPresentRefreshesOnlyStaleClosures (0.86s)1398=== CONT TestConnectWaitsForAPeerMigration1399=== NAME TestClientSharedPathCommittedMidPush1400 client_integration_test.go:680: Retrieved narinfo from S3:1401 StorePath: /build/TestClientSharedPathCommittedMidPush2666857843/001/store/flg524bzfp9k61dq6hz42q5n8w1n5k9v-top1402 URL: nar/1gjlk5a03y1cqa3fva57xzq5cijjcr7rwbd8mgq9yz68jfqflw2z.nar.zst1403 Compression: zstd1404 NarHash: sha256:1gjlk5a03y1cqa3fva57xzq5cijjcr7rwbd8mgq9yz68jfqflw2z1405 NarSize: 2241406 References: /build/TestClientSharedPathCommittedMidPush2666857843/001/store/7nxpb6f27ccgixnpgbp4mrhf85ddfd72-shared-dep1407 CA: text:sha256:0cz2n3n955yiskc5mg64daxlmdrmb8shk94r8nlsy74yk7xw1fdf1408--- PASS: TestClientSharedPathCommittedMidPush (1.01s)1409=== CONT TestObjectStatsTrigger1410=== NAME TestClientWithDependencies1411 client_integration_test.go:615: Found 1 dependencies (including self)1412=== NAME TestClientMultipleUploads1413 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3542352186/001/store/870xic1pwzx9gkih7idg3fvm7hxiiwk1-test-file-2.txt1414--- PASS: TestPresentReportsOnlyClosureRoots (0.79s)1415=== CONT TestResolveDBConnectionString1416=== RUN TestResolveDBConnectionString/flag_wins1417=== PAUSE TestResolveDBConnectionString/flag_wins1418=== RUN TestResolveDBConnectionString/file_when_flag_empty1419=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1420=== RUN TestResolveDBConnectionString/missing_file_is_an_error1421=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1422=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1423=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1424=== RUN TestResolveDBConnectionString/nothing_configured1425=== PAUSE TestResolveDBConnectionString/nothing_configured1426=== CONT TestPendingCleanupUsesOneCutoff14272026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes14282026/10/25 16:05:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14292026/10/25 16:05:32 INFO Uploading 55iydb8phiv4w986k2x9zf52gwsnyvnq-test-file.txt (152B)1430=== NAME TestClientCADerivations1431 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1006267932/001/store/adbwjajylhd40srrzdh0pjawr7a46xlx-ca-test14322026/10/25 16:05:32 WARN Failed to register uploaded object key=55iydb8phiv4w986k2x9zf52gwsnyvnq.ls error="server returned 404: 404 page not found\n"14332026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14342026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14352026/10/25 16:05:32 INFO Signed narinfos id=1 count=114362026/10/25 16:05:32 INFO Uploading 1 narinfos14372026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/1/complete14382026/10/25 16:05:32 WARN Failed to register uploaded object key=55iydb8phiv4w986k2x9zf52gwsnyvnq.narinfo error="server returned 404: 404 page not found\n"14392026/10/25 16:05:32 INFO Completed push id=1 objects=3 duration=9.620047ms14402026/10/25 16:05:32 INFO Upload complete. (73ms)14412026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes1442 client_ca_test.go:139: Found 1 dependencies (including self)14432026/10/25 16:05:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14442026/10/25 16:05:32 INFO Uploading vidp3c3m509i3cjpd8nl5fqxsx93fjkq-test-script (136B)14452026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes14462026/10/25 16:05:32 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14472026/10/25 16:05:32 INFO Uploading 870xic1pwzx9gkih7idg3fvm7hxiiwk1-test-file-2.txt (160B)14482026/10/25 16:05:32 INFO Uploading w0dj6qipv17w4l1vns3q8amvpz67w991-test-file-0.txt (160B)14492026/10/25 16:05:32 INFO Uploading 11fvmp5awzld62g5r3w8qcxqq7apvhpc-test-file-1.txt (160B)14502026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14512026/10/25 16:05:32 WARN Failed to register uploaded object key=vidp3c3m509i3cjpd8nl5fqxsx93fjkq.ls error="server returned 404: 404 page not found\n"14522026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14532026/10/25 16:05:32 INFO Signed narinfos id=1 count=114542026/10/25 16:05:32 INFO Uploading 1 narinfos14552026/10/25 16:05:32 WARN Failed to register uploaded object key=log/q03088kbk4nhals61mi66134h6pavzhw-test-script.drv error="server returned 404: 404 page not found\n"14562026/10/25 16:05:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14572026/10/25 16:05:32 WARN Refused reserved pin name=worker-x86_64-linux14582026/10/25 16:05:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14592026/10/25 16:05:32 INFO Received create pin request method=POST path=/api/pins/my-app14602026/10/25 16:05:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1461--- PASS: TestCreatePin_ReservedPins (0.82s)1462=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock14632026/10/25 16:05:32 INFO All 1 paths already cached1464=== NAME TestClientIntegration1465 client_integration_test.go:312: Retrieved narinfo from S3:1466 StorePath: /build/TestClientIntegration2734921694/002/store/55iydb8phiv4w986k2x9zf52gwsnyvnq-test-file.txt1467 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1468 Compression: zstd1469 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11470 NarSize: 1521471 References: 14722026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"1473 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk114742026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14752026/10/25 16:05:32 WARN Failed to register uploaded object key=w0dj6qipv17w4l1vns3q8amvpz67w991.ls error="server returned 404: 404 page not found\n"14762026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/1/complete14772026/10/25 16:05:32 WARN Failed to register uploaded object key=vidp3c3m509i3cjpd8nl5fqxsx93fjkq.narinfo error="server returned 404: 404 page not found\n"14782026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14792026/10/25 16:05:32 WARN Failed to register uploaded object key=870xic1pwzx9gkih7idg3fvm7hxiiwk1.ls error="server returned 404: 404 page not found\n"14802026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14812026/10/25 16:05:32 WARN Failed to register uploaded object key=11fvmp5awzld62g5r3w8qcxqq7apvhpc.ls error="server returned 404: 404 page not found\n"14822026/10/25 16:05:32 INFO Signed narinfos id=1 count=314832026/10/25 16:05:32 INFO Uploading 3 narinfos1484 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1485 client_integration_test.go:313: Decompressed .ls content (64 bytes):1486 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1487 client_integration_test.go:316: Testing garbage collection...14882026/10/25 16:05:32 WARN Failed to register uploaded object key=11fvmp5awzld62g5r3w8qcxqq7apvhpc.narinfo error="server returned 404: 404 page not found\n"14892026/10/25 16:05:32 WARN Failed to register uploaded object key=w0dj6qipv17w4l1vns3q8amvpz67w991.narinfo error="server returned 404: 404 page not found\n"14902026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/1/complete14912026/10/25 16:05:32 WARN Failed to register uploaded object key=870xic1pwzx9gkih7idg3fvm7hxiiwk1.narinfo error="server returned 404: 404 page not found\n"14922026/10/25 16:05:32 INFO Completed push id=1 objects=4 duration=8.836981ms14932026/10/25 16:05:32 INFO Upload complete. (124ms)1494=== NAME TestClientWithDependencies1495 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies341408526/001/store) requires matching store prefix1496--- PASS: TestClientWithDependencies (1.18s)1497=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded14982026/10/25 16:05:32 INFO Completed push id=1 objects=9 duration=8.412456ms14992026/10/25 16:05:32 INFO Upload complete. (116ms)1500=== NAME TestClientMultipleUploads1501 client_integration_test.go:369: Uploaded 3 paths in 153.309817ms1502--- PASS: TestClientMultipleUploads (1.15s)1503=== CONT TestDeleteClosuresRacingPins15042026/10/25 16:05:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures15052026/10/25 16:05:32 INFO Garbage collection started15062026/10/25 16:05:32 INFO Aborted multipart uploads count=0 kept=015072026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes15082026/10/25 16:05:32 WARN Force mode enabled - objects will be deleted immediately without grace period15092026/10/25 16:05:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15102026/10/25 16:05:32 INFO Uploading adbwjajylhd40srrzdh0pjawr7a46xlx-ca-test (144B)15112026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15122026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15132026/10/25 16:05:32 WARN Failed to register uploaded object key=log/784snh5sckvk3zshi2y6h5fj62ji62n9-ca-test.drv error="server returned 404: 404 page not found\n"15142026/10/25 16:05:32 INFO Signed narinfos id=1 count=115152026/10/25 16:05:32 INFO Uploading 1 narinfos15162026/10/25 16:05:32 WARN Failed to register uploaded object key=adbwjajylhd40srrzdh0pjawr7a46xlx.ls error="server returned 404: 404 page not found\n"15172026/10/25 16:05:32 INFO Received uploads request method=POST path=/api/pending_closures15182026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/1/complete15192026/10/25 16:05:32 WARN Failed to register uploaded object key=adbwjajylhd40srrzdh0pjawr7a46xlx.narinfo error="server returned 404: 404 page not found\n"15202026/10/25 16:05:32 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=015212026/10/25 16:05:32 INFO Vacuumed table table=pending_closures15222026/10/25 16:05:32 INFO Completed push id=1 objects=4 duration=7.76089ms15232026/10/25 16:05:32 INFO Upload complete. (119ms)15242026/10/25 16:05:32 INFO Aborted multipart uploads count=0 kept=015252026/10/25 16:05:32 INFO Vacuumed table table=pending_objects15262026/10/25 16:05:32 INFO Vacuumed table table=multipart_uploads1527=== NAME TestClientCADerivations1528 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1006267932/001/store/adbwjajylhd40srrzdh0pjawr7a46xlx-ca-test1529 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1530 Compression: zstd1531 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1532 NarSize: 1441533 References: 1534 Deriver: /build/TestClientCADerivations1006267932/001/store/784snh5sckvk3zshi2y6h5fj62ji62n9-ca-test.drv1535 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1536 client_ca_test.go:185: Checking for realisation files in S3...15372026/10/25 16:05:32 INFO Vacuumed table table=closures1538 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1539 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15402026/10/25 16:05:32 INFO Vacuumed table table=objects15412026/10/25 16:05:32 WARN Force mode enabled - objects will be deleted immediately without grace period15422026/10/25 16:05:32 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=015432026/10/25 16:05:32 INFO Vacuumed table table=pending_closures15442026/10/25 16:05:32 INFO Vacuumed table table=pending_objects15452026/10/25 16:05:32 INFO Vacuumed table table=multipart_uploads1546=== NAME TestPinProtectsFromGC1547 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3501816181/001/store/061gpyvkgy6r32ljclrm3bhzw1k96fkj-pinned-file.txt15482026/10/25 16:05:32 INFO Vacuumed table table=closures1549 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3501816181/001/store/g0cq23v82h4i55qsxwl7ml2pbv81gpwa-unpinned-file.txt15502026/10/25 16:05:32 INFO Vacuumed table table=objects1551--- PASS: TestGCMetrics (0.73s)1552=== CONT TestClientFallsBackToClosures15532026/10/25 16:05:32 INFO Aborted multipart uploads count=0 kept=015542026/10/25 16:05:32 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"1555--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.70s)1556=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15572026/10/25 16:05:32 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=015582026/10/25 16:05:32 INFO Vacuumed table table=pending_closures1559=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1560=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1561=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1562=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1563=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1564=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1565=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1566=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1567=== CONT TestClientPushesUseOnePush15682026/10/25 16:05:32 INFO Vacuumed table table=pending_objects15692026/10/25 16:05:32 INFO Vacuumed table table=multipart_uploads15702026/10/25 16:05:32 INFO Vacuumed table table=closures15712026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes15722026/10/25 16:05:32 INFO Vacuumed table table=objects15732026/10/25 16:05:32 INFO Aborted multipart uploads count=0 kept=015742026/10/25 16:05:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15752026/10/25 16:05:32 INFO Uploading 061gpyvkgy6r32ljclrm3bhzw1k96fkj-pinned-file.txt (128B)15762026/10/25 16:05:32 WARN Force mode enabled - objects will be deleted immediately without grace period15772026/10/25 16:05:32 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=01578=== NAME TestClientCADerivations1579 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1580 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1581 error: binary cache 's3://bucket60?endpoint=http://localhost:34165®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1006267932/001/store'1582 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11583--- PASS: TestClientCADerivations (1.27s)1584=== CONT TestService_ReadAuthMiddleware15852026/10/25 16:05:32 INFO Vacuumed table table=pending_closures15862026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15872026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15882026/10/25 16:05:32 WARN Failed to register uploaded object key=061gpyvkgy6r32ljclrm3bhzw1k96fkj.ls error="server returned 404: 404 page not found\n"15892026/10/25 16:05:32 INFO Signed narinfos id=1 count=115902026/10/25 16:05:32 INFO Uploading 1 narinfos15912026/10/25 16:05:32 INFO Vacuumed table table=pending_objects15922026/10/25 16:05:32 INFO Vacuumed table table=multipart_uploads1593--- PASS: TestService_ReadScope_PublicByDefault (0.71s)1594=== CONT TestService_AuthMiddleware_MTLSProxyHeader15952026/10/25 16:05:32 INFO Vacuumed table table=closures15962026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/1/complete15972026/10/25 16:05:32 WARN Failed to register uploaded object key=061gpyvkgy6r32ljclrm3bhzw1k96fkj.narinfo error="server returned 404: 404 page not found\n"15982026/10/25 16:05:32 INFO Vacuumed table table=objects1599--- PASS: TestPushDedupSurvivesConcurrentGC (0.88s)1600=== CONT TestService_NativeMTLS16012026/10/25 16:05:32 INFO Completed push id=1 objects=3 duration=7.816031ms16022026/10/25 16:05:32 INFO Upload complete. (76ms)16032026/10/25 16:05:32 INFO lead: acquired remote=192.0.2.1:123416042026/10/25 16:05:32 INFO lead: acquired remote=192.0.2.1:123416052026/10/25 16:05:32 INFO lead: released remote=192.0.2.1:12341606--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.65s)1607=== CONT TestMetricsCommit16082026/10/25 16:05:32 INFO Received push request method=POST path=/api/pushes16092026/10/25 16:05:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16102026/10/25 16:05:32 INFO Uploading g0cq23v82h4i55qsxwl7ml2pbv81gpwa-unpinned-file.txt (128B)16112026/10/25 16:05:32 WARN Failed to register uploaded object key=g0cq23v82h4i55qsxwl7ml2pbv81gpwa.ls error="server returned 404: 404 page not found\n"16122026/10/25 16:05:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16132026/10/25 16:05:32 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16142026/10/25 16:05:32 INFO Signed narinfos id=2 count=116152026/10/25 16:05:32 INFO Uploading 1 narinfos1616=== NAME TestOrphanedObjectsGC1617 orphaned_objects_gc_test.go:287: GC Test Summary:1618 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1619 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1620 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1621 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1622 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1623--- PASS: TestOrphanedObjectsGC (1.10s)1624=== CONT TestServerTLSConfig1625=== RUN TestServerTLSConfig/no_client_CA1626=== PAUSE TestServerTLSConfig/no_client_CA1627=== RUN TestServerTLSConfig/missing_CA_file1628=== PAUSE TestServerTLSConfig/missing_CA_file1629=== RUN TestServerTLSConfig/not_a_PEM_file1630=== PAUSE TestServerTLSConfig/not_a_PEM_file1631=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1632=== RUN TestService_RequireScope_OIDC/builder_may_write1633=== PAUSE TestService_RequireScope_OIDC/builder_may_write1634=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1635=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1636=== RUN TestService_RequireScope_OIDC/ops_may_admin1637=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1638=== RUN TestService_RequireScope_OIDC/ops_may_not_write1639=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1640=== RUN TestService_RequireScope_OIDC/reader_may_not_write1641=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1642=== RUN TestService_RequireScope_OIDC/static_token_may_admin1643=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1644=== RUN TestService_RequireScope_OIDC/static_token_may_write1645=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1646=== RUN TestService_RequireScope_OIDC/reader_may_read1647=== PAUSE TestService_RequireScope_OIDC/reader_may_read1648=== RUN TestService_RequireScope_OIDC/writer_implies_read1649=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1650=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1651=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1652=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1653=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1654=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1655=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1656=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1657=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1658=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1659=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1660=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check16612026/10/25 16:05:32 INFO Received complete push request method=POST path=/api/pushes/2/complete16622026/10/25 16:05:32 WARN Failed to register uploaded object key=g0cq23v82h4i55qsxwl7ml2pbv81gpwa.narinfo error="server returned 404: 404 page not found\n"16632026/10/25 16:05:32 INFO Completed push id=2 objects=3 duration=3.056648ms16642026/10/25 16:05:32 INFO Upload complete. (68ms)1665--- PASS: TestGCBugBareHashReferences (0.94s)1666=== CONT TestGCEndsOnShutdown/before_the_run16672026/10/25 16:05:32 INFO lead: acquired remote=192.0.2.1:123416682026/10/25 16:05:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures16692026/10/25 16:05:32 INFO Garbage collection started16702026/10/25 16:05:32 INFO Received uploads request method=POST path=/api/pending_closures16712026/10/25 16:05:32 INFO Aborted multipart uploads count=0 kept=016722026/10/25 16:05:32 WARN Force mode enabled - objects will be deleted immediately without grace period16732026/10/25 16:05:32 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=016742026/10/25 16:05:32 INFO Vacuumed table table=pending_closures16752026/10/25 16:05:32 INFO Vacuumed table table=pending_objects16762026/10/25 16:05:32 INFO Vacuumed table table=multipart_uploads16772026/10/25 16:05:32 INFO Vacuumed table table=closures16782026/10/25 16:05:32 INFO Vacuumed table table=objects1679--- PASS: TestObjectStatsTrigger (0.68s)1680=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark16812026/10/25 16:05:32 INFO Received cleanup request method=DELETE path=/api/pending_closures16822026/10/25 16:05:32 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket78/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""16832026/10/25 16:05:32 INFO Aborted multipart uploads count=0 kept=116842026/10/25 16:05:32 INFO Received uploads request method=POST path=/api/pending_closures16852026/10/25 16:05:33 INFO Received cleanup request method=DELETE path=/api/pending_closures16862026/10/25 16:05:33 INFO Aborted multipart uploads count=1 kept=01687--- PASS: TestMultipartCleanup (0.81s)1688=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete16892026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures16902026/10/25 16:05:33 INFO Received cleanup request method=DELETE path=/api/pending_closures16912026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures1692--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.62s)1693=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16942026/10/25 16:05:33 INFO Received uploads request method=POST path=/1695=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16962026/10/25 16:05:33 INFO Received complete multipart upload request method=POST path=/1697=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16982026/10/25 16:05:33 INFO Received uploads request method=POST path=/1699=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17002026/10/25 16:05:33 INFO Received request for more parts method=POST path=/1701--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1702 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1703 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1704 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1705 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1706=== CONT TestIsValidUploadKey/empty_key1707=== CONT TestIsValidUploadKey/narinfo1708=== CONT TestIsValidUploadKey/absolute1709=== CONT TestIsValidUploadKey/traversal_nar1710=== CONT TestIsValidUploadKey/traversal1711=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1712=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1713=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1714=== CONT TestIsValidUploadKey/index.html1715=== CONT TestIsValidUploadKey/nix-cache-info1716=== CONT TestIsValidUploadKey/realisation_plus_in_output1717=== CONT TestIsValidUploadKey/realisation1718=== CONT TestIsValidUploadKey/build_log_equals1719=== CONT TestIsValidUploadKey/build_log_question_mark1720=== CONT TestIsValidUploadKey/build_log_plus_in_name1721=== CONT TestIsValidUploadKey/build_log_home-manager_file1722=== CONT TestIsValidUploadKey/build_log1723=== CONT TestIsValidUploadKey/unknown_type1724=== CONT TestIsValidUploadKey/listing1725=== CONT TestIsValidUploadKey/nar_zst1726=== CONT TestIsValidUploadKey/nar_xz1727=== CONT TestIsValidUploadKey/nar_plain1728--- PASS: TestIsValidUploadKey (0.00s)1729 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1730 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1731 --- PASS: TestIsValidUploadKey/absolute (0.00s)1732 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1733 --- PASS: TestIsValidUploadKey/traversal (0.00s)1734 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1735 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1736 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1737 --- PASS: TestIsValidUploadKey/index.html (0.00s)1738 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1739 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1740 --- PASS: TestIsValidUploadKey/realisation (0.00s)1741 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1742 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1743 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1744 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1745 --- PASS: TestIsValidUploadKey/build_log (0.00s)1746 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1747 --- PASS: TestIsValidUploadKey/listing (0.00s)1748 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1749 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1750 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1751=== CONT TestPendingClosureWriteTimeout/empty1752=== CONT TestPendingClosureWriteTimeout/670k_objects1753=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17542026/10/25 16:05:33 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17552026/10/25 16:05:33 WARN mTLS auth: bound subjects configured but subject DN unavailable17562026/10/25 16:05:33 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1757--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.54s)1758=== CONT TestPendingClosureWriteTimeout/400_objects1759=== CONT TestProxyWriteTimeout/narinfo1760=== CONT TestProxyWriteTimeout/unknown_size1761=== CONT TestProxyWriteTimeout/10_GiB_nar1762=== CONT TestProxyWriteTimeout/1_GiB_nar1763=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17642026/10/25 16:05:33 INFO Received uploads request method=POST path=/1765--- PASS: TestProxyWriteTimeout (0.00s)1766 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1767 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1768 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1769 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1770--- PASS: TestService_ReadAuthMiddleware (0.56s)1771=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17722026/10/25 16:05:33 INFO Received request for more parts method=POST path=/17732026/10/25 16:05:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17742026/10/25 16:05:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1775--- PASS: TestService_NativeMTLS (0.58s)1776=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17772026/10/25 16:05:33 INFO Received complete multipart upload request method=POST path=/1778--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.62s)1779=== CONT TestParseSingleRange/none1780=== CONT TestParseSingleRange/open-ended1781=== CONT TestParseSingleRange/closed1782=== CONT TestParseSingleRange/malformed_end_before_start1783=== CONT TestParseSingleRange/malformed_both_empty1784=== CONT TestParseSingleRange/malformed_no_dash1785=== CONT TestParseSingleRange/multi-range_ignored1786=== CONT TestParseSingleRange/unknown_unit1787=== CONT TestParseSingleRange/end_clamped_to_size1788=== CONT TestParseSingleRange/start_past_EOF1789=== CONT TestParseSingleRange/single_byte1790=== CONT TestParseSingleRange/suffix_exceeds_size1791=== CONT TestParseSingleRange/suffix1792=== CONT TestParseSingleRange/start_far_past_EOF1793=== CONT TestPush_RejectsBadRequests/no_roots1794--- PASS: TestParseSingleRange (0.00s)1795 --- PASS: TestParseSingleRange/none (0.00s)1796 --- PASS: TestParseSingleRange/open-ended (0.00s)1797 --- PASS: TestParseSingleRange/closed (0.00s)1798 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1799 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1800 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1801 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1802 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1803 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1804 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1805 --- PASS: TestParseSingleRange/single_byte (0.00s)1806 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1807 --- PASS: TestParseSingleRange/suffix (0.00s)1808 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)18092026/10/25 16:05:33 INFO Received push request method=POST path=/api/pushes1810=== CONT TestPush_RejectsBadRequests/root_not_in_objects18112026/10/25 16:05:33 INFO Received push request method=POST path=/api/pushes1812=== CONT TestPush_RejectsBadRequests/bad_root18132026/10/25 16:05:33 INFO Received push request method=POST path=/api/pushes1814=== CONT TestPush_RejectsBadRequests/no_objects18152026/10/25 16:05:33 INFO Received push request method=POST path=/api/pushes1816--- PASS: TestPush_RejectsBadRequests (0.68s)1817 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1818 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1819 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1820 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1821=== CONT TestIsValidCachePath/narinfo1822=== CONT TestIsValidCachePath/index.html1823=== CONT TestIsValidCachePath/short_hash1824=== CONT TestIsValidCachePath/wrong_extension1825=== CONT TestIsValidCachePath/leading_slash1826=== CONT TestIsValidCachePath/empty1827=== CONT TestIsValidCachePath/random_path1828=== CONT TestIsValidCachePath/invalid_char_u1829=== CONT TestIsValidCachePath/invalid_char_e1830=== CONT TestIsValidCachePath/traversal_in_middle1831=== CONT TestIsValidCachePath/traversal_parent1832=== CONT TestIsValidCachePath/nar_uncompressed1833=== CONT TestIsValidCachePath/nix-cache-info1834=== CONT TestIsValidCachePath/realisation1835=== CONT TestIsValidCachePath/log1836=== CONT TestIsValidCachePath/ls1837=== CONT TestIsValidCachePath/nar_xz1838=== CONT TestIsValidCachePath/nar_bz21839=== CONT TestIsValidCachePath/nar_zst1840=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1841--- PASS: TestIsValidCachePath (0.00s)1842 --- PASS: TestIsValidCachePath/narinfo (0.00s)1843 --- PASS: TestIsValidCachePath/index.html (0.00s)1844 --- PASS: TestIsValidCachePath/short_hash (0.00s)1845 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1846 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1847 --- PASS: TestIsValidCachePath/empty (0.00s)1848 --- PASS: TestIsValidCachePath/random_path (0.00s)1849 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1850 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1851 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1852 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1853 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1854 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1855 --- PASS: TestIsValidCachePath/realisation (0.00s)1856 --- PASS: TestIsValidCachePath/log (0.00s)1857 --- PASS: TestIsValidCachePath/ls (0.00s)1858 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1859 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1860 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1861 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1862=== CONT TestClientErrorHandling/InvalidStorePath1863=== CONT TestClientErrorHandling/ServerNotAvailable18642026/10/25 16:05:33 INFO Received push request method=POST path=/api/pushes1865=== CONT TestClientErrorHandling/InvalidAuthToken18662026/10/25 16:05:33 INFO Received complete push request method=POST path=/api/pushes/1/complete1867--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.92s)1868=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18692026/10/25 16:05:33 INFO Completed push id=1 objects=4 duration=10.052432ms18702026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures18712026/10/25 16:05:33 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18722026/10/25 16:05:33 INFO Completed upload id=2 objects=2 duration=2.070259ms1873--- PASS: TestMetricsCommit (0.62s)1874=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18752026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures18762026/10/25 16:05:33 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18772026/10/25 16:05:33 INFO Uploading 9i9pb2a6m20npjqjafzi83sdm9vvw9gm-a (216B)18782026/10/25 16:05:33 INFO Uploading 5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2-shared-dep (136B)18792026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures18802026/10/25 16:05:33 WARN Failed to register uploaded object key=5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2.ls error="server returned 404: 404 page not found\n"18812026/10/25 16:05:33 WARN Failed to register uploaded object key=9i9pb2a6m20npjqjafzi83sdm9vvw9gm.ls error="server returned 404: 404 page not found\n"18822026/10/25 16:05:33 WARN Failed to register uploaded object key=nar/1q5yd26b6r9kijsh9gwqs9bi8195fx23r49j7hf0pmjykzv51qrr.nar.zst error="server returned 404: 404 page not found\n"18832026/10/25 16:05:33 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18842026/10/25 16:05:33 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18852026/10/25 16:05:33 WARN Failed to register uploaded object key=a3i3hs8khx9v1qxnmw2rpcb35ivfri18.ls error="server returned 404: 404 page not found\n"18862026/10/25 16:05:33 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/present18872026/10/25 16:05:33 INFO Signed narinfos id=1 count=218882026/10/25 16:05:33 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18892026/10/25 16:05:33 INFO Signed narinfos id=2 count=218902026/10/25 16:05:33 INFO Uploading 4 narinfos18912026/10/25 16:05:33 WARN Failed to register uploaded object key=5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2.narinfo error="server returned 404: 404 page not found\n"18922026/10/25 16:05:33 WARN Failed to register uploaded object key=a3i3hs8khx9v1qxnmw2rpcb35ivfri18.narinfo error="server returned 404: 404 page not found\n"18932026/10/25 16:05:33 WARN Failed to register uploaded object key=9i9pb2a6m20npjqjafzi83sdm9vvw9gm.narinfo error="server returned 404: 404 page not found\n"18942026/10/25 16:05:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18952026/10/25 16:05:33 WARN Failed to register uploaded object key=5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2.narinfo error="server returned 404: 404 page not found\n"18962026/10/25 16:05:33 INFO Aborted multipart uploads count=0 kept=018972026/10/25 16:05:33 INFO Received push request method=POST path=/api/pushes18982026/10/25 16:05:33 INFO Completed upload id=1 objects=6 duration=6.853742ms18992026/10/25 16:05:33 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19002026/10/25 16:05:33 INFO Completed upload id=2 objects=6 duration=2.872626ms19012026/10/25 16:05:33 INFO Upload complete. (98ms)19022026/10/25 16:05:33 WARN Force mode enabled - objects will be deleted immediately without grace period1903=== NAME TestClientFallsBackToClosures1904 client_pushes_test.go:112: Retrieved narinfo from S3:1905 StorePath: /build/TestClientFallsBackToClosures153172439/001/store/5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2-shared-dep1906 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1907 Compression: zstd1908 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821909 NarSize: 1361910 References: 1911 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n19122026/10/25 16:05:33 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19132026/10/25 16:05:33 INFO Uploading xz3dzpdz1zqvxz7ja1pcgsb1mcap33mm-shared-dep (136B)19142026/10/25 16:05:33 INFO Uploading r1z27zh0wip54ynlcvhwxafxl2l2j835-b (216B)19152026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures1916 client_pushes_test.go:112: Retrieved narinfo from S3:1917 StorePath: /build/TestClientFallsBackToClosures153172439/001/store/9i9pb2a6m20npjqjafzi83sdm9vvw9gm-a1918 URL: nar/1q5yd26b6r9kijsh9gwqs9bi8195fx23r49j7hf0pmjykzv51qrr.nar.zst1919 Compression: zstd1920 NarHash: sha256:1q5yd26b6r9kijsh9gwqs9bi8195fx23r49j7hf0pmjykzv51qrr1921 NarSize: 2161922 References: /build/TestClientFallsBackToClosures153172439/001/store/5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2-shared-dep1923 CA: text:sha256:1g40zv0j9nmhjqpsaqxrj8f1j55p1qzn2vplwg937k01ap88v2dr19242026/10/25 16:05:33 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=019252026/10/25 16:05:33 WARN Failed to register uploaded object key=gycb4rk0fmlhzjym9kcaln7ipxvg7far.ls error="server returned 404: 404 page not found\n"19262026/10/25 16:05:33 INFO Vacuumed table table=pending_closures19272026/10/25 16:05:33 WARN Failed to register uploaded object key=xz3dzpdz1zqvxz7ja1pcgsb1mcap33mm.ls error="server returned 404: 404 page not found\n"19282026/10/25 16:05:33 WARN Failed to register uploaded object key=r1z27zh0wip54ynlcvhwxafxl2l2j835.ls error="server returned 404: 404 page not found\n"19292026/10/25 16:05:33 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19302026/10/25 16:05:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19312026/10/25 16:05:33 WARN Failed to register uploaded object key=nar/1yhnj86h7067rpv5gcpf7wnm9jvkxravbkdsxwr3i8v0w0w437vz.nar.zst error="server returned 404: 404 page not found\n"19322026/10/25 16:05:33 INFO Signed narinfos id=1 count=319332026/10/25 16:05:33 INFO Aborted multipart uploads count=0 kept=019342026/10/25 16:05:33 INFO Uploading 3 narinfos1935 client_pushes_test.go:112: Retrieved narinfo from S3:1936 StorePath: /build/TestClientFallsBackToClosures153172439/001/store/a3i3hs8khx9v1qxnmw2rpcb35ivfri18-b1937 URL: nar/1q5yd26b6r9kijsh9gwqs9bi8195fx23r49j7hf0pmjykzv51qrr.nar.zst1938 Compression: zstd1939 NarHash: sha256:1q5yd26b6r9kijsh9gwqs9bi8195fx23r49j7hf0pmjykzv51qrr1940 NarSize: 2161941 References: /build/TestClientFallsBackToClosures153172439/001/store/5fbmqvvmz6cgcn40xrgsvnbj3ymfrcl2-shared-dep1942 CA: text:sha256:1g40zv0j9nmhjqpsaqxrj8f1j55p1qzn2vplwg937k01ap88v2dr19432026/10/25 16:05:33 INFO Vacuumed table table=pending_objects19442026/10/25 16:05:33 INFO Vacuumed table table=multipart_uploads19452026/10/25 16:05:33 INFO Vacuumed table table=closures19462026/10/25 16:05:33 INFO Vacuumed table table=objects19472026/10/25 16:05:33 WARN Failed to register uploaded object key=xz3dzpdz1zqvxz7ja1pcgsb1mcap33mm.narinfo error="server returned 404: 404 page not found\n"19482026/10/25 16:05:33 WARN Failed to register uploaded object key=gycb4rk0fmlhzjym9kcaln7ipxvg7far.narinfo error="server returned 404: 404 page not found\n"19492026/10/25 16:05:33 INFO Received complete push request method=POST path=/api/pushes/1/complete19502026/10/25 16:05:33 WARN Force mode enabled - objects will be deleted immediately without grace period19512026/10/25 16:05:33 WARN Failed to register uploaded object key=r1z27zh0wip54ynlcvhwxafxl2l2j835.narinfo error="server returned 404: 404 page not found\n"1952--- PASS: TestClientFallsBackToClosures (0.85s)1953=== CONT TestCacheConfigHandler/full_config,_no_issuer1954=== CONT TestCacheConfigHandler/no_signing_keys1955=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1956=== CONT TestCacheConfigHandler/no_cache_url_configured1957--- PASS: TestCacheConfigHandler (0.00s)1958 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1959 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1960 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1961 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1962=== CONT TestResolveDBConnectionString/flag_wins1963=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1964=== CONT TestResolveDBConnectionString/nothing_configured1965=== CONT TestResolveDBConnectionString/missing_file_is_an_error1966=== CONT TestResolveDBConnectionString/file_when_flag_empty1967=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1968--- PASS: TestResolveDBConnectionString (0.00s)1969 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1970 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1971 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1972 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1973 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1974=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19752026/10/25 16:05:33 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]1976=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1977=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19782026/10/25 16:05:33 WARN Authentication failed token_preview=eyJhbGciOi...mgfi7k-SXQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1979--- PASS: TestService_AuthMiddleware_OIDC (0.92s)1980 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1981 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1982 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1983 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1984=== CONT TestServerTLSConfig/no_client_CA1985=== CONT TestServerTLSConfig/not_a_PEM_file1986=== CONT TestServerTLSConfig/missing_CA_file1987--- PASS: TestServerTLSConfig (0.00s)1988 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1989 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1990 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1991=== CONT TestService_RequireScope_OIDC/builder_may_write19922026/10/25 16:05:33 INFO Completed push id=1 objects=8 duration=10.935519ms19932026/10/25 16:05:33 INFO Upload complete. (77ms)1994=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1995=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19962026/10/25 16:05:33 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]1997=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1998=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1999=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2000=== CONT TestService_RequireScope_OIDC/writer_implies_read2001=== CONT TestService_RequireScope_OIDC/reader_may_read2002=== CONT TestService_RequireScope_OIDC/static_token_may_write2003=== CONT TestService_RequireScope_OIDC/static_token_may_admin2004=== CONT TestService_RequireScope_OIDC/reader_may_not_write2005=== CONT TestService_RequireScope_OIDC/ops_may_not_write2006=== CONT TestService_RequireScope_OIDC/ops_may_admin2007=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2008=== NAME TestClientPushesUseOnePush2009 client_pushes_test.go:97: Retrieved narinfo from S3:2010 StorePath: /build/TestClientPushesUseOnePush2843590467/001/store/xz3dzpdz1zqvxz7ja1pcgsb1mcap33mm-shared-dep2011 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2012 Compression: zstd2013 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822014 NarSize: 1362015 References: 2016 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2017--- PASS: TestService_RequireScope_OIDC (0.78s)2018 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2026 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2027 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2028 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2029 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2030 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2031 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2032=== NAME TestClientPushesUseOnePush2033 client_pushes_test.go:97: Retrieved narinfo from S3:2034 StorePath: /build/TestClientPushesUseOnePush2843590467/001/store/gycb4rk0fmlhzjym9kcaln7ipxvg7far-a2035 URL: nar/1yhnj86h7067rpv5gcpf7wnm9jvkxravbkdsxwr3i8v0w0w437vz.nar.zst2036 Compression: zstd2037 NarHash: sha256:1yhnj86h7067rpv5gcpf7wnm9jvkxravbkdsxwr3i8v0w0w437vz2038 NarSize: 2162039 References: /build/TestClientPushesUseOnePush2843590467/001/store/xz3dzpdz1zqvxz7ja1pcgsb1mcap33mm-shared-dep2040 CA: text:sha256:1jgfmvwbgrshmv92rnfz433h963xl3jwjlkn2y24r1xb99kysifn20412026/10/25 16:05:33 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=02042 client_pushes_test.go:97: Retrieved narinfo from S3:2043 StorePath: /build/TestClientPushesUseOnePush2843590467/001/store/r1z27zh0wip54ynlcvhwxafxl2l2j835-b2044 URL: nar/1yhnj86h7067rpv5gcpf7wnm9jvkxravbkdsxwr3i8v0w0w437vz.nar.zst2045 Compression: zstd2046 NarHash: sha256:1yhnj86h7067rpv5gcpf7wnm9jvkxravbkdsxwr3i8v0w0w437vz2047 NarSize: 2162048 References: /build/TestClientPushesUseOnePush2843590467/001/store/xz3dzpdz1zqvxz7ja1pcgsb1mcap33mm-shared-dep2049 CA: text:sha256:1jgfmvwbgrshmv92rnfz433h963xl3jwjlkn2y24r1xb99kysifn20502026/10/25 16:05:33 INFO Vacuumed table table=pending_closures20512026/10/25 16:05:33 INFO Vacuumed table table=pending_objects20522026/10/25 16:05:33 INFO Vacuumed table table=multipart_uploads20532026/10/25 16:05:33 INFO Vacuumed table table=closures20542026/10/25 16:05:33 INFO Vacuumed table table=objects2055--- PASS: TestClientPushesUseOnePush (0.81s)2056--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2057 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.65s)2058 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.69s)20592026/10/25 16:05:33 WARN Request failed, retrying attempt=2 backoff=202.893761ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20602026/10/25 16:05:33 INFO Aborted multipart uploads count=0 kept=020612026/10/25 16:05:33 WARN Force mode enabled - objects will be deleted immediately without grace period20622026/10/25 16:05:33 INFO Aborted multipart uploads count=0 kept=020632026/10/25 16:05:33 WARN Force mode enabled - objects will be deleted immediately without grace period20642026/10/25 16:05:33 INFO Received uploads request method=POST path=/api/pending_closures20652026/10/25 16:05:33 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:34165/bucket95/?delete=\": context canceled"2066--- PASS: TestGCEndsOnShutdown (0.01s)2067 --- PASS: TestGCEndsOnShutdown/before_the_run (0.63s)2068 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.51s)2069 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.49s)20702026/10/25 16:05:33 WARN Request failed, retrying attempt=3 backoff=421.100776ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20712026/10/25 16:05:33 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20722026/10/25 16:05:33 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20732026/10/25 16:05:33 INFO lead: released remote=192.0.2.1:12342074--- PASS: TestLeadEndsOnShutdown (1.76s)20752026/10/25 16:05:34 INFO lead: released remote=192.0.2.1:123420762026/10/25 16:05:34 WARN Request failed, retrying attempt=4 backoff=769.164131ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20772026/10/25 16:05:34 INFO lead: acquired remote=192.0.2.1:12342078--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2079 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2080 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2081 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.96s)2082--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2083 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.84s)2084 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.85s)2085--- PASS: TestPendingClosureWriteTimeout (0.00s)2086 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2087 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2088 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2089 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.21s)2090--- PASS: TestDeleteClosuresRacingPins (1.83s)20912026/10/25 16:05:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02092=== NAME TestClientIntegration2093 client_integration_test.go:323: Objects in database after GC:2094 client_integration_test.go:323: Successfully deleted all objects with GC --force2095--- PASS: TestClientIntegration (3.14s)2096=== NAME TestOrphanedObjectsGCStressTest2097 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2098 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion20992026/10/25 16:05:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021002026/10/25 16:05:34 INFO Received create pin request method=POST path=/api/pins/myapp21012026/10/25 16:05:34 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3501816181/001/store/061gpyvkgy6r32ljclrm3bhzw1k96fkj-pinned-file.txt narinfo_key=061gpyvkgy6r32ljclrm3bhzw1k96fkj.narinfo21022026/10/25 16:05:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures2103 orphaned_objects_gc_test.go:503: Stress test completed successfully:2104 orphaned_objects_gc_test.go:504: - Active objects preserved: 202105 orphaned_objects_gc_test.go:505: - Objects deleted: 2102106 orphaned_objects_gc_test.go:506: - Total GC'd: 21021072026/10/25 16:05:34 INFO Garbage collection started2108--- PASS: TestOrphanedObjectsGCStressTest (3.23s)21092026/10/25 16:05:34 INFO Aborted multipart uploads count=0 kept=021102026/10/25 16:05:34 WARN Force mode enabled - objects will be deleted immediately without grace period21112026/10/25 16:05:34 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=021122026/10/25 16:05:34 INFO Vacuumed table table=pending_closures21132026/10/25 16:05:34 INFO Vacuumed table table=pending_objects21142026/10/25 16:05:34 INFO Vacuumed table table=multipart_uploads21152026/10/25 16:05:34 INFO Vacuumed table table=closures21162026/10/25 16:05:34 INFO Vacuumed table table=objects21172026/10/25 16:05:34 WARN Request failed, retrying attempt=5 backoff=1.595827108s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21182026/10/25 16:05:35 INFO lead: released remote=192.0.2.1:12342119--- PASS: TestLeadElectsOneAndHandsOver (3.06s)21202026/10/25 16:05:35 WARN Rate limiter enabled after throttle name=s3-test rate=521212026/10/25 16:05:35 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.63s)2126--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.22s)21272026/10/25 16:05:36 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-config21282026/10/25 16:05:36 WARN Request failed, retrying attempt=2 backoff=186.725617ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21292026/10/25 16:05:36 WARN Request failed, retrying attempt=3 backoff=420.358273ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2130=== NAME TestPinProtectsFromGC2131 client_integration_test.go:840: Pin successfully protected closure from garbage collection2132--- PASS: TestPinProtectsFromGC (5.07s)21332026/10/25 16:05:37 WARN Request failed, retrying attempt=4 backoff=758.432829ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2134--- PASS: TestConnectWaitsForAPeerMigration (5.15s)21352026/10/25 16:05:37 WARN Request failed, retrying attempt=5 backoff=1.755909582s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/10/25 16:05:39 INFO Aborted multipart uploads count=1 kept=021372026/10/25 16:05:39 INFO Received cleanup request method=DELETE path=/api/pending_closures21382026/10/25 16:05:39 INFO Aborted multipart uploads count=1 kept=02139--- PASS: TestPendingCleanupUsesOneCutoff (6.72s)21402026/10/25 16:05:39 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 16:05:39 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 16:05:39 WARN Request failed, retrying attempt=2 backoff=187.744139ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/10/25 16:05:40 WARN Request failed, retrying attempt=3 backoff=435.810026ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21442026/10/25 16:05:40 WARN Request failed, retrying attempt=4 backoff=738.455624ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/10/25 16:05:41 WARN Request failed, retrying attempt=5 backoff=1.57443895s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/10/25 16:05:42 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 16:05:42 WARN Request failed, retrying attempt=2 backoff=187.631177ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21482026/10/25 16:05:43 WARN Request failed, retrying attempt=3 backoff=380.811049ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21492026/10/25 16:05:43 WARN Request failed, retrying attempt=4 backoff=859.637169ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21502026/10/25 16:05:44 WARN Request failed, retrying attempt=5 backoff=1.744328799s 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.28s)2153 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.43s)2154 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.77s)2155PASS21562026-10-25 16:05:46.297 UTC [127] LOG: received smart shutdown request21572026-10-25 16:05:46.304 UTC [127] LOG: background worker "logical replication launcher" (PID 137) exited with exit code 121582026-10-25 16:05:46.315 UTC [132] LOG: shutting down21592026-10-25 16:05:46.315 UTC [132] LOG: checkpoint starting: shutdown immediate21602026-10-25 16:05:47.606 UTC [132] LOG: checkpoint complete: wrote 10771 buffers (65.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.277 s, sync=0.969 s, total=1.291 s; sync files=34046, longest=0.009 s, average=0.001 s; distance=494068 kB, estimate=494068 kB; lsn=0/1F9E2D80, redo lsn=0/1F9E2D8021612026-10-25 16:05:47.689 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=== CONT TestPins_ConfigValidation2202--- PASS: TestAudienceForIssuer (0.00s)2203=== CONT TestValidateToken_NoMatchingProvider2204=== CONT TestScopes_Rules2205=== CONT TestValidateToken_MultipleProviders2206=== CONT TestValidateToken_BoundSubjectMismatch2207=== CONT TestValidateToken_BoundClaimsMismatch2208=== CONT TestValidateToken_Expired2209--- PASS: TestPins_ConfigValidation (0.00s)2210=== CONT TestValidateToken_WrongAudience2211=== CONT TestValidateToken_ValidToken2212=== CONT TestGlobMatch2213=== RUN TestGlobMatch/foo_foo2214=== PAUSE TestGlobMatch/foo_foo2215=== RUN TestGlobMatch/foo_bar2216=== PAUSE TestGlobMatch/foo_bar2217=== RUN TestGlobMatch/*_2218=== PAUSE TestGlobMatch/*_2219=== RUN TestGlobMatch/*_anything2220=== PAUSE TestGlobMatch/*_anything2221=== RUN TestGlobMatch/foo*_foo2222=== CONT TestScopes_ConfigValidation2223=== CONT TestScopes_LegacyProviderDefaultsToWrite2224=== CONT TestPins_ReservedForMatchingRule2225=== CONT TestPins_TopLevelShorthand2226--- PASS: TestScopes_ConfigValidation (0.00s)2227=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2228=== CONT TestNewValidator_KubernetesRequiresCA2229=== PAUSE TestGlobMatch/foo*_foo2230=== RUN TestGlobMatch/foo*_foobar2231=== PAUSE TestGlobMatch/foo*_foobar2232=== RUN TestGlobMatch/foo*_bar2233=== PAUSE TestGlobMatch/foo*_bar2234=== RUN TestGlobMatch/*bar_bar2235=== PAUSE TestGlobMatch/*bar_bar2236=== RUN TestGlobMatch/*bar_foobar2237=== PAUSE TestGlobMatch/*bar_foobar2238=== RUN TestGlobMatch/*bar_foo2239=== PAUSE TestGlobMatch/*bar_foo2240=== RUN TestGlobMatch/foo*bar_foobar2241=== PAUSE TestGlobMatch/foo*bar_foobar2242=== RUN TestGlobMatch/foo*bar_foo123bar2243=== PAUSE TestGlobMatch/foo*bar_foo123bar2244=== RUN TestGlobMatch/foo*bar_foobarbaz2245=== PAUSE TestGlobMatch/foo*bar_foobarbaz2246=== RUN TestGlobMatch/*/*_foo/bar2247=== PAUSE TestGlobMatch/*/*_foo/bar2248=== RUN TestGlobMatch/*/*_foo2249=== PAUSE TestGlobMatch/*/*_foo2250=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2251=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2252=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02253=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02254=== RUN TestGlobMatch/refs/*/main_refs/heads/main2255=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2256=== RUN TestGlobMatch/fo?_foo2257=== PAUSE TestGlobMatch/fo?_foo2258=== RUN TestGlobMatch/fo?_fo2259=== PAUSE TestGlobMatch/fo?_fo2260=== RUN TestGlobMatch/fo?_fooo2261=== PAUSE TestGlobMatch/fo?_fooo2262=== RUN TestGlobMatch/?oo_foo2263=== PAUSE TestGlobMatch/?oo_foo2264=== RUN TestGlobMatch/?oo_boo2265=== PAUSE TestGlobMatch/?oo_boo2266=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2267=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2268=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2269=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2270=== CONT TestGlobMatch/foo_foo2271=== CONT TestGlobMatch/?oo_boo2272=== CONT TestGlobMatch/?oo_foo2273=== CONT TestGlobMatch/fo?_fooo2274=== CONT TestGlobMatch/fo?_fo2275=== CONT TestGlobMatch/fo?_foo2276=== CONT TestGlobMatch/refs/*/main_refs/heads/main2277=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02278=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2279=== CONT TestGlobMatch/*/*_foo2280=== CONT TestGlobMatch/*/*_foo/bar2281=== CONT TestGlobMatch/foo*bar_foo123bar2282=== CONT TestGlobMatch/foo_bar2283=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2284=== CONT TestGlobMatch/foo*bar_foobar2285=== CONT TestGlobMatch/*bar_foobar2286=== CONT TestGlobMatch/*bar_foo2287=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2288=== CONT TestGlobMatch/*bar_bar2289=== CONT TestGlobMatch/foo*bar_foobarbaz2290=== CONT TestGlobMatch/foo*_bar2291=== CONT TestGlobMatch/foo*_foobar2292=== CONT TestGlobMatch/foo*_foo2293=== CONT TestGlobMatch/*_anything2294=== CONT TestGlobMatch/*_2295--- PASS: TestGlobMatch (0.00s)2296 --- PASS: TestGlobMatch/foo_foo (0.00s)2297 --- PASS: TestGlobMatch/?oo_boo (0.00s)2298 --- PASS: TestGlobMatch/?oo_foo (0.00s)2299 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2300 --- PASS: TestGlobMatch/fo?_fo (0.00s)2301 --- PASS: TestGlobMatch/fo?_foo (0.00s)2302 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2303 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2304 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2305 --- PASS: TestGlobMatch/*/*_foo (0.00s)2306 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2307 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2308 --- PASS: TestGlobMatch/foo_bar (0.00s)2309 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2310 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2311 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2312 --- PASS: TestGlobMatch/*bar_foo (0.00s)2313 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2314 --- PASS: TestGlobMatch/*bar_bar (0.00s)2315 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2316 --- PASS: TestGlobMatch/foo*_bar (0.00s)2317 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2318 --- PASS: TestGlobMatch/foo*_foo (0.00s)2319 --- PASS: TestGlobMatch/*_anything (0.00s)2320 --- PASS: TestGlobMatch/*_ (0.00s)23212026/10/25 16:05:49 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:416352322--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)23232026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44031/oidc2324--- PASS: TestPins_ReservedForMatchingRule (0.04s)23252026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36313/oidc2326--- PASS: TestPins_TopLevelShorthand (0.05s)23272026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46695/oidc2328--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)23292026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44575/oidc23302026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36875/oidc2331--- PASS: TestValidateToken_Expired (0.07s)2332--- PASS: TestValidateToken_WrongAudience (0.07s)23332026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36797/oidc2334--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)23352026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44409/oidc2336--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)23372026/10/25 16:05:49 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323382026/10/25 16:05:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46441/oidc2339--- PASS: TestValidateToken_NoMatchingProvider (0.12s)2340--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)23412026/10/25 16:05:49 http: TLS handshake error from 127.0.0.1:36946: remote error: tls: bad certificate2342--- PASS: TestNewValidator_KubernetesRequiresCA (0.14s)23432026/10/25 16:05:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:34225/oidc23442026/10/25 16:05:49 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36749/oidc2345--- PASS: TestValidateToken_MultipleProviders (0.21s)23462026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34045/oidc2347--- PASS: TestScopes_Rules (0.24s)23482026/10/25 16:05:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32781/oidc2349--- PASS: TestValidateToken_ValidToken (0.34s)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 16:05:49 ERROR Failed to queue paths error="permission denied" count=12374--- PASS: TestServerQueueError (0.00s)2375=== RUN TestGetListenerSocketActivation2376 server_test.go:219: === RUN TestGetListenerSocketActivation2377 --- PASS: TestGetListenerSocketActivation (0.00s)2378 PASS2379 2380--- PASS: TestGetListenerSocketActivation (0.01s)2381=== RUN TestDrainIsolatesPoisonPath2382=== PAUSE TestDrainIsolatesPoisonPath2383=== RUN TestRunNotBlockedByPoisonHead2384=== PAUSE TestRunNotBlockedByPoisonHead2385=== RUN TestDrainGivesUpWhenServerDown2386=== PAUSE TestDrainGivesUpWhenServerDown2387=== RUN TestFailedPathPrunedByLaterClosure2388=== PAUSE TestFailedPathPrunedByLaterClosure2389=== RUN TestWorkerUploadsAndRemoves2390=== PAUSE TestWorkerUploadsAndRemoves2391=== RUN TestWorkerSkipsGCdPaths2392=== PAUSE TestWorkerSkipsGCdPaths2393=== RUN TestWorkerPrunesClosureDeps2394=== PAUSE TestWorkerPrunesClosureDeps2395=== RUN TestDrainTimeout2396=== PAUSE TestDrainTimeout2397=== RUN TestWorkerRemoveFailureIsNotProgress2398=== PAUSE TestWorkerRemoveFailureIsNotProgress2399=== RUN TestWorkerKeepsPathItCannotStat2400=== PAUSE TestWorkerKeepsPathItCannotStat2401=== CONT TestSendPathsEmpty2402=== CONT TestDrainIsolatesPoisonPath2403=== CONT TestWorkerKeepsPathItCannotStat2404--- PASS: TestSendPathsEmpty (0.00s)2405=== CONT TestWorkerRemoveFailureIsNotProgress2406=== CONT TestQueueRemoveLargeClosure2407=== CONT TestQueueFetchBatchLimit2408=== CONT TestQueueRemove2409=== CONT TestQueueConcurrentWriters2410=== CONT TestQueueDeduplication2411=== CONT TestQueueFetchRemoveLifecycle2412=== CONT TestQueueEnqueueAndFetch2413=== CONT TestQueueRetryMovesToBack2414=== CONT TestWorkerPrunesClosureDeps2415=== CONT TestDrainGivesUpWhenServerDown2416=== CONT TestDrainTimeout2417=== CONT TestWorkerUploadsAndRemoves2418=== CONT TestFailedPathPrunedByLaterClosure2419=== CONT TestWorkerSkipsGCdPaths2420=== CONT TestRunNotBlockedByPoisonHead24212026/10/25 16:05:49 INFO Upload queue status pending=224222026/10/25 16:05:49 INFO Uploading batch count=124232026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=124242026/10/25 16:05:49 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat926339309/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat926339309/002/locked/aaa: permission denied"24252026/10/25 16:05:49 INFO Uploading batch count=224262026/10/25 16:05:49 INFO Upload queue status pending=324272026/10/25 16:05:49 INFO Uploading batch count=424282026/10/25 16:05:49 INFO Uploading batch count=124292026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=424302026/10/25 16:05:49 INFO Uploading batch count=224312026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=124322026/10/25 16:05:49 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat926339309/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat926339309/002/locked/aaa: permission denied"24332026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1134291881/002/bbb24342026/10/25 16:05:49 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3981122181/002/nonexistent24352026/10/25 16:05:49 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12436--- PASS: TestQueueRemove (0.02s)24372026/10/25 16:05:49 INFO Uploading batch count=224382026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=224392026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1114850073/002/a24402026/10/25 16:05:49 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat926339309/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat926339309/002/locked/aaa: permission denied"2441--- PASS: TestQueueEnqueueAndFetch (0.02s)2442--- PASS: TestQueueRetryMovesToBack (0.02s)24432026/10/25 16:05:49 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3981122181/002/nonexistent24442026/10/25 16:05:49 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124452026/10/25 16:05:49 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3981122181/002/nonexistent24462026/10/25 16:05:49 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124472026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1114850073/002/b24482026/10/25 16:05:49 ERROR Drain finished with paths left in queue remaining=12449--- PASS: TestQueueDeduplication (0.02s)24502026/10/25 16:05:49 INFO Uploading batch count=124512026/10/25 16:05:49 INFO Upload queue status pending=224522026/10/25 16:05:49 ERROR Drain finished with paths left in queue remaining=124532026/10/25 16:05:49 INFO Uploading batch count=124542026/10/25 16:05:49 INFO Upload queue status pending=224552026/10/25 16:05:49 INFO Uploading batch count=22456--- PASS: TestQueueFetchBatchLimit (0.02s)24572026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=224582026/10/25 16:05:49 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1901457591/002/nonexistent2459--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)24602026/10/25 16:05:49 INFO Uploading batch count=12461--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24622026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1114850073/002/c24632026/10/25 16:05:49 INFO Uploading batch count=124642026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=124652026/10/25 16:05:49 INFO Uploading batch count=124662026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1114850073/002/d24672026/10/25 16:05:49 INFO Uploading batch count=12468--- PASS: TestWorkerKeepsPathItCannotStat (0.03s)24692026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=124702026/10/25 16:05:49 INFO Uploading batch count=224712026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=224722026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1114850073/002/e24732026/10/25 16:05:49 INFO Uploading batch count=124742026/10/25 16:05:49 ERROR Upload failed error="upload failed" count=12475--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24762026/10/25 16:05:49 ERROR Drain finished with paths left in queue remaining=124772026/10/25 16:05:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1114850073/002/f24782026/10/25 16:05:49 ERROR Drain finished with paths left in queue remaining=102479--- PASS: TestDrainIsolatesPoisonPath (0.03s)2480--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2481--- PASS: TestWorkerUploadsAndRemoves (0.04s)2482--- PASS: TestWorkerSkipsGCdPaths (0.04s)2483--- PASS: TestWorkerPrunesClosureDeps (0.04s)2484--- PASS: TestQueueRemoveLargeClosure (0.11s)2485--- PASS: TestQueueConcurrentWriters (0.16s)24862026/10/25 16:05:50 ERROR Upload failed error="context deadline exceeded" count=224872026/10/25 16:05:50 ERROR Drain finished with paths left in queue remaining=42488--- PASS: TestDrainTimeout (0.22s)24892026/10/25 16:05:50 INFO Uploading batch count=124902026/10/25 16:05:50 INFO Uploading batch count=124912026/10/25 16:05:50 INFO Uploading batch count=124922026/10/25 16:05:50 ERROR Upload failed error="upload failed" count=124932026/10/25 16:05:50 INFO Uploading batch count=124942026/10/25 16:05:50 ERROR Upload failed error="upload failed" count=124952026/10/25 16:05:50 INFO Uploading batch count=124962026/10/25 16:05:50 ERROR Upload failed error="upload failed" count=124972026/10/25 16:05:50 INFO Uploading batch count=124982026/10/25 16:05:50 ERROR Upload failed error="upload failed" count=124992026/10/25 16:05:50 ERROR Drain finished with paths left in queue remaining=12500--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2501PASS2502Running signing tests...2503=== RUN TestExternalSigner2504=== PAUSE TestExternalSigner2505=== RUN TestExternalSignerWrongPublicKey2506=== PAUSE TestExternalSignerWrongPublicKey2507=== RUN TestExternalSignerErrors2508=== PAUSE TestExternalSignerErrors2509=== RUN TestExternalSignerRestartsAfterCrash2510=== PAUSE TestExternalSignerRestartsAfterCrash2511=== RUN TestExternalSignerProgramErrorKeepsProcess2512=== PAUSE TestExternalSignerProgramErrorKeepsProcess2513=== RUN TestExternalSignerClose2514=== PAUSE TestExternalSignerClose2515=== RUN TestExternalSignerRejectsInvalidPublicKey2516=== PAUSE TestExternalSignerRejectsInvalidPublicKey2517=== RUN TestExternalSignerCancellation2518=== PAUSE TestExternalSignerCancellation2519=== RUN TestGenerateFingerprint2520=== PAUSE TestGenerateFingerprint2521=== RUN TestParseSigningKey2522=== PAUSE TestParseSigningKey2523=== RUN TestSign2524=== PAUSE TestSign2525=== RUN TestSignBatch2526=== PAUSE TestSignBatch2527=== RUN TestNilKeyPublicKey2528=== PAUSE TestNilKeyPublicKey2529=== RUN TestSignErrors2530=== PAUSE TestSignErrors2531=== CONT TestExternalSigner2532=== CONT TestSignErrors2533=== CONT TestExternalSignerCancellation2534=== CONT TestExternalSignerProgramErrorKeepsProcess2535=== CONT TestExternalSignerClose2536=== CONT TestParseSigningKey2537=== RUN TestParseSigningKey/valid_32-byte_key2538=== PAUSE TestParseSigningKey/valid_32-byte_key2539=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2540=== CONT TestGenerateFingerprint2541=== RUN TestGenerateFingerprint/basic_with_references2542=== PAUSE TestGenerateFingerprint/basic_with_references2543=== RUN TestGenerateFingerprint/no_references2544=== PAUSE TestGenerateFingerprint/no_references2545=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2546=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2547=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2548=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2549=== RUN TestGenerateFingerprint/invalid_nar_hash_length2550=== CONT TestNilKeyPublicKey2551=== CONT TestExternalSignerRestartsAfterCrash2552=== CONT TestSignBatch2553=== CONT TestExternalSignerWrongPublicKey2554=== CONT TestSign2555=== CONT TestExternalSignerRejectsInvalidPublicKey2556=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2557=== RUN TestParseSigningKey/no_colon2558=== PAUSE TestParseSigningKey/no_colon2559=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2560=== RUN TestGenerateFingerprint/invalid_store_path_prefix2561=== CONT TestExternalSignerErrors2562--- PASS: TestNilKeyPublicKey (0.00s)2563=== RUN TestParseSigningKey/empty_name2564=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2565=== RUN TestExternalSignerRejectsInvalidPublicKey/#002566=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002567=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2568=== RUN TestExternalSignerErrors/wrong_id2569=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2570=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2571=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2572=== PAUSE TestExternalSignerErrors/wrong_id2573=== RUN TestGenerateFingerprint/invalid_reference_prefix2574=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2575=== CONT TestGenerateFingerprint/basic_with_references2576=== CONT TestGenerateFingerprint/invalid_nar_hash_length2577=== PAUSE TestParseSigningKey/empty_name2578=== RUN TestParseSigningKey/invalid_base642579=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2580=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2581=== RUN TestExternalSignerErrors/program_error2582=== PAUSE TestExternalSignerErrors/program_error2583=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2584=== CONT TestGenerateFingerprint/no_references2585=== CONT TestGenerateFingerprint/invalid_store_path_prefix2586=== CONT TestGenerateFingerprint/invalid_reference_prefix2587--- PASS: TestGenerateFingerprint (0.00s)2588 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2589 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2590 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2591 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2592 --- PASS: TestGenerateFingerprint/no_references (0.00s)2593 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2594 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2595=== PAUSE TestParseSigningKey/invalid_base642596=== RUN TestParseSigningKey/wrong_length2597=== PAUSE TestParseSigningKey/wrong_length2598=== CONT TestParseSigningKey/valid_32-byte_key2599=== CONT TestParseSigningKey/invalid_base642600=== CONT TestParseSigningKey/empty_name2601=== CONT TestParseSigningKey/wrong_length2602=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2603--- PASS: TestSign (0.00s)2604=== RUN TestExternalSignerErrors/exit_at_startup2605=== RUN TestSignErrors/nil_key2606=== CONT TestParseSigningKey/no_colon2607=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2608--- PASS: TestParseSigningKey (0.00s)2609 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2610 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2611 --- PASS: TestParseSigningKey/empty_name (0.00s)2612 --- PASS: TestParseSigningKey/wrong_length (0.00s)2613 --- PASS: TestParseSigningKey/no_colon (0.00s)2614 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2615=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2616=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2617=== PAUSE TestExternalSignerErrors/exit_at_startup2618=== RUN TestExternalSignerErrors/missing_signatures2619=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2620=== CONT TestExternalSignerRejectsInvalidPublicKey/#002621=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2622=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2623=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2624--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2625 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2626 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2627 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2628 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2629 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2630=== PAUSE TestSignErrors/nil_key2631=== PAUSE TestExternalSignerErrors/missing_signatures2632=== RUN TestExternalSignerErrors/null_signatures2633=== RUN TestSignErrors/nil_narinfo2634=== PAUSE TestSignErrors/nil_narinfo2635=== RUN TestSignErrors/invalid_narinfo2636=== PAUSE TestExternalSignerErrors/null_signatures2637=== PAUSE TestSignErrors/invalid_narinfo2638=== RUN TestExternalSignerErrors/invalid_JSON2639=== PAUSE TestExternalSignerErrors/invalid_JSON2640=== RUN TestExternalSignerErrors/wrong_signatures_shape2641--- PASS: TestSignBatch (0.00s)2642=== RUN TestSignErrors/canceled2643=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2644=== RUN TestExternalSignerErrors/missing_signature_name2645=== PAUSE TestSignErrors/canceled2646=== CONT TestSignErrors/nil_key2647=== PAUSE TestExternalSignerErrors/missing_signature_name2648=== RUN TestExternalSignerErrors/wrong_signature_name2649=== PAUSE TestExternalSignerErrors/wrong_signature_name2650=== RUN TestExternalSignerErrors/invalid_signature_base642651=== PAUSE TestExternalSignerErrors/invalid_signature_base642652=== RUN TestExternalSignerErrors/null2653=== CONT TestSignErrors/invalid_narinfo2654=== CONT TestSignErrors/canceled2655=== CONT TestSignErrors/nil_narinfo2656--- PASS: TestSignErrors (0.00s)2657 --- PASS: TestSignErrors/nil_key (0.00s)2658 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2659 --- PASS: TestSignErrors/canceled (0.00s)2660 --- PASS: TestSignErrors/nil_narinfo (0.00s)2661=== PAUSE TestExternalSignerErrors/null2662=== RUN TestExternalSignerErrors/too_few_signatures2663=== PAUSE TestExternalSignerErrors/too_few_signatures2664=== RUN TestExternalSignerErrors/unrequested_key2665=== PAUSE TestExternalSignerErrors/unrequested_key2666=== RUN TestExternalSignerErrors/wrong_signature_length2667=== PAUSE TestExternalSignerErrors/wrong_signature_length2668=== RUN TestExternalSignerErrors/exit_on_request2669=== PAUSE TestExternalSignerErrors/exit_on_request2670=== RUN TestExternalSignerErrors/wrong_shape2671=== PAUSE TestExternalSignerErrors/wrong_shape2672=== CONT TestExternalSignerErrors/wrong_id2673=== CONT TestExternalSignerErrors/wrong_signature_name2674=== CONT TestExternalSignerErrors/program_error2675=== CONT TestExternalSignerErrors/invalid_signature_base642676=== CONT TestExternalSignerErrors/unrequested_key2677=== CONT TestExternalSignerErrors/wrong_shape2678=== CONT TestExternalSignerErrors/exit_on_request2679=== CONT TestExternalSignerErrors/wrong_signature_length2680=== CONT TestExternalSignerErrors/wrong_signatures_shape2681=== CONT TestExternalSignerErrors/too_few_signatures2682=== CONT TestExternalSignerErrors/null2683=== CONT TestExternalSignerErrors/missing_signatures2684=== CONT TestExternalSignerErrors/null_signatures2685=== CONT TestExternalSignerErrors/invalid_JSON2686=== CONT TestExternalSignerErrors/missing_signature_name2687=== CONT TestExternalSignerErrors/exit_at_startup2688--- PASS: TestExternalSignerClose (0.01s)2689--- PASS: TestExternalSignerWrongPublicKey (0.01s)2690--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2691--- PASS: TestExternalSigner (0.01s)2692--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2693--- PASS: TestExternalSignerErrors (0.00s)2694 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2695 --- PASS: TestExternalSignerErrors/program_error (0.00s)2696 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2697 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2698 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2699 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2700 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2701 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2702 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2703 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2704 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2705 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2706 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2707 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2708 --- PASS: TestExternalSignerErrors/null (0.01s)2709 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2710--- PASS: TestExternalSignerCancellation (0.02s)2711PASS2712Running OpenBao signer tests...2713=== RUN TestSign2714=== PAUSE TestSign2715=== RUN TestSignErrors2716=== PAUSE TestSignErrors2717=== RUN TestServe2718=== PAUSE TestServe2719=== RUN TestServeRejectsGarbage2720=== PAUSE TestServeRejectsGarbage2721=== CONT TestSign2722=== CONT TestSignErrors2723=== CONT TestServe2724=== RUN TestSignErrors/http_error2725=== CONT TestServeRejectsGarbage2726=== PAUSE TestSignErrors/http_error2727=== RUN TestSignErrors/invalid_json2728=== PAUSE TestSignErrors/invalid_json2729=== RUN TestSignErrors/no_prefix2730=== PAUSE TestSignErrors/no_prefix2731=== RUN TestSignErrors/invalid_base642732=== PAUSE TestSignErrors/invalid_base642733=== CONT TestSignErrors/http_error2734--- PASS: TestServeRejectsGarbage (0.00s)2735=== CONT TestSignErrors/no_prefix2736=== CONT TestSignErrors/invalid_json2737=== CONT TestSignErrors/invalid_base642738--- PASS: TestServe (0.00s)2739--- PASS: TestSign (0.00s)2740--- PASS: TestSignErrors (0.00s)2741 --- PASS: TestSignErrors/invalid_base64 (0.00s)2742 --- PASS: TestSignErrors/no_prefix (0.00s)2743 --- PASS: TestSignErrors/http_error (0.00s)2744 --- PASS: TestSignErrors/invalid_json (0.00s)2745PASS