niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #432
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestShellSplitErrors117--- PASS: TestShellSplitErrors (0.00s)118=== CONT TestUploadMultipart_FailedPartBufferNotReused119=== CONT TestSetClientTLSErrors120=== CONT TestScriptTokenEmptyCommand121--- PASS: TestScriptTokenEmptyCommand (0.00s)122=== CONT TestStreamPushBatchesUnderLoad123=== CONT TestScriptTokenScriptFails124=== CONT TestStreamPushReportsSignatures125=== CONT TestScriptTokenBadJSON126=== CONT TestSetClientTLSDoesNotMutateDefaultTransport127=== CONT TestScriptTokenEmptyToken128=== CONT TestStreamPushIsolatesFailures129=== CONT TestScriptTokenCachesUntilRefresh130=== CONT TestSetClientTLS131=== CONT TestStreamPushRequestLine132=== CONT TestScriptTokenNoExpiryRerunsEveryCall133=== CONT TestStreamPushStopsWhenCanceled134=== CONT TestFileTokenEmpty135=== CONT TestClientSignaturesByStorePath136=== CONT TestFileTokenMissing137=== CONT TestFileTokenReadsAndCaches138=== CONT TestStreamPushGivesUpOnDeadServer139=== CONT TestStreamPushReportsSkippedPaths140=== CONT TestEncodeNixBase32WithRealHash141=== CONT TestStaticToken142=== CONT TestShellSplit1432026/10/25 19:00:57 ERROR Upload failed error=boom count=1144--- PASS: TestStreamPushReportsSignatures (0.00s)145=== CONT TestEncodeNixBase32146=== RUN TestSetClientTLSErrors/missing_cert_file147--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)148=== CONT TestDoWithRetry_FinalResponseBodyReadable149--- PASS: TestScriptTokenBadJSON (0.00s)150=== CONT TestDumpPathMatchesNix151--- PASS: TestScriptTokenScriptFails (0.03s)152=== CONT TestSupersededNARStillUploadsListing153--- PASS: TestClientSignaturesByStorePath (0.00s)154=== CONT TestRetryTimeoutOutlastsMaxRetries1552026/10/25 19:00:57 ERROR Upload failed error=boom count=1156--- PASS: TestDoServerRequestAttachesToken (0.03s)157=== CONT TestDumpPathWriterError1582026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=server-test rate=51592026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:41887160--- PASS: TestStreamPushReportsSkippedPaths (0.00s)161=== CONT TestDoWithRetry_BodyReplayedViaGetBody1622026/10/25 19:00:57 ERROR Upload failed error="connection refused" count=201632026/10/25 19:00:57 ERROR Server seems unavailable, giving up on batch untried=17164--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1652026/10/25 19:00:57 WARN Rate limiter backed off name=server-test rate=5166=== CONT TestUploadMultipart_SupersededByPeer167=== RUN TestUploadMultipart_SupersededByPeer/exists168=== CONT TestDumpPathSingleFile169=== CONT TestPartSizeForNAR170=== RUN TestEncodeNixBase32/test_string_hash171=== PAUSE TestEncodeNixBase32/test_string_hash172=== RUN TestEncodeNixBase32/empty_input173=== PAUSE TestEncodeNixBase32/empty_input174=== PAUSE TestSetClientTLSErrors/missing_cert_file175=== RUN TestSetClientTLSErrors/missing_key_file176=== PAUSE TestSetClientTLSErrors/missing_key_file177=== RUN TestSetClientTLSErrors/missing_ca_file178=== PAUSE TestSetClientTLSErrors/missing_ca_file179=== RUN TestSetClientTLSErrors/invalid_ca_file180=== PAUSE TestSetClientTLSErrors/invalid_ca_file181=== RUN TestPartSizeForNAR/zero_stays_at_minimum182=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum183=== RUN TestPartSizeForNAR/small_stays_at_minimum184=== PAUSE TestPartSizeForNAR/small_stays_at_minimum185=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum186=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum187=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts188=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts189=== RUN TestPartSizeForNAR/1_TiB1902026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=server-test rate=5191=== PAUSE TestPartSizeForNAR/1_TiB1922026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:41267193=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer1942026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33271195=== CONT TestPathInfoHashCompatibility196=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1972026/10/25 19:00:57 WARN Rate limiter backed off name=server-test rate=5198=== PAUSE TestUploadMultipart_SupersededByPeer/exists1992026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:41267200=== RUN TestUploadMultipart_SupersededByPeer/missing201=== PAUSE TestUploadMultipart_SupersededByPeer/missing202=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun2032026/10/25 19:00:57 ERROR Upload failed error="bad path" count=3204=== CONT TestGetStorePathHash205=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess206=== CONT TestResolveStorePath207=== CONT TestParsePathInfoJSON208=== CONT TestUploadMultipart_PartsInParallel2092026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=server-test rate=5210=== RUN TestParsePathInfoJSON/Nix_format211=== RUN TestPartSizeForNAR/5_TiB_S3_max_object212=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object213=== CONT TestConvertHashToNix32214=== RUN TestPartSizeForNAR/capped_at_5_GiB215=== PAUSE TestPartSizeForNAR/capped_at_5_GiB216=== RUN TestGetStorePathHash/valid_store_path217--- PASS: TestStaticToken (0.00s)218=== CONT TestRateLimiterFeedback219=== RUN TestSupersededNARStillUploadsListing/small_NAR220=== PAUSE TestParsePathInfoJSON/Nix_format221=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)222=== CONT TestFilterOversizedClosures223=== RUN TestConvertHashToNix32/SRI_format_to_Nix32224=== CONT TestPathInfoCACompatibility225=== CONT TestParsePathInfoJSONMultiplePaths226=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon2272026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33271228=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon2292026/10/25 19:00:57 INFO Garbage collection started230=== CONT TestCaseHackSuffix231=== PAUSE TestGetStorePathHash/valid_store_path232=== PAUSE TestSupersededNARStillUploadsListing/small_NAR233=== RUN TestParsePathInfoJSON/Lix_format234=== PAUSE TestParsePathInfoJSON/Lix_format235=== RUN TestParsePathInfoJSON/empty_input236=== PAUSE TestParsePathInfoJSON/empty_input237=== RUN TestParsePathInfoJSON/whitespace_only238=== PAUSE TestParsePathInfoJSON/whitespace_only239=== RUN TestParsePathInfoJSON/invalid_JSON240=== PAUSE TestParsePathInfoJSON/invalid_JSON241=== RUN TestRateLimiterFeedback/429_enables_limiter242=== PAUSE TestRateLimiterFeedback/429_enables_limiter243=== RUN TestRateLimiterFeedback/503_enables_limiter244=== PAUSE TestRateLimiterFeedback/503_enables_limiter245=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter246=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter247=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths248=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths249--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)250=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths251--- PASS: TestShellSplit (0.00s)252=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32253=== RUN TestConvertHashToNix32/already_Nix32_format254=== PAUSE TestConvertHashToNix32/already_Nix32_format255=== RUN TestConvertHashToNix32/invalid_format256=== PAUSE TestConvertHashToNix32/invalid_format257=== RUN TestFilterOversizedClosures/no_limit_keeps_everything258=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything259=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI260=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI261=== RUN TestGetStorePathHash/basename_without_hyphen_should_error262=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error263=== RUN TestSupersededNARStillUploadsListing/dump_cut_short264=== CONT TestRegisterUploadedObjectReusesConnections265=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica266=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter267=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter268=== RUN TestPathInfoCACompatibility/null_ca_field269=== PAUSE TestPathInfoCACompatibility/null_ca_field270=== RUN TestPathInfoCACompatibility/old_string_format_-_text271=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text272=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive273=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive274=== RUN TestPathInfoCACompatibility/new_structured_format_-_text275=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text276=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method277=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method278=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths279=== CONT TestEncodeNixBase32/test_string_hash280=== CONT TestSetClientTLSErrors/missing_ca_file2812026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33271282=== CONT TestSetClientTLSErrors/missing_key_file283=== CONT TestSetClientTLSErrors/invalid_ca_file284=== CONT TestUploadMultipart_SupersededByPeer/exists2852026/10/25 19:00:57 INFO Garbage collection started286=== CONT TestUploadMultipart_SupersededByPeer/missing287=== CONT TestEncodeNixBase32/empty_input288=== CONT TestPartSizeForNAR/zero_stays_at_minimum289=== CONT TestPartSizeForNAR/capped_at_5_GiB290=== CONT TestPartSizeForNAR/5_TiB_S3_max_object291=== CONT TestPartSizeForNAR/1_TiB292=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts293=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum294=== CONT TestPartSizeForNAR/small_stays_at_minimum295=== CONT TestParsePathInfoJSON/Nix_format296=== CONT TestParsePathInfoJSON/invalid_JSON297=== CONT TestParsePathInfoJSON/whitespace_only298=== CONT TestParsePathInfoJSON/empty_input299=== CONT TestParsePathInfoJSON/Lix_format300=== CONT TestConvertHashToNix32/SRI_format_to_Nix32301=== CONT TestConvertHashToNix32/already_Nix32_format302=== CONT TestConvertHashToNix32/invalid_format303=== CONT TestRateLimiterFeedback/429_enables_limiter304--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)305--- PASS: TestStreamPushStopsWhenCanceled (0.00s)306--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)307--- PASS: TestStreamPushIsolatesFailures (0.00s)308--- PASS: TestFileTokenMissing (0.00s)309--- PASS: TestFileTokenEmpty (0.00s)310--- PASS: TestFileTokenReadsAndCaches (0.01s)311--- PASS: TestDumpPathSingleFile (0.03s)312--- PASS: TestScriptTokenEmptyToken (0.04s)313--- PASS: TestResolveStorePath (0.03s)314--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)315=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter316=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry317--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)318--- PASS: TestEncodeNixBase32 (0.00s)319 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)320 --- PASS: TestEncodeNixBase32/empty_input (0.00s)3212026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=server-test rate=5322=== CONT TestSetClientTLSErrors/missing_cert_file3232026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:377313242026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33271325=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512326=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512327=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error328=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error329=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error330=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error331=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3322026/10/25 19:00:57 WARN Rate limiter backed off name=server-test rate=5333=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3342026/10/25 19:00:57 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=0335=== CONT TestRateLimiterFeedback/503_enables_limiter336=== CONT TestPathInfoCACompatibility/old_string_format_-_text337=== RUN TestSetClientTLS/rejects_connection_without_client_cert338=== CONT TestStreamPushReportsEveryPath339--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)340 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)341 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)342--- PASS: TestPartSizeForNAR (0.03s)343 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)344 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)345 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)346 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)347 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)348 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)349 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)350=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert351=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA352=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA353=== RUN TestSetClientTLS/preserves_debug_logging_transport354=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short355=== CONT TestPathInfoCACompatibility/null_ca_field356=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3572026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:33271358=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails3592026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=server-test rate=5360=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails3612026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:36087362=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3632026/10/25 19:00:57 WARN Garbage collection finished on another replica. Its statistics are not available here364=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon3652026/10/25 19:00:57 WARN Rate limiter backed off name=server-test rate=5366=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error367=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive368=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths3692026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=s3-test rate=5370=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3712026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:34279372=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)373--- PASS: TestStreamPushReportsEveryPath (0.00s)374=== CONT TestGetStorePathHash/valid_store_path375=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512376=== CONT TestSupersededNARStillUploadsListing/small_NAR377--- PASS: TestSetClientTLSErrors (0.03s)378 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)380 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)381 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)382=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped383=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI384=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error385=== CONT TestGetStorePathHash/basename_without_hyphen_should_error386--- PASS: TestConvertHashToNix32 (0.03s)387 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)388 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)389 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)3902026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:33271391=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3922026/10/25 19:00:57 INFO Uploading abc-hello (1.0GB)393=== CONT TestSetClientTLS/preserves_debug_logging_transport394=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA395=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3962026/10/25 19:00:57 INFO Uploading abc-hello (1.0GB)397=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3982026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:33271399=== CONT TestSetClientTLS/rejects_connection_without_client_cert400--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)401=== RUN TestFilterOversizedClosures/all_closures_skipped402--- PASS: TestParsePathInfoJSON (0.03s)403 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)404 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)405 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)406 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)407 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)408--- PASS: TestGetStorePathHash (0.04s)409 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)410 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)411 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)412 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)413=== PAUSE TestFilterOversizedClosures/all_closures_skipped414=== CONT TestFilterOversizedClosures/no_limit_keeps_everything4152026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:33271416--- PASS: TestPathInfoCACompatibility (0.13s)417 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)418 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)419 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)420 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)421 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)422=== CONT TestFilterOversizedClosures/all_closures_skipped4232026/10/25 19:00:57 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=50424--- PASS: TestStreamPushBatchesUnderLoad (0.20s)425--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)426--- PASS: TestPathInfoHashCompatibility (0.16s)427 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)428 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)429 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)430 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)431--- PASS: TestRateLimiterFeedback (0.13s)432 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)433 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)434 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)435 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)436--- PASS: TestParsePathInfoJSONMultiplePaths (0.13s)437 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)438 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)439=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4402026/10/25 19:00:57 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=2000441--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)442--- PASS: TestCaseHackSuffix (0.14s)443--- PASS: TestFilterOversizedClosures (0.14s)444 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)445 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)446 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)447--- PASS: TestStreamPushRequestLine (0.18s)4482026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:332714492026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:332714502026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:332714512026/10/25 19:00:57 http: TLS handshake error from 127.0.0.1:35486: remote error: tls: bad certificate4522026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:33271453--- PASS: TestSetClientTLS (0.04s)454 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.14s)455 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.14s)456 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)4572026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:332714582026/10/25 19:00:57 WARN Rate limiter enabled after throttle name=s3-test rate=54592026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:33271460--- PASS: TestRegisterUploadedObjectReusesConnections (0.15s)4612026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:332714622026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:332714632026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:332714642026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:33271465--- PASS: TestDumpPathWriterError (0.19s)4662026/10/25 19:00:57 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:332714672026/10/25 19:00:57 INFO Uploading abc-hello (1.0GB)468--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.19s)4692026/10/25 19:00:57 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:44959/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:44959/part/2470--- PASS: TestDumpPathMatchesNix (0.23s)4712026/10/25 19:00:57 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:44959/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:44959/part/34722026/10/25 19:00:57 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"473--- PASS: TestSupersededNARStillUploadsListing (0.04s)474 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.13s)475 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.14s)476 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.67s)477--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.77s)478--- PASS: TestUploadMultipart_PartsInParallel (0.78s)4792026/10/25 19:00:58 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:43637/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:43637/api/uploads/complete480--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4812026/10/25 19:00:58 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4822026/10/25 19:00:58 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:43637/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:43637/api/uploads/complete4832026/10/25 19:00:58 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4842026/10/25 19:00:58 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:43637/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:43637/api/uploads/complete4852026/10/25 19:00:58 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"486--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)487PASS488Running server tests...489The files belonging to this database system will be owned by user "nixbld".490This user must also own the server process.491492The database cluster will be initialized with locale "C".493The default database encoding has accordingly been set to "SQL_ASCII".494The default text search configuration will be set to "english".495496Data page checksums are enabled.497498creating directory /build/postgres2959657843/data ... ok499creating subdirectories ... ok500selecting dynamic shared memory implementation ... posix501selecting default "max_connections" ... 100502selecting default "shared_buffers" ... 128MB503selecting default time zone ... UTC504creating configuration files ... ok505running bootstrap script ... ok506performing post-bootstrap initialization ... ok507syncing data to disk ... ok508509initdb: warning: enabling "trust" authentication for local connections510initdb: 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.511512Success. You can now start the database server using:513514 pg_ctl -D /build/postgres2959657843/data -l logfile start515516/build/postgres2959657843:5432 - no response5172026-10-25 19:00:59.126 UTC [127] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5182026-10-25 19:00:59.126 UTC [127] LOG: listening on Unix socket "/build/postgres2959657843/.s.PGSQL.5432"5192026-10-25 19:00:59.131 UTC [134] LOG: database system was shut down at 2026-10-25 19:00:58 UTC5202026-10-25 19:00:59.134 UTC [127] LOG: database system is ready to accept connections521/build/postgres2959657843:5432 - accepting connections522=== RUN TestService_AuthMiddleware523=== PAUSE TestService_AuthMiddleware524=== RUN TestService_AuthMiddleware_MTLSProxyHeader525=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader526=== RUN TestService_AuthMiddleware_MTLSBoundSubjects527=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects528=== RUN TestService_ReadAuthMiddleware529=== PAUSE TestService_ReadAuthMiddleware530=== RUN TestService_AuthMiddleware_OIDC531=== PAUSE TestService_AuthMiddleware_OIDC532=== RUN TestService_RequireScope_OIDC533=== PAUSE TestService_RequireScope_OIDC534=== RUN TestService_ReadScope_PublicByDefault535=== PAUSE TestService_ReadScope_PublicByDefault536=== RUN TestCacheConfigHandler537=== PAUSE TestCacheConfigHandler538=== RUN TestCacheStatsHandler539=== PAUSE TestCacheStatsHandler540=== RUN TestClientCADerivations541=== PAUSE TestClientCADerivations542=== RUN TestClientErrorHandling543=== PAUSE TestClientErrorHandling544=== RUN TestClientIntegration545=== PAUSE TestClientIntegration546=== RUN TestClientMultipleUploads547=== PAUSE TestClientMultipleUploads548=== RUN TestClientWithDependencies549=== PAUSE TestClientWithDependencies550=== RUN TestClientSharedPathCommittedMidPush551=== PAUSE TestClientSharedPathCommittedMidPush552=== RUN TestPinProtectsFromGC553=== PAUSE TestPinProtectsFromGC554=== RUN TestClientPushesUseOnePush555=== PAUSE TestClientPushesUseOnePush556=== RUN TestClientFallsBackToClosures557=== PAUSE TestClientFallsBackToClosures558=== RUN TestDeleteClosuresRacingPins559=== PAUSE TestDeleteClosuresRacingPins560=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock561=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock562=== RUN TestResolveDBConnectionString563=== PAUSE TestResolveDBConnectionString564=== RUN TestConnectWaitsForAPeerMigration565=== PAUSE TestConnectWaitsForAPeerMigration566=== RUN TestLeadElectsOneAndHandsOver567=== PAUSE TestLeadElectsOneAndHandsOver568=== RUN TestLeadIncumbentWinsAfterRestart5692026/10/25 19:00:59 INFO lead: acquired remote=192.0.2.1:12345702026/10/25 19:01:00 INFO lead: released remote=192.0.2.1:12345712026/10/25 19:01:00 INFO lead: acquired remote=192.0.2.1:12345722026/10/25 19:01:01 INFO lead: released remote=192.0.2.1:1234573--- PASS: TestLeadIncumbentWinsAfterRestart (1.87s)574=== RUN TestLeadIncumbentAnnouncesAtOnce575=== PAUSE TestLeadIncumbentAnnouncesAtOnce576=== RUN TestLeadEndsOnShutdown577=== PAUSE TestLeadEndsOnShutdown578=== RUN TestLeadEndsWhenItsConnectionHangs5792026/10/25 19:01:01 INFO lead: acquired remote=192.0.2.1:12345802026-10-25 19:01:02.917 UTC [316] FATAL: terminating connection due to administrator command5812026/10/25 19:01:03 INFO lead: acquired remote=192.0.2.1:12345822026/10/25 19:01:04 WARN lead: lock connection lost error="timeout: context deadline exceeded"5832026/10/25 19:01:04 INFO lead: released remote=192.0.2.1:12345842026/10/25 19:01:04 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)586=== RUN TestGCAdvisoryLockBlocksConcurrentRun587=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun588=== RUN TestGCBugBareHashReferences589=== PAUSE TestGCBugBareHashReferences590=== RUN TestGCMetrics591=== PAUSE TestGCMetrics592=== RUN TestPushDedupSurvivesConcurrentGC593=== PAUSE TestPushDedupSurvivesConcurrentGC594=== RUN TestDeduplicatedObjectsRecordedAsPending595=== PAUSE TestDeduplicatedObjectsRecordedAsPending596=== RUN TestGCSweepSkipsPendingObjects597=== PAUSE TestGCSweepSkipsPendingObjects598=== RUN TestTombstonedObjectOfferedWithoutWaiting599=== PAUSE TestTombstonedObjectOfferedWithoutWaiting600=== RUN TestGCSweepDeliversEachKeyOnce601=== PAUSE TestGCSweepDeliversEachKeyOnce602=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection603=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection604=== RUN TestForceGCDuringPushOffersSweptObject605=== PAUSE TestForceGCDuringPushOffersSweptObject606=== RUN TestFailedS3DeleteKeepsTombstone607=== PAUSE TestFailedS3DeleteKeepsTombstone608=== RUN TestSweepSkipsRowsLockedByPush609=== PAUSE TestSweepSkipsRowsLockedByPush610=== RUN TestRegisterCompletedObjectNeedsPendingRow611=== PAUSE TestRegisterCompletedObjectNeedsPendingRow612=== RUN TestGetExistingObjectsLocksRows613=== PAUSE TestGetExistingObjectsLocksRows614=== RUN TestSweepRechecksPendingAfterLocking615=== PAUSE TestSweepRechecksPendingAfterLocking616=== RUN TestPushWaitsForSweepHoldingRow617=== PAUSE TestPushWaitsForSweepHoldingRow618=== RUN TestCommitRacingPendingCleanupKeepsObjects619=== PAUSE TestCommitRacingPendingCleanupKeepsObjects620=== RUN TestGCEndsOnShutdown621=== PAUSE TestGCEndsOnShutdown622=== RUN TestGCTaskStore_StartNew623=== PAUSE TestGCTaskStore_StartNew624=== RUN TestGCTaskStore_DeduplicateSameParams625=== PAUSE TestGCTaskStore_DeduplicateSameParams626=== RUN TestGCTaskStore_ConflictDifferentParams627=== PAUSE TestGCTaskStore_ConflictDifferentParams628=== RUN TestGCTaskStore_GetEmpty629=== PAUSE TestGCTaskStore_GetEmpty630=== RUN TestGCTaskStore_GetReturnsLatest631=== PAUSE TestGCTaskStore_GetReturnsLatest632=== RUN TestGCTaskStore_CompletedAllowsNewTask633=== PAUSE TestGCTaskStore_CompletedAllowsNewTask634=== RUN TestGCTaskStore_PhaseUpdates635=== PAUSE TestGCTaskStore_PhaseUpdates636=== RUN TestGCTaskStore_Fail637=== PAUSE TestGCTaskStore_Fail638=== RUN TestGracefulShutdownDrainsInflight639=== PAUSE TestGracefulShutdownDrainsInflight640=== RUN TestService_healthCheckHandler641=== PAUSE TestService_healthCheckHandler642=== RUN TestService_readinessHandler643=== PAUSE TestService_readinessHandler644=== RUN TestGenerateLandingPage645=== PAUSE TestGenerateLandingPage646=== RUN TestCacheConfigHandlerMaxNarSize647=== PAUSE TestCacheConfigHandlerMaxNarSize648=== RUN TestCreatePendingClosureRejectsOversizedNAR649=== PAUSE TestCreatePendingClosureRejectsOversizedNAR650=== RUN TestNARDeduplicationMetadataUploadBug651=== PAUSE TestNARDeduplicationMetadataUploadBug652=== RUN TestMetricsInventory653=== PAUSE TestMetricsInventory654=== RUN TestMetricsCommit655=== PAUSE TestMetricsCommit656=== RUN TestService_NativeMTLS657=== PAUSE TestService_NativeMTLS658=== RUN TestServerTLSConfig659=== PAUSE TestServerTLSConfig660=== RUN TestMultipartCleanup661=== PAUSE TestMultipartCleanup662=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded663=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded664=== RUN TestPendingCleanupUsesOneCutoff665=== PAUSE TestPendingCleanupUsesOneCutoff666=== RUN TestObjectStatsTrigger667=== PAUSE TestObjectStatsTrigger668=== RUN TestObjectStatsUpdatedOncePerCommit669=== PAUSE TestObjectStatsUpdatedOncePerCommit670=== RUN TestOrphanedObjectsGC671=== PAUSE TestOrphanedObjectsGC672=== RUN TestOrphanedObjectsGCStressTest673=== PAUSE TestOrphanedObjectsGCStressTest674=== RUN TestCreatePin_ReservedPins675=== PAUSE TestCreatePin_ReservedPins676=== RUN TestPresentReportsOnlyClosureRoots677=== PAUSE TestPresentReportsOnlyClosureRoots678=== RUN TestPresentRefreshesOnlyStaleClosures679=== PAUSE TestPresentRefreshesOnlyStaleClosures680=== RUN TestPresentNotReportedWhileGCDeletesClosure681=== PAUSE TestPresentNotReportedWhileGCDeletesClosure682=== RUN TestParseSingleRange683=== PAUSE TestParseSingleRange684=== RUN TestProxyHeadersOnlyTrustedOnSocket6852026/10/25 19:01:04 INFO Starting HTTP server address=127.0.0.1:445516862026/10/25 19:01:04 INFO Starting HTTP server address=proxy.sock6872026/10/25 19:01:04 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6882026/10/25 19:01:04 INFO Shutdown signal received, draining in-flight requests timeout=10s689--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.10s)690=== RUN TestIsValidCachePath691=== PAUSE TestIsValidCachePath692=== RUN TestReadProxyNarinfo693=== PAUSE TestReadProxyNarinfo694=== RUN TestReadProxyNarinfoAlreadyDecompressed695=== PAUSE TestReadProxyNarinfoAlreadyDecompressed696=== RUN TestReadProxyContentNegotiation697=== PAUSE TestReadProxyContentNegotiation698=== RUN TestReadProxyNarStreaming699=== PAUSE TestReadProxyNarStreaming700=== RUN TestReadProxy404701=== PAUSE TestReadProxy404702=== RUN TestReadProxyInvalidPath703=== PAUSE TestReadProxyInvalidPath704=== RUN TestReadProxyHead705=== PAUSE TestReadProxyHead706=== RUN TestReadProxyOutlastsServerWriteTimeout707=== PAUSE TestReadProxyOutlastsServerWriteTimeout708=== RUN TestReadProxyConditionalGet709=== PAUSE TestReadProxyConditionalGet710=== RUN TestReadProxyRootRedirectsToIndexHTML711=== PAUSE TestReadProxyRootRedirectsToIndexHTML712=== RUN TestReadProxyDisabled713=== PAUSE TestReadProxyDisabled714=== RUN TestReadRedirectNar715=== PAUSE TestReadRedirectNar716=== RUN TestReadRedirectKeepsNarinfoProxied717=== PAUSE TestReadRedirectKeepsNarinfoProxied718=== RUN TestReadProxyRangeRequest719=== PAUSE TestReadProxyRangeRequest720=== RUN TestReadRedirectUsesPublicS3URL721=== PAUSE TestReadRedirectUsesPublicS3URL722=== RUN TestPush_OverlappingRootsStoreOneRowPerKey723=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey724=== RUN TestPush_CompleteCommitsEveryRoot725=== PAUSE TestPush_CompleteCommitsEveryRoot726=== RUN TestPush_RepeatedRootCommitsOnce727=== PAUSE TestPush_RepeatedRootCommitsOnce728=== RUN TestPush_CompleteWaitsForCleanupOfThePush729=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush730=== RUN TestPush_RootsAreLockedInByteOrder731=== PAUSE TestPush_RootsAreLockedInByteOrder732=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit733=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit734=== RUN TestPush_RejectsBadRequests735=== PAUSE TestPush_RejectsBadRequests736=== RUN TestPush_SignsNarinfosOfItsPendingObjects737=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects738=== RUN TestRedundantMultipartUpload739=== PAUSE TestRedundantMultipartUpload740=== RUN TestCompleteMultipartUpload_ErrorButObjectExists741=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists742=== RUN TestCompletedNarNotReofferedAcrossClosures743=== PAUSE TestCompletedNarNotReofferedAcrossClosures744=== RUN TestPresignedUploadRegisteredBeforeCommit745=== PAUSE TestPresignedUploadRegisteredBeforeCommit746=== RUN TestService_Rustfstest747=== PAUSE TestService_Rustfstest748=== RUN TestParseSize749=== PAUSE TestParseSize750=== RUN TestSkippedUploadsHandler751=== PAUSE TestSkippedUploadsHandler752=== RUN TestSystemdListenerNotActivated753--- PASS: TestSystemdListenerNotActivated (0.00s)754=== RUN TestWatchdogBeatsWhenHealthy755--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)756=== RUN TestWatchdogSkipsWhenUnhealthy7572026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 19:01:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"767--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)768=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle769=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle770=== RUN TestProxyWriteTimeout771=== PAUSE TestProxyWriteTimeout772=== RUN TestPendingClosureWriteTimeout773=== PAUSE TestPendingClosureWriteTimeout774=== RUN TestIsValidUploadKey775=== PAUSE TestIsValidUploadKey776=== RUN TestUploadHandlersRejectInvalidKeys777=== PAUSE TestUploadHandlersRejectInvalidKeys778=== RUN TestUploadHandlersRejectOversizedBody779=== PAUSE TestUploadHandlersRejectOversizedBody780=== RUN TestService_cleanupPendingClosuresHandler781=== PAUSE TestService_cleanupPendingClosuresHandler782=== RUN TestService_createPendingClosureHandler783=== PAUSE TestService_createPendingClosureHandler784=== RUN TestService_verifyS3Integrity785=== PAUSE TestService_verifyS3Integrity786=== RUN TestCompleteMultipartUnregistered787=== PAUSE TestCompleteMultipartUnregistered788=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT789=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT790=== CONT TestService_AuthMiddleware791=== CONT TestMetricsInventory792=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT793=== CONT TestCompleteMultipartUnregistered794=== CONT TestService_verifyS3Integrity795=== CONT TestService_createPendingClosureHandler796=== CONT TestService_cleanupPendingClosuresHandler797=== CONT TestUploadHandlersRejectOversizedBody798=== CONT TestUploadHandlersRejectInvalidKeys799=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info800=== CONT TestIsValidUploadKey801=== CONT TestPendingClosureWriteTimeout802=== RUN TestPendingClosureWriteTimeout/empty803=== CONT TestProxyWriteTimeout804=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle805=== CONT TestSkippedUploadsHandler806=== CONT TestParseSize807=== CONT TestService_Rustfstest808=== CONT TestPresignedUploadRegisteredBeforeCommit809=== CONT TestCompletedNarNotReofferedAcrossClosures810=== CONT TestPush_CompleteWaitsForCleanupOfThePush811=== CONT TestCompleteMultipartUpload_ErrorButObjectExists812=== CONT TestPush_SignsNarinfosOfItsPendingObjects813=== CONT TestPush_RejectsBadRequests8142026/10/25 19:01:04 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000815=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit816=== CONT TestPush_RootsAreLockedInByteOrder817=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info818=== RUN TestIsValidUploadKey/narinfo819=== PAUSE TestPendingClosureWriteTimeout/empty820=== RUN TestProxyWriteTimeout/narinfo821=== RUN TestPendingClosureWriteTimeout/400_objects822--- PASS: TestParseSize (0.00s)823=== CONT TestRedundantMultipartUpload824=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal825=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal826=== PAUSE TestProxyWriteTimeout/narinfo827=== PAUSE TestPendingClosureWriteTimeout/400_objects828=== PAUSE TestIsValidUploadKey/narinfo829=== RUN TestIsValidUploadKey/nar_zst830=== PAUSE TestIsValidUploadKey/nar_zst831=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key832=== RUN TestProxyWriteTimeout/1_GiB_nar833=== PAUSE TestProxyWriteTimeout/1_GiB_nar834=== RUN TestPendingClosureWriteTimeout/670k_objects835=== PAUSE TestPendingClosureWriteTimeout/670k_objects836=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key837=== RUN TestProxyWriteTimeout/10_GiB_nar838=== PAUSE TestProxyWriteTimeout/10_GiB_nar839=== RUN TestProxyWriteTimeout/unknown_size840=== PAUSE TestProxyWriteTimeout/unknown_size841=== RUN TestIsValidUploadKey/nar_xz842=== PAUSE TestIsValidUploadKey/nar_xz843=== RUN TestIsValidUploadKey/nar_plain844=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline845=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key846=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline847=== PAUSE TestIsValidUploadKey/nar_plain848=== RUN TestIsValidUploadKey/listing849=== PAUSE TestIsValidUploadKey/listing850=== RUN TestIsValidUploadKey/build_log851=== PAUSE TestIsValidUploadKey/build_log852=== RUN TestIsValidUploadKey/build_log_home-manager_file853=== PAUSE TestIsValidUploadKey/build_log_home-manager_file854=== CONT TestPush_RepeatedRootCommitsOnce855=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key856=== CONT TestPush_CompleteCommitsEveryRoot857=== RUN TestIsValidUploadKey/build_log_plus_in_name858=== PAUSE TestIsValidUploadKey/build_log_plus_in_name859=== CONT TestPush_OverlappingRootsStoreOneRowPerKey860=== RUN TestIsValidUploadKey/build_log_question_mark861=== PAUSE TestIsValidUploadKey/build_log_question_mark862=== RUN TestIsValidUploadKey/build_log_equals863=== PAUSE TestIsValidUploadKey/build_log_equals864=== RUN TestIsValidUploadKey/realisation865=== PAUSE TestIsValidUploadKey/realisation866=== RUN TestIsValidUploadKey/realisation_plus_in_output867=== PAUSE TestIsValidUploadKey/realisation_plus_in_output868=== RUN TestIsValidUploadKey/nix-cache-info869=== PAUSE TestIsValidUploadKey/nix-cache-info870=== RUN TestIsValidUploadKey/index.html871=== PAUSE TestIsValidUploadKey/index.html872=== RUN TestIsValidUploadKey/narinfo_key,_nar_type873=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type874=== RUN TestIsValidUploadKey/nar_key,_narinfo_type875=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type876=== RUN TestIsValidUploadKey/listing_key,_narinfo_type877=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type878=== RUN TestIsValidUploadKey/traversal879=== PAUSE TestIsValidUploadKey/traversal880=== RUN TestIsValidUploadKey/traversal_nar881=== PAUSE TestIsValidUploadKey/traversal_nar882=== RUN TestIsValidUploadKey/absolute883=== PAUSE TestIsValidUploadKey/absolute884=== RUN TestIsValidUploadKey/empty_key885=== PAUSE TestIsValidUploadKey/empty_key886=== RUN TestIsValidUploadKey/unknown_type887=== PAUSE TestIsValidUploadKey/unknown_type888=== CONT TestReadRedirectUsesPublicS3URL889--- PASS: TestSkippedUploadsHandler (0.09s)890=== CONT TestReadProxyRangeRequest891=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts892=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts893=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure894=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure895=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart896=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart897=== CONT TestReadRedirectKeepsNarinfoProxied8982026/10/25 19:01:05 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"899--- PASS: TestService_AuthMiddleware (0.27s)900=== CONT TestReadRedirectNar9012026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures902--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.31s)903=== CONT TestReadProxyDisabled9042026/10/25 19:01:05 INFO Received cleanup request method=DELETE path=/api/pending_closures9052026/10/25 19:01:05 INFO Aborted multipart uploads count=0 kept=09062026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9072026/10/25 19:01:05 INFO Received cleanup request method=DELETE path=/api/pending_closures9082026/10/25 19:01:05 INFO Aborted multipart uploads count=1 kept=09092026/10/25 19:01:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9102026-10-25 19:01:05.194 UTC [386] ERROR: Closure does not exist: id=19112026-10-25 19:01:05.194 UTC [386] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9122026-10-25 19:01:05.194 UTC [386] STATEMENT: -- name: CommitPendingClosure :one913 SELECT commit_pending_closure($1::bigint)::bigint914 915--- PASS: TestService_cleanupPendingClosuresHandler (0.34s)916=== CONT TestReadProxyRootRedirectsToIndexHTML9172026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures918--- PASS: TestMetricsInventory (0.36s)919=== CONT TestReadProxyConditionalGet9202026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9212026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9222026/10/25 19:01:05 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LmIzMTY5YTc1LTQ0Y2QtNDQxYy05YjM4LTI3YTQwOTAwNDJkMngxNzkyOTU0ODY1MjE5NjM0MDg49232026/10/25 19:01:05 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LmIzMTY5YTc1LTQ0Y2QtNDQxYy05YjM4LTI3YTQwOTAwNDJkMngxNzkyOTU0ODY1MjE5NjM0MDg4 parts=1924--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.40s)925=== CONT TestReadProxyOutlastsServerWriteTimeout926=== RUN TestPush_RejectsBadRequests/root_not_in_objects927=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects928=== RUN TestPush_RejectsBadRequests/no_roots929=== PAUSE TestPush_RejectsBadRequests/no_roots930=== RUN TestPush_RejectsBadRequests/no_objects931=== PAUSE TestPush_RejectsBadRequests/no_objects932=== RUN TestPush_RejectsBadRequests/bad_root933=== PAUSE TestPush_RejectsBadRequests/bad_root934=== CONT TestReadProxyHead935--- PASS: TestService_Rustfstest (0.42s)936=== CONT TestReadProxyInvalidPath9372026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9382026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9392026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9402026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9422026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures9432026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9442026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9452026/10/25 19:01:05 INFO Received complete push request method=POST path=/api/pushes/1/complete9462026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9472026/10/25 19:01:05 INFO Completed push id=1 objects=4 duration=6.012087ms9482026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9492026/10/25 19:01:05 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst950--- PASS: TestCompleteMultipartUnregistered (0.56s)951=== CONT TestReadProxy4049522026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9532026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9542026/10/25 19:01:05 INFO Received complete push request method=POST path=/api/pushes/1/complete9552026/10/25 19:01:05 INFO Aborted multipart uploads count=0 kept=09562026/10/25 19:01:05 INFO Completed push id=1 objects=4 duration=7.475576ms957--- PASS: TestPush_RepeatedRootCommitsOnce (0.53s)958=== CONT TestReadProxyNarStreaming9592026/10/25 19:01:05 WARN Force mode enabled - objects will be deleted immediately without grace period9602026/10/25 19:01:05 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=09612026-10-25 19:01:05.496 UTC [452] ERROR: could not obtain lock on row in relation "closures"9622026-10-25 19:01:05.496 UTC [452] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9632026-10-25 19:01:05.496 UTC [452] ERROR: could not obtain lock on row in relation "closures"9642026-10-25 19:01:05.496 UTC [452] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9652026-10-25 19:01:05.496 UTC [452] ERROR: could not obtain lock on row in relation "closures"9662026-10-25 19:01:05.496 UTC [452] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9672026-10-25 19:01:05.497 UTC [452] ERROR: could not obtain lock on row in relation "closures"9682026-10-25 19:01:05.497 UTC [452] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9692026-10-25 19:01:05.497 UTC [452] ERROR: could not obtain lock on row in relation "closures"9702026-10-25 19:01:05.497 UTC [452] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9712026/10/25 19:01:05 INFO Vacuumed table table=pending_closures9722026/10/25 19:01:05 INFO Vacuumed table table=pending_objects973--- PASS: TestPush_RootsAreLockedInByteOrder (0.56s)974=== CONT TestReadProxyContentNegotiation975--- PASS: TestReadRedirectUsesPublicS3URL (0.56s)976=== CONT TestReadProxyNarinfoAlreadyDecompressed9772026/10/25 19:01:05 INFO Vacuumed table table=multipart_uploads9782026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9792026/10/25 19:01:05 INFO Vacuumed table table=closures9802026/10/25 19:01:05 INFO Vacuumed table table=objects9812026/10/25 19:01:05 INFO Received complete push request method=POST path=/api/pushes/2/complete9822026/10/25 19:01:05 INFO Completed push id=2 objects=4 duration=2.555079ms983--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.65s)984=== CONT TestReadProxyNarinfo9852026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes986--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.59s)987=== CONT TestObjectStatsUpdatedOncePerCommit9882026/10/25 19:01:05 INFO Received complete push request method=POST path=/api/pushes/1/complete989--- PASS: TestReadProxyRangeRequest (0.61s)990=== CONT TestObjectStatsTrigger9912026/10/25 19:01:05 INFO Completed push id=1 objects=6 duration=8.381596ms992--- PASS: TestPush_CompleteCommitsEveryRoot (0.62s)993=== CONT TestPendingCleanupUsesOneCutoff9942026/10/25 19:01:05 INFO Received push request method=POST path=/api/pushes9952026/10/25 19:01:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9962026/10/25 19:01:05 INFO Signed narinfos id=1 count=19972026/10/25 19:01:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9982026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9992026/10/25 19:01:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10002026/10/25 19:01:05 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10012026/10/25 19:01:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10022026/10/25 19:01:05 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10032026/10/25 19:01:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10042026/10/25 19:01:05 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110052026/10/25 19:01:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10062026/10/25 19:01:05 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1007--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.73s)1008=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10092026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures10102026/10/25 19:01:05 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10112026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures10122026/10/25 19:01:05 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LmIwMjQ2YjEyLTFiNjYtNDA5MC1iYmVhLTRkZGJkOTg1ODY3MXgxNzkyOTU0ODY1MjQzNTgyNzI4 parts=1010132026/10/25 19:01:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10142026/10/25 19:01:05 INFO Completed upload id=1 objects=2 duration=3.993198ms1015--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.76s)1016=== CONT TestMultipartCleanup10172026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures1018--- PASS: TestReadRedirectKeepsNarinfoProxied (0.60s)1019=== CONT TestServerTLSConfig1020=== RUN TestServerTLSConfig/no_client_CA1021=== PAUSE TestServerTLSConfig/no_client_CA1022=== RUN TestServerTLSConfig/missing_CA_file1023=== PAUSE TestServerTLSConfig/missing_CA_file1024=== RUN TestServerTLSConfig/not_a_PEM_file1025=== PAUSE TestServerTLSConfig/not_a_PEM_file1026=== CONT TestService_NativeMTLS10272026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/25 19:01:05 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10292026/10/25 19:01:05 WARN Found objects in DB but missing from S3, will re-upload count=110302026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures1031--- PASS: TestService_verifyS3Integrity (0.78s)1032=== CONT TestMetricsCommit10332026-10-25 19:01:05.647 UTC [432] ERROR: Push does not exist: id=110342026-10-25 19:01:05.647 UTC [432] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10352026-10-25 19:01:05.647 UTC [432] STATEMENT: SELECT commit_push($1)1036--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.79s)1037=== CONT TestPresentRefreshesOnlyStaleClosures10382026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures1039--- PASS: TestReadRedirectNar (0.55s)1040=== CONT TestIsValidCachePath1041=== RUN TestIsValidCachePath/narinfo1042=== PAUSE TestIsValidCachePath/narinfo1043=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1044=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1045=== RUN TestIsValidCachePath/nar_zst1046=== PAUSE TestIsValidCachePath/nar_zst1047=== RUN TestIsValidCachePath/nar_xz1048=== PAUSE TestIsValidCachePath/nar_xz1049=== RUN TestIsValidCachePath/nar_bz21050=== PAUSE TestIsValidCachePath/nar_bz21051=== RUN TestIsValidCachePath/nar_uncompressed1052=== PAUSE TestIsValidCachePath/nar_uncompressed1053=== RUN TestIsValidCachePath/ls1054=== PAUSE TestIsValidCachePath/ls1055=== RUN TestIsValidCachePath/log1056=== PAUSE TestIsValidCachePath/log1057=== RUN TestIsValidCachePath/realisation1058=== PAUSE TestIsValidCachePath/realisation1059=== RUN TestIsValidCachePath/nix-cache-info1060=== PAUSE TestIsValidCachePath/nix-cache-info1061=== RUN TestIsValidCachePath/index.html1062=== PAUSE TestIsValidCachePath/index.html1063=== RUN TestIsValidCachePath/traversal_parent1064=== PAUSE TestIsValidCachePath/traversal_parent1065=== RUN TestIsValidCachePath/traversal_in_middle1066=== PAUSE TestIsValidCachePath/traversal_in_middle1067=== RUN TestIsValidCachePath/invalid_char_e1068=== PAUSE TestIsValidCachePath/invalid_char_e1069=== RUN TestIsValidCachePath/invalid_char_u1070=== PAUSE TestIsValidCachePath/invalid_char_u1071=== RUN TestIsValidCachePath/random_path1072=== PAUSE TestIsValidCachePath/random_path1073=== RUN TestIsValidCachePath/empty1074=== PAUSE TestIsValidCachePath/empty1075=== RUN TestIsValidCachePath/leading_slash1076=== PAUSE TestIsValidCachePath/leading_slash1077=== RUN TestIsValidCachePath/wrong_extension1078=== PAUSE TestIsValidCachePath/wrong_extension1079=== RUN TestIsValidCachePath/short_hash1080=== PAUSE TestIsValidCachePath/short_hash1081=== CONT TestParseSingleRange1082=== RUN TestParseSingleRange/none1083=== PAUSE TestParseSingleRange/none1084=== RUN TestParseSingleRange/unknown_unit1085=== PAUSE TestParseSingleRange/unknown_unit1086=== RUN TestParseSingleRange/multi-range_ignored1087=== PAUSE TestParseSingleRange/multi-range_ignored1088=== RUN TestParseSingleRange/malformed_no_dash1089=== PAUSE TestParseSingleRange/malformed_no_dash1090=== RUN TestParseSingleRange/malformed_both_empty1091=== PAUSE TestParseSingleRange/malformed_both_empty1092=== RUN TestParseSingleRange/malformed_end_before_start1093=== PAUSE TestParseSingleRange/malformed_end_before_start1094=== RUN TestParseSingleRange/closed1095=== PAUSE TestParseSingleRange/closed1096=== RUN TestParseSingleRange/open-ended1097=== PAUSE TestParseSingleRange/open-ended1098=== RUN TestParseSingleRange/end_clamped_to_size1099=== PAUSE TestParseSingleRange/end_clamped_to_size1100=== RUN TestParseSingleRange/suffix1101=== PAUSE TestParseSingleRange/suffix1102=== RUN TestParseSingleRange/suffix_exceeds_size1103=== PAUSE TestParseSingleRange/suffix_exceeds_size1104=== RUN TestParseSingleRange/single_byte1105=== PAUSE TestParseSingleRange/single_byte1106=== RUN TestParseSingleRange/start_past_EOF1107=== PAUSE TestParseSingleRange/start_past_EOF1108=== RUN TestParseSingleRange/start_far_past_EOF1109=== PAUSE TestParseSingleRange/start_far_past_EOF1110=== CONT TestPresentNotReportedWhileGCDeletesClosure1111=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1112=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1113=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1114=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1115=== CONT TestDeduplicatedObjectsRecordedAsPending11162026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1117--- PASS: TestReadProxyDisabled (0.64s)1118=== CONT TestOrphanedObjectsGC11192026/10/25 19:01:05 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LjlkNmZjNzBlLWVmOTAtNDA3ZS1iM2VjLTg3MWEwNzBhZjc4ZHgxNzkyOTU0ODY1Mzc4Mzk2MjE3 parts=1011202026/10/25 19:01:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11212026/10/25 19:01:05 INFO Completed upload id=1 objects=2 duration=3.464828ms11222026/10/25 19:01:05 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011232026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures11242026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11252026/10/25 19:01:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures11262026/10/25 19:01:05 INFO Aborted multipart uploads count=0 kept=01127--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.67s)1128=== CONT TestNARDeduplicationMetadataUploadBug11292026/10/25 19:01:05 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LmJjZTVkYTE1LTI0OGQtNGEwYy1hZTUyLTJkMGM5YTdiM2M0OHgxNzkyOTU0ODY1MzU2NjMzNTc3 parts=1211302026/10/25 19:01:05 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=011312026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures11322026/10/25 19:01:05 INFO Vacuumed table table=pending_closures1133--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.01s)1134=== CONT TestPresentReportsOnlyClosureRoots11352026/10/25 19:01:05 INFO Vacuumed table table=pending_objects11362026/10/25 19:01:05 INFO Vacuumed table table=multipart_uploads1137--- PASS: TestReadProxyConditionalGet (0.68s)1138=== CONT TestCreatePendingClosureRejectsOversizedNAR11392026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures1140--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1141=== CONT TestCreatePin_ReservedPins11422026/10/25 19:01:05 INFO Vacuumed table table=closures11432026/10/25 19:01:05 INFO Vacuumed table table=objects11442026/10/25 19:01:05 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001145--- PASS: TestService_createPendingClosureHandler (1.04s)1146=== CONT TestCacheConfigHandlerMaxNarSize1147--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1148=== CONT TestOrphanedObjectsGCStressTest1149--- PASS: TestReadProxyHead (0.68s)1150=== CONT TestGenerateLandingPage1151--- PASS: TestGenerateLandingPage (0.00s)1152=== CONT TestGCEndsOnShutdown1153=== RUN TestGCEndsOnShutdown/before_the_run1154=== PAUSE TestGCEndsOnShutdown/before_the_run1155=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1156=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1157=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1158=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1159=== CONT TestCommitRacingPendingCleanupKeepsObjects1160--- PASS: TestReadProxyInvalidPath (0.68s)1161=== CONT TestPushWaitsForSweepHoldingRow1162--- PASS: TestReadProxyNarStreaming (0.55s)1163=== CONT TestSweepRechecksPendingAfterLocking1164--- PASS: TestReadProxy404 (0.62s)1165=== CONT TestService_readinessHandler1166--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.57s)1167=== CONT TestGetExistingObjectsLocksRows1168--- PASS: TestReadProxyContentNegotiation (0.58s)1169=== CONT TestRegisterCompletedObjectNeedsPendingRow11702026/10/25 19:01:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40341/oidc1171--- PASS: TestObjectStatsUpdatedOncePerCommit (0.62s)1172=== CONT TestService_healthCheckHandler11732026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures1174--- PASS: TestObjectStatsTrigger (0.61s)1175=== CONT TestSweepSkipsRowsLockedByPush11762026/10/25 19:01:06 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1177--- PASS: TestReadProxyNarinfo (0.66s)1178=== CONT TestGracefulShutdownDrainsInflight11792026/10/25 19:01:06 INFO Starting HTTP server address=127.0.0.1:4117711802026/10/25 19:01:06 INFO Shutdown signal received, draining in-flight requests timeout=10s11812026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures11822026/10/25 19:01:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11832026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures11842026/10/25 19:01:06 INFO Received cleanup request method=DELETE path=/api/pending_closures1185--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.61s)1186=== CONT TestFailedS3DeleteKeepsTombstone11872026/10/25 19:01:06 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LjM4ZjgyOWIxLWIwYTMtNDg3NS1hNjY1LTk2ZWNlNzUxOWZkZXgxNzkyOTU0ODY1NjUzMzQxNTYz parts=1211882026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures11892026/10/25 19:01:06 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11902026/10/25 19:01:06 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1191--- PASS: TestService_NativeMTLS (0.59s)1192=== CONT TestForceGCDuringPushOffersSweptObject1193=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1194=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1195=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1196=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1197=== CONT TestGCTaskStore_Fail1198--- PASS: TestGCTaskStore_Fail (0.00s)1199=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12002026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures12012026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures1202--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1203=== CONT TestGCSweepDeliversEachKeyOnce1204--- PASS: TestPresentRefreshesOnlyStaleClosures (0.62s)1205=== CONT TestTombstonedObjectOfferedWithoutWaiting12062026/10/25 19:01:06 INFO Received push request method=POST path=/api/pushes12072026/10/25 19:01:06 INFO Received complete push request method=POST path=/api/pushes/1/complete12082026/10/25 19:01:06 INFO Completed push id=1 objects=4 duration=8.639537ms12092026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures12102026/10/25 19:01:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12112026/10/25 19:01:06 INFO Completed upload id=2 objects=2 duration=2.775059ms1212--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.63s)1213=== CONT TestGCSweepSkipsPendingObjects1214--- PASS: TestMetricsCommit (0.67s)1215=== CONT TestGCTaskStore_PhaseUpdates1216--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1217=== CONT TestGCTaskStore_CompletedAllowsNewTask1218--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1219=== CONT TestGCTaskStore_ConflictDifferentParams1220--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1221=== CONT TestGCTaskStore_DeduplicateSameParams1222--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1223=== CONT TestGCTaskStore_GetReturnsLatest1224--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1225=== CONT TestGCTaskStore_GetEmpty1226--- PASS: TestGCTaskStore_GetEmpty (0.00s)1227=== CONT TestGCTaskStore_StartNew1228--- PASS: TestGCTaskStore_StartNew (0.00s)1229=== CONT TestLeadElectsOneAndHandsOver12302026/10/25 19:01:06 INFO Received cleanup request method=DELETE path=/api/pending_closures12312026/10/25 19:01:06 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket45/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12322026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=112332026/10/25 19:01:06 INFO Received cleanup request method=DELETE path=/api/pending_closures12342026/10/25 19:01:06 INFO Aborted multipart uploads count=1 kept=01235--- PASS: TestMultipartCleanup (0.74s)1236=== CONT TestCacheStatsHandler1237=== NAME TestNARDeduplicationMetadataUploadBug1238 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug4288059803/001/store/57b7yzy321lwr1p22kxsg7p5kp76yyp4-file1.txt1239--- PASS: TestPresentReportsOnlyClosureRoots (0.52s)1240=== CONT TestPushDedupSurvivesConcurrentGC12412026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures12422026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=012432026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period12442026/10/25 19:01:06 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=012452026/10/25 19:01:06 INFO Vacuumed table table=pending_closures12462026/10/25 19:01:06 INFO Received push request method=POST path=/api/pushes12472026/10/25 19:01:06 INFO Vacuumed table table=pending_objects12482026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads12492026/10/25 19:01:06 INFO Vacuumed table table=closures12502026/10/25 19:01:06 INFO Vacuumed table table=objects12512026/10/25 19:01:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12522026/10/25 19:01:06 INFO Uploading 57b7yzy321lwr1p22kxsg7p5kp76yyp4-file1.txt (160B)12532026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=01254--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.54s)1255=== CONT TestClientSharedPathCommittedMidPush12562026/10/25 19:01:06 WARN Failed to register uploaded object key=57b7yzy321lwr1p22kxsg7p5kp76yyp4.ls error="server returned 404: 404 page not found\n"12572026/10/25 19:01:06 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12582026/10/25 19:01:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12592026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period12602026/10/25 19:01:06 INFO Signed narinfos id=1 count=112612026/10/25 19:01:06 INFO Uploading 1 narinfos12622026/10/25 19:01:06 WARN readiness check failed error="closed pool"1263--- PASS: TestService_readinessHandler (0.44s)1264=== CONT TestGCMetrics12652026/10/25 19:01:06 INFO Received complete push request method=POST path=/api/pushes/1/complete12662026/10/25 19:01:06 WARN Failed to register uploaded object key=57b7yzy321lwr1p22kxsg7p5kp76yyp4.narinfo error="server returned 404: 404 page not found\n"12672026/10/25 19:01:06 INFO Completed push id=1 objects=3 duration=6.670677ms12682026/10/25 19:01:06 INFO Upload complete. (62ms)12692026/10/25 19:01:06 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=01270=== NAME TestNARDeduplicationMetadataUploadBug1271 metadata_upload_test.go:54: Retrieved narinfo from S3:1272 StorePath: /build/TestNARDeduplicationMetadataUploadBug4288059803/001/store/57b7yzy321lwr1p22kxsg7p5kp76yyp4-file1.txt1273 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1274 Compression: zstd1275 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1276 NarSize: 1601277 References: 1278 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1279 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1280 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1281 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12822026/10/25 19:01:06 INFO Vacuumed table table=pending_closures12832026/10/25 19:01:06 INFO Vacuumed table table=pending_objects12842026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads12852026/10/25 19:01:06 INFO Vacuumed table table=closures12862026/10/25 19:01:06 INFO Vacuumed table table=objects1287--- PASS: TestSweepRechecksPendingAfterLocking (0.48s)1288=== CONT TestClientWithDependencies1289--- PASS: TestGetExistingObjectsLocksRows (0.44s)1290=== CONT TestGCBugBareHashReferences1291=== NAME TestNARDeduplicationMetadataUploadBug1292 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug4288059803/001/store/mcrdyn2jngb3jhwyr12gbrir2p95ckv2-file2.txt1293--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.45s)1294=== CONT TestGCAdvisoryLockBlocksConcurrentRun12952026/10/25 19:01:06 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12962026/10/25 19:01:06 WARN Refused reserved pin name=worker-x86_64-linux12972026/10/25 19:01:06 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12982026/10/25 19:01:06 INFO Received create pin request method=POST path=/api/pins/my-app12992026/10/25 19:01:06 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1300--- PASS: TestCreatePin_ReservedPins (0.66s)1301=== CONT TestClientMultipleUploads1302--- PASS: TestService_healthCheckHandler (0.42s)1303=== CONT TestLeadEndsOnShutdown13042026/10/25 19:01:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13052026/10/25 19:01:06 INFO Received push request method=POST path=/api/pushes13062026/10/25 19:01:06 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2Ljk2NTBmMmMxLWVmNTQtNDFmOS05NDk2LWU0NjMyOWRhMDgxOHgxNzkyOTU0ODY2MjIxMTgxMzY3 error="Get \"http://127.0.0.1:1/bucket27/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13072026/10/25 19:01:06 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=N2FhZjRiM2YtYmM4Mi00ZjE0LTg1NDYtODk2YjM5MzJiMTc2LjUzODU2MWI0LTJjMmYtNGVhZi05NDY1LTdmZWRiN2Q0NzIxZHgxNzkyOTU0ODY2MjE0Mjc2NTcw parts=1213082026/10/25 19:01:06 INFO Received cleanup request method=DELETE path=/api/pending_closures13092026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=013102026/10/25 19:01:06 INFO Aborted multipart uploads count=1 kept=013112026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period13122026/10/25 19:01:06 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=013132026/10/25 19:01:06 INFO Vacuumed table table=pending_closures13142026/10/25 19:01:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13152026/10/25 19:01:06 INFO Vacuumed table table=pending_objects13162026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads13172026/10/25 19:01:06 INFO Vacuumed table table=closures1318--- PASS: TestRedundantMultipartUpload (1.83s)1319=== CONT TestLeadIncumbentAnnouncesAtOnce13202026/10/25 19:01:06 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13212026/10/25 19:01:06 WARN Failed to register uploaded object key=mcrdyn2jngb3jhwyr12gbrir2p95ckv2.ls error="server returned 404: 404 page not found\n"13222026/10/25 19:01:06 INFO Signed narinfos id=2 count=113232026/10/25 19:01:06 INFO Uploading 1 narinfos13242026/10/25 19:01:06 INFO Vacuumed table table=objects13252026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=013262026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period13272026/10/25 19:01:06 INFO Received complete push request method=POST path=/api/pushes/2/complete13282026/10/25 19:01:06 WARN Failed to register uploaded object key=mcrdyn2jngb3jhwyr12gbrir2p95ckv2.narinfo error="server returned 404: 404 page not found\n"13292026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures13302026/10/25 19:01:06 INFO Completed push id=2 objects=3 duration=8.969886ms13312026/10/25 19:01:06 INFO Upload complete. (182ms)1332=== NAME TestNARDeduplicationMetadataUploadBug1333 metadata_upload_test.go:76: Retrieved narinfo from S3:1334 StorePath: /build/TestNARDeduplicationMetadataUploadBug4288059803/001/store/mcrdyn2jngb3jhwyr12gbrir2p95ckv2-file2.txt1335 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1336 Compression: zstd1337 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1338 NarSize: 1601339 References: 1340 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1341 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1342 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1343 {"version":1,"root":{"type":"regular","size":44}}1344--- PASS: TestNARDeduplicationMetadataUploadBug (0.89s)1345=== CONT TestClientIntegration13462026/10/25 19:01:06 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=013472026/10/25 19:01:06 INFO Vacuumed table table=pending_closures13482026/10/25 19:01:06 INFO Vacuumed table table=pending_objects13492026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads13502026/10/25 19:01:06 INFO Vacuumed table table=closures13512026/10/25 19:01:06 INFO Vacuumed table table=objects1352--- PASS: TestSweepSkipsRowsLockedByPush (0.62s)1353=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13542026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures13552026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures13562026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=01357--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.56s)1358=== CONT TestClientErrorHandling1359=== RUN TestClientErrorHandling/InvalidStorePath1360=== PAUSE TestClientErrorHandling/InvalidStorePath1361=== RUN TestClientErrorHandling/InvalidAuthToken1362=== PAUSE TestClientErrorHandling/InvalidAuthToken1363=== RUN TestClientErrorHandling/ServerNotAvailable1364=== PAUSE TestClientErrorHandling/ServerNotAvailable1365=== CONT TestConnectWaitsForAPeerMigration13662026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period1367=== NAME TestOrphanedObjectsGC1368 orphaned_objects_gc_test.go:287: GC Test Summary:1369 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1370 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1371 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1372 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1373 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1374--- PASS: TestOrphanedObjectsGC (1.03s)1375=== CONT TestPinProtectsFromGC13762026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures13772026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=013782026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period13792026/10/25 19:01:06 INFO lead: acquired remote=192.0.2.1:123413802026/10/25 19:01:06 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13812026/10/25 19:01:06 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."13822026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=013832026/10/25 19:01:06 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=01384--- PASS: TestFailedS3DeleteKeepsTombstone (0.65s)1385=== CONT TestClientCADerivations13862026/10/25 19:01:06 INFO Vacuumed table table=pending_closures13872026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period13882026/10/25 19:01:06 INFO Vacuumed table table=pending_objects13892026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads13902026/10/25 19:01:06 INFO Vacuumed table table=closures13912026/10/25 19:01:06 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=013922026/10/25 19:01:06 INFO Vacuumed table table=objects1393--- PASS: TestGCSweepDeliversEachKeyOnce (0.61s)1394=== CONT TestDeleteClosuresRacingPins13952026/10/25 19:01:06 INFO Vacuumed table table=pending_closures13962026/10/25 19:01:06 INFO Vacuumed table table=pending_objects13972026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads13982026/10/25 19:01:06 INFO Vacuumed table table=closures13992026/10/25 19:01:06 INFO Vacuumed table table=objects1400--- PASS: TestGCSweepSkipsPendingObjects (0.56s)1401=== CONT TestClientFallsBackToClosures1402--- PASS: TestCacheStatsHandler (0.52s)1403=== CONT TestClientPushesUseOnePush14042026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures14052026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=014062026/10/25 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period14072026/10/25 19:01:06 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=014082026/10/25 19:01:06 INFO Vacuumed table table=pending_closures14092026/10/25 19:01:06 INFO Vacuumed table table=pending_objects14102026/10/25 19:01:06 INFO Vacuumed table table=multipart_uploads14112026/10/25 19:01:06 INFO Vacuumed table table=closures14122026/10/25 19:01:06 INFO Vacuumed table table=objects1413--- PASS: TestGCMetrics (0.46s)1414=== CONT TestService_AuthMiddleware_OIDC1415--- PASS: TestPushWaitsForSweepHoldingRow (1.00s)1416=== CONT TestCacheConfigHandler1417=== RUN TestCacheConfigHandler/full_config,_no_issuer1418=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1419=== RUN TestCacheConfigHandler/no_cache_url_configured1420=== PAUSE TestCacheConfigHandler/no_cache_url_configured1421=== RUN TestCacheConfigHandler/no_signing_keys1422=== PAUSE TestCacheConfigHandler/no_signing_keys1423=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1424=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1425=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14262026/10/25 19:01:06 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"1427--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.44s)1428=== CONT TestService_ReadScope_PublicByDefault14292026/10/25 19:01:06 INFO lead: acquired remote=192.0.2.1:123414302026/10/25 19:01:06 INFO Aborted multipart uploads count=0 kept=014312026/10/25 19:01:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41599/oidc14322026/10/25 19:01:06 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=01433--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.79s)1434=== CONT TestService_RequireScope_OIDC14352026/10/25 19:01:07 INFO Vacuumed table table=pending_closures14362026/10/25 19:01:07 INFO Vacuumed table table=pending_objects14372026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads14382026/10/25 19:01:07 INFO Vacuumed table table=closures14392026/10/25 19:01:07 INFO Vacuumed table table=objects14402026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=014412026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period14422026/10/25 19:01:07 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=01443=== NAME TestClientWithDependencies1444 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1824437262/001/store/9rmvghai58hjpbdidwdhqbj63awrdk6k-test-script14452026/10/25 19:01:07 INFO Vacuumed table table=pending_closures14462026/10/25 19:01:07 INFO Vacuumed table table=pending_objects14472026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads14482026/10/25 19:01:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35469/oidc14492026/10/25 19:01:07 INFO lead: acquired remote=192.0.2.1:123414502026/10/25 19:01:07 INFO lead: released remote=192.0.2.1:12341451--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.34s)1452=== CONT TestService_ReadAuthMiddleware14532026/10/25 19:01:07 INFO Vacuumed table table=closures14542026/10/25 19:01:07 INFO Vacuumed table table=objects1455--- PASS: TestPushDedupSurvivesConcurrentGC (0.64s)1456=== CONT TestService_AuthMiddleware_MTLSProxyHeader14572026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1458=== NAME TestClientMultipleUploads1459 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads4226136564/001/store/86cn9d0wq2md8myp79pzgdbh42p1ykgs-test-file-0.txt1460=== NAME TestClientWithDependencies1461 client_integration_test.go:615: Found 1 dependencies (including self)14622026/10/25 19:01:07 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14632026/10/25 19:01:07 INFO Uploading b1zcv5d7fv46gys6f78gxj471dhv5kbg-shared-dep (136B)14642026/10/25 19:01:07 INFO Uploading 2pgdc8a6l05j5wnvxzlqvprvz4nv67i6-top (224B)14652026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/0h9dixvy1nbs5airn52qcq4igf5m0w8k90ag62bs5vwi8mnbfiz4.nar.zst error="server returned 404: 404 page not found\n"14662026/10/25 19:01:07 WARN Failed to register uploaded object key=2pgdc8a6l05j5wnvxzlqvprvz4nv67i6.ls error="server returned 404: 404 page not found\n"14672026/10/25 19:01:07 WARN Failed to register uploaded object key=b1zcv5d7fv46gys6f78gxj471dhv5kbg.ls error="server returned 404: 404 page not found\n"14682026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14692026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14702026/10/25 19:01:07 INFO Signed narinfos id=1 count=214712026/10/25 19:01:07 INFO Uploading 2 narinfos14722026/10/25 19:01:07 WARN Failed to register uploaded object key=2pgdc8a6l05j5wnvxzlqvprvz4nv67i6.narinfo error="server returned 404: 404 page not found\n"14732026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete14742026/10/25 19:01:07 WARN Failed to register uploaded object key=b1zcv5d7fv46gys6f78gxj471dhv5kbg.narinfo error="server returned 404: 404 page not found\n"1475=== NAME TestClientMultipleUploads1476 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads4226136564/001/store/dl98lijsdi1aaacl8r0y4mnb51mcdv37-test-file-1.txt14772026/10/25 19:01:07 INFO Completed push id=1 objects=6 duration=6.766577ms14782026/10/25 19:01:07 INFO Upload complete. (77ms)1479=== NAME TestClientSharedPathCommittedMidPush1480 client_integration_test.go:680: Retrieved narinfo from S3:1481 StorePath: /build/TestClientSharedPathCommittedMidPush1776787540/001/store/b1zcv5d7fv46gys6f78gxj471dhv5kbg-shared-dep1482 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1483 Compression: zstd1484 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821485 NarSize: 1361486 References: 1487 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1488=== NAME TestClientIntegration1489 client_integration_test.go:286: Created store path: /build/TestClientIntegration3929731262/002/store/kngnm4zwc5c5i33nzfc65sahz2a6fc0v-test-file.txt1490=== NAME TestClientSharedPathCommittedMidPush1491 client_integration_test.go:680: Retrieved narinfo from S3:1492 StorePath: /build/TestClientSharedPathCommittedMidPush1776787540/001/store/2pgdc8a6l05j5wnvxzlqvprvz4nv67i6-top1493 URL: nar/0h9dixvy1nbs5airn52qcq4igf5m0w8k90ag62bs5vwi8mnbfiz4.nar.zst1494 Compression: zstd1495 NarHash: sha256:0h9dixvy1nbs5airn52qcq4igf5m0w8k90ag62bs5vwi8mnbfiz41496 NarSize: 2241497 References: /build/TestClientSharedPathCommittedMidPush1776787540/001/store/b1zcv5d7fv46gys6f78gxj471dhv5kbg-shared-dep1498 CA: text:sha256:04521lv8v9k2fbgmjpsszgrlwr09avrww4h652y0dlhqrhnj6zqw1499--- PASS: TestClientSharedPathCommittedMidPush (0.61s)1500=== CONT TestResolveDBConnectionString1501=== RUN TestResolveDBConnectionString/flag_wins1502=== PAUSE TestResolveDBConnectionString/flag_wins1503=== RUN TestResolveDBConnectionString/file_when_flag_empty1504=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1505=== RUN TestResolveDBConnectionString/missing_file_is_an_error1506=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1507=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1508=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1509=== RUN TestResolveDBConnectionString/nothing_configured1510=== PAUSE TestResolveDBConnectionString/nothing_configured1511=== CONT TestProxyWriteTimeout/narinfo1512=== CONT TestProxyWriteTimeout/unknown_size1513=== CONT TestProxyWriteTimeout/10_GiB_nar1514=== CONT TestProxyWriteTimeout/1_GiB_nar1515=== CONT TestPendingClosureWriteTimeout/empty1516=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1517--- PASS: TestProxyWriteTimeout (0.08s)1518 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1519 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1520 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1521 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1522=== NAME TestClientMultipleUploads1523 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads4226136564/001/store/n1zkfvxwlfiz9nk92nz0xbny82x3cx8f-test-file-2.txt15242026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes15252026/10/25 19:01:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15262026/10/25 19:01:07 INFO Uploading 9rmvghai58hjpbdidwdhqbj63awrdk6k-test-script (136B)15272026/10/25 19:01:07 WARN Failed to register uploaded object key=9rmvghai58hjpbdidwdhqbj63awrdk6k.ls error="server returned 404: 404 page not found\n"15282026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15292026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15302026/10/25 19:01:07 WARN Failed to register uploaded object key=log/mng7k35lvkhyy8kw5lcghgskn1j83c0v-test-script.drv error="server returned 404: 404 page not found\n"15312026/10/25 19:01:07 INFO Signed narinfos id=1 count=115322026/10/25 19:01:07 INFO Uploading 1 narinfos15332026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete15342026/10/25 19:01:07 WARN Failed to register uploaded object key=9rmvghai58hjpbdidwdhqbj63awrdk6k.narinfo error="server returned 404: 404 page not found\n"15352026/10/25 19:01:07 INFO Completed push id=1 objects=4 duration=5.971297ms15362026/10/25 19:01:07 INFO Upload complete. (62ms)1537=== NAME TestClientWithDependencies1538 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1824437262/001/store) requires matching store prefix1539--- PASS: TestClientWithDependencies (0.65s)1540=== CONT TestPendingClosureWriteTimeout/670k_objects1541=== CONT TestPendingClosureWriteTimeout/400_objects1542=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15432026/10/25 19:01:07 INFO Received uploads request method=POST path=/1544=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15452026/10/25 19:01:07 INFO Received request for more parts method=POST path=/1546=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15472026/10/25 19:01:07 INFO Received complete multipart upload request method=POST path=/1548=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15492026/10/25 19:01:07 INFO Received uploads request method=POST path=/1550--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1551 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1552 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1553 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1554 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1555=== CONT TestIsValidUploadKey/narinfo1556=== CONT TestIsValidUploadKey/empty_key1557=== CONT TestIsValidUploadKey/absolute1558=== CONT TestIsValidUploadKey/traversal_nar1559=== CONT TestIsValidUploadKey/traversal1560=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1561=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1562=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1563=== CONT TestIsValidUploadKey/index.html1564=== CONT TestIsValidUploadKey/nix-cache-info1565=== CONT TestIsValidUploadKey/realisation_plus_in_output1566=== CONT TestIsValidUploadKey/realisation1567=== CONT TestIsValidUploadKey/build_log_equals1568=== CONT TestIsValidUploadKey/build_log_question_mark1569=== CONT TestIsValidUploadKey/build_log_plus_in_name1570=== CONT TestIsValidUploadKey/build_log_home-manager_file1571=== CONT TestIsValidUploadKey/build_log1572=== CONT TestIsValidUploadKey/unknown_type1573=== CONT TestIsValidUploadKey/listing1574=== CONT TestIsValidUploadKey/nar_plain1575=== CONT TestIsValidUploadKey/nar_zst1576=== CONT TestIsValidUploadKey/nar_xz1577--- PASS: TestIsValidUploadKey (0.09s)1578 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1579 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1580 --- PASS: TestIsValidUploadKey/absolute (0.00s)1581 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1582 --- PASS: TestIsValidUploadKey/traversal (0.00s)1583 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1584 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1585 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1586 --- PASS: TestIsValidUploadKey/index.html (0.00s)1587 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1588 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1589 --- PASS: TestIsValidUploadKey/realisation (0.00s)1590 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1591 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1592 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1593 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1594 --- PASS: TestIsValidUploadKey/build_log (0.00s)1595 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1596 --- PASS: TestIsValidUploadKey/listing (0.00s)1597 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1598 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1599 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1600=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16012026/10/25 19:01:07 INFO Received request for more parts method=POST path=/1602=== NAME TestPinProtectsFromGC1603 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC455078195/001/store/f92picq8d6sgjbh8f0mywyvl1a6f21j1-pinned-file.txt1604 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC455078195/001/store/ydiajmgivax2sl6zcyrmkd9nv4y295kl-unpinned-file.txt16052026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes16062026/10/25 19:01:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16072026/10/25 19:01:07 INFO Uploading kngnm4zwc5c5i33nzfc65sahz2a6fc0v-test-file.txt (152B)16082026/10/25 19:01:07 WARN Failed to register uploaded object key=kngnm4zwc5c5i33nzfc65sahz2a6fc0v.ls error="server returned 404: 404 page not found\n"16092026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16102026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16112026/10/25 19:01:07 INFO Signed narinfos id=1 count=116122026/10/25 19:01:07 INFO Uploading 1 narinfos16132026/10/25 19:01:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16142026/10/25 19:01:07 WARN mTLS auth: bound subjects configured but subject DN unavailable16152026/10/25 19:01:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1616--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.20s)1617=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16182026/10/25 19:01:07 INFO Received complete multipart upload request method=POST path=/16192026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete16202026/10/25 19:01:07 WARN Failed to register uploaded object key=kngnm4zwc5c5i33nzfc65sahz2a6fc0v.narinfo error="server returned 404: 404 page not found\n"16212026/10/25 19:01:07 INFO Completed push id=1 objects=3 duration=5.219017ms16222026/10/25 19:01:07 INFO Upload complete. (53ms)16232026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1624=== NAME TestClientCADerivations1625 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3476806060/001/store/q0wjvnxrhvy1mhkrbmwc93rpwsjs543h-ca-test16262026/10/25 19:01:07 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16272026/10/25 19:01:07 INFO Uploading dl98lijsdi1aaacl8r0y4mnb51mcdv37-test-file-1.txt (160B)16282026/10/25 19:01:07 INFO Uploading n1zkfvxwlfiz9nk92nz0xbny82x3cx8f-test-file-2.txt (160B)16292026/10/25 19:01:07 INFO Uploading 86cn9d0wq2md8myp79pzgdbh42p1ykgs-test-file-0.txt (160B)16302026/10/25 19:01:07 WARN Failed to register uploaded object key=dl98lijsdi1aaacl8r0y4mnb51mcdv37.ls error="server returned 404: 404 page not found\n"16312026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16322026/10/25 19:01:07 WARN Failed to register uploaded object key=86cn9d0wq2md8myp79pzgdbh42p1ykgs.ls error="server returned 404: 404 page not found\n"16332026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16342026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16352026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1636--- PASS: TestGCBugBareHashReferences (0.66s)16372026/10/25 19:01:07 WARN Failed to register uploaded object key=n1zkfvxwlfiz9nk92nz0xbny82x3cx8f.ls error="server returned 404: 404 page not found\n"1638=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16392026/10/25 19:01:07 INFO Signed narinfos id=1 count=316402026/10/25 19:01:07 INFO Received uploads request method=POST path=/16412026/10/25 19:01:07 INFO Uploading 3 narinfos1642--- PASS: TestService_ReadScope_PublicByDefault (0.20s)1643=== CONT TestPush_RejectsBadRequests/root_not_in_objects16442026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1645=== CONT TestPush_RejectsBadRequests/no_objects16462026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1647=== CONT TestPush_RejectsBadRequests/bad_root16482026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1649=== CONT TestPush_RejectsBadRequests/no_roots16502026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1651=== CONT TestServerTLSConfig/no_client_CA1652--- PASS: TestPush_RejectsBadRequests (0.40s)1653 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1654 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1655 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1656 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1657=== CONT TestServerTLSConfig/missing_CA_file1658=== CONT TestServerTLSConfig/not_a_PEM_file1659--- PASS: TestServerTLSConfig (0.00s)1660 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1661 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1662 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1663=== CONT TestIsValidCachePath/narinfo1664=== CONT TestIsValidCachePath/index.html1665=== CONT TestIsValidCachePath/short_hash1666=== CONT TestIsValidCachePath/wrong_extension1667=== CONT TestIsValidCachePath/leading_slash1668=== CONT TestIsValidCachePath/empty1669=== CONT TestIsValidCachePath/random_path1670=== CONT TestIsValidCachePath/invalid_char_u1671=== CONT TestIsValidCachePath/invalid_char_e1672=== CONT TestIsValidCachePath/traversal_in_middle1673=== CONT TestIsValidCachePath/traversal_parent1674=== CONT TestIsValidCachePath/nar_uncompressed1675=== CONT TestIsValidCachePath/nix-cache-info1676=== CONT TestIsValidCachePath/realisation1677=== CONT TestIsValidCachePath/log1678=== CONT TestIsValidCachePath/ls1679=== CONT TestIsValidCachePath/nar_xz1680=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1681=== CONT TestIsValidCachePath/nar_zst1682=== CONT TestIsValidCachePath/nar_bz21683--- PASS: TestIsValidCachePath (0.00s)1684 --- PASS: TestIsValidCachePath/narinfo (0.00s)1685 --- PASS: TestIsValidCachePath/index.html (0.00s)1686 --- PASS: TestIsValidCachePath/short_hash (0.00s)1687 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1688 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1689 --- PASS: TestIsValidCachePath/empty (0.00s)1690 --- PASS: TestIsValidCachePath/random_path (0.00s)1691 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1692 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1693 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1694 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1695 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1696 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1697 --- PASS: TestIsValidCachePath/realisation (0.00s)1698 --- PASS: TestIsValidCachePath/log (0.00s)1699 --- PASS: TestIsValidCachePath/ls (0.00s)1700 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1701 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1702 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1703 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1704=== CONT TestParseSingleRange/none1705=== CONT TestParseSingleRange/open-ended1706=== CONT TestParseSingleRange/start_far_past_EOF1707=== CONT TestParseSingleRange/start_past_EOF1708=== CONT TestParseSingleRange/single_byte1709=== CONT TestParseSingleRange/suffix_exceeds_size1710=== CONT TestParseSingleRange/suffix1711=== CONT TestParseSingleRange/end_clamped_to_size1712=== CONT TestParseSingleRange/malformed_both_empty1713=== CONT TestParseSingleRange/closed1714=== CONT TestParseSingleRange/malformed_end_before_start1715=== CONT TestParseSingleRange/multi-range_ignored1716=== CONT TestParseSingleRange/malformed_no_dash1717=== CONT TestParseSingleRange/unknown_unit1718--- PASS: TestParseSingleRange (0.00s)1719 --- PASS: TestParseSingleRange/none (0.00s)1720 --- PASS: TestParseSingleRange/open-ended (0.00s)1721 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1722 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1723 --- PASS: TestParseSingleRange/single_byte (0.00s)1724 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1725 --- PASS: TestParseSingleRange/suffix (0.00s)1726 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1727 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1728 --- PASS: TestParseSingleRange/closed (0.00s)1729 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1730 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1731 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1732 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1733=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1734=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17352026/10/25 19:01:07 WARN Failed to register uploaded object key=dl98lijsdi1aaacl8r0y4mnb51mcdv37.narinfo error="server returned 404: 404 page not found\n"17362026/10/25 19:01:07 WARN Failed to register uploaded object key=n1zkfvxwlfiz9nk92nz0xbny82x3cx8f.narinfo error="server returned 404: 404 page not found\n"17372026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete17382026/10/25 19:01:07 WARN Failed to register uploaded object key=86cn9d0wq2md8myp79pzgdbh42p1ykgs.narinfo error="server returned 404: 404 page not found\n"17392026/10/25 19:01:07 INFO Completed push id=1 objects=9 duration=4.286528ms17402026/10/25 19:01:07 INFO Upload complete. (50ms)1741=== NAME TestClientMultipleUploads1742 client_integration_test.go:369: Uploaded 3 paths in 78.519315ms1743--- PASS: TestClientMultipleUploads (0.64s)1744=== CONT TestGCEndsOnShutdown/before_the_run1745=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1746=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1747=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1748=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1749=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1750=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1751=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1752=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1753=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17542026/10/25 19:01:07 INFO All 1 paths already cached1755=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1756=== NAME TestClientIntegration1757 client_integration_test.go:312: Retrieved narinfo from S3:1758 StorePath: /build/TestClientIntegration3929731262/002/store/kngnm4zwc5c5i33nzfc65sahz2a6fc0v-test-file.txt1759 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1760 Compression: zstd1761 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11762 NarSize: 1521763 References: 1764 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11765=== NAME TestClientCADerivations1766 client_ca_test.go:139: Found 1 dependencies (including self)1767=== NAME TestClientIntegration1768 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1769 client_integration_test.go:313: Decompressed .ls content (64 bytes):1770 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1771 client_integration_test.go:316: Testing garbage collection...17722026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes1773--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.18s)1774=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17752026/10/25 19:01:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17762026/10/25 19:01:07 INFO Uploading f92picq8d6sgjbh8f0mywyvl1a6f21j1-pinned-file.txt (128B)17772026/10/25 19:01:07 WARN Failed to register uploaded object key=f92picq8d6sgjbh8f0mywyvl1a6f21j1.ls error="server returned 404: 404 page not found\n"17782026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17792026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17802026/10/25 19:01:07 INFO Signed narinfos id=1 count=117812026/10/25 19:01:07 INFO Uploading 1 narinfos17822026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete17832026/10/25 19:01:07 WARN Failed to register uploaded object key=f92picq8d6sgjbh8f0mywyvl1a6f21j1.narinfo error="server returned 404: 404 page not found\n"17842026/10/25 19:01:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures17852026/10/25 19:01:07 INFO Garbage collection started17862026/10/25 19:01:07 INFO Completed push id=1 objects=3 duration=7.704426ms17872026/10/25 19:01:07 INFO Upload complete. (61ms)17882026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=01789=== RUN TestService_RequireScope_OIDC/builder_may_write1790=== PAUSE TestService_RequireScope_OIDC/builder_may_write1791=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1792=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1793=== RUN TestService_RequireScope_OIDC/ops_may_admin1794=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1795=== RUN TestService_RequireScope_OIDC/ops_may_not_write1796=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1797=== RUN TestService_RequireScope_OIDC/reader_may_not_write1798=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1799=== RUN TestService_RequireScope_OIDC/static_token_may_admin1800=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1801=== RUN TestService_RequireScope_OIDC/static_token_may_write1802=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1803=== RUN TestService_RequireScope_OIDC/reader_may_read1804=== PAUSE TestService_RequireScope_OIDC/reader_may_read1805=== RUN TestService_RequireScope_OIDC/writer_implies_read1806=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1807=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1808=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1809=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1810=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1811=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1812=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1813=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1814=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1815=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1816=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1817=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18182026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period1819--- PASS: TestService_ReadAuthMiddleware (0.23s)1820=== CONT TestClientErrorHandling/InvalidStorePath18212026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures1822--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.49s)1823=== CONT TestClientErrorHandling/ServerNotAvailable18242026/10/25 19:01:07 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=018252026/10/25 19:01:07 INFO Vacuumed table table=pending_closures18262026/10/25 19:01:07 INFO Vacuumed table table=pending_objects18272026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads18282026/10/25 19:01:07 INFO Vacuumed table table=closures18292026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes18302026/10/25 19:01:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18312026/10/25 19:01:07 INFO Uploading ydiajmgivax2sl6zcyrmkd9nv4y295kl-unpinned-file.txt (128B)18322026/10/25 19:01:07 INFO Vacuumed table table=objects18332026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures18342026/10/25 19:01:07 WARN Failed to register uploaded object key=ydiajmgivax2sl6zcyrmkd9nv4y295kl.ls error="server returned 404: 404 page not found\n"18352026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes18362026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18372026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18382026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes18392026/10/25 19:01:07 INFO Signed narinfos id=2 count=118402026/10/25 19:01:07 INFO Uploading 1 narinfos18412026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures18422026/10/25 19:01:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18432026/10/25 19:01:07 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18442026/10/25 19:01:07 INFO Uploading q0wjvnxrhvy1mhkrbmwc93rpwsjs543h-ca-test (144B)18452026/10/25 19:01:07 INFO Uploading j21icasxxg0pwvxd3dlp2x6vw8xbglsz-shared-dep (136B)18462026/10/25 19:01:07 INFO Uploading hi87xjxa1b34x96h7kmzfm2qydzxv2vp-a (216B)18472026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/2/complete18482026/10/25 19:01:07 WARN Failed to register uploaded object key=ydiajmgivax2sl6zcyrmkd9nv4y295kl.narinfo error="server returned 404: 404 page not found\n"18492026/10/25 19:01:07 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18502026/10/25 19:01:07 INFO Uploading 9jh0r6h51hccpcxxgn3p16m5l2qzj92s-a (216B)18512026/10/25 19:01:07 INFO Uploading 31489rqxagrbsv5brpdv0sbja6cxn05k-shared-dep (136B)18522026/10/25 19:01:07 INFO Completed push id=2 objects=3 duration=3.495109ms18532026/10/25 19:01:07 INFO Upload complete. (92ms)18542026/10/25 19:01:07 WARN Failed to register uploaded object key=q0wjvnxrhvy1mhkrbmwc93rpwsjs543h.ls error="server returned 404: 404 page not found\n"18552026/10/25 19:01:07 WARN Failed to register uploaded object key=j21icasxxg0pwvxd3dlp2x6vw8xbglsz.ls error="server returned 404: 404 page not found\n"18562026/10/25 19:01:07 WARN Failed to register uploaded object key=l7s6bscy5by79vjw35s882gzkj9pr9xw.ls error="server returned 404: 404 page not found\n"18572026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18582026/10/25 19:01:07 WARN Failed to register uploaded object key=hi87xjxa1b34x96h7kmzfm2qydzxv2vp.ls error="server returned 404: 404 page not found\n"18592026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18602026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18612026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/07glr5z13rd0ijg2vwa28cdjpinf66c7wg4g84zx87s5c4zzx0w8.nar.zst error="server returned 404: 404 page not found\n"18622026/10/25 19:01:07 WARN Failed to register uploaded object key=vxnk8ra861gj8xxcgd0pbki0fmvxh0b7.ls error="server returned 404: 404 page not found\n"18632026/10/25 19:01:07 WARN Failed to register uploaded object key=9jh0r6h51hccpcxxgn3p16m5l2qzj92s.ls error="server returned 404: 404 page not found\n"18642026/10/25 19:01:07 INFO Signed narinfos id=1 count=318652026/10/25 19:01:07 INFO Uploading 3 narinfos18662026/10/25 19:01:07 WARN Failed to register uploaded object key=31489rqxagrbsv5brpdv0sbja6cxn05k.ls error="server returned 404: 404 page not found\n"18672026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18682026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18692026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18702026/10/25 19:01:07 WARN Failed to register uploaded object key=nar/1rncjifslfdjmxvjv90n5wjisf59xzcsp2r6f1371l4z0ydah64d.nar.zst error="server returned 404: 404 page not found\n"18712026/10/25 19:01:07 WARN Failed to register uploaded object key=log/b75jnbaadvx2qy447vx541jaq6lh0pq1-ca-test.drv error="server returned 404: 404 page not found\n"18722026/10/25 19:01:07 INFO Signed narinfos id=2 count=218732026/10/25 19:01:07 INFO Signed narinfos id=1 count=118742026/10/25 19:01:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18752026/10/25 19:01:07 INFO Uploading 1 narinfos18762026/10/25 19:01:07 INFO Signed narinfos id=1 count=218772026/10/25 19:01:07 INFO Uploading 4 narinfos18782026/10/25 19:01:07 WARN Failed to register uploaded object key=l7s6bscy5by79vjw35s882gzkj9pr9xw.narinfo error="server returned 404: 404 page not found\n"18792026/10/25 19:01:07 WARN Failed to register uploaded object key=j21icasxxg0pwvxd3dlp2x6vw8xbglsz.narinfo error="server returned 404: 404 page not found\n"18802026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete18812026/10/25 19:01:07 WARN Failed to register uploaded object key=hi87xjxa1b34x96h7kmzfm2qydzxv2vp.narinfo error="server returned 404: 404 page not found\n"18822026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete18832026/10/25 19:01:07 WARN Failed to register uploaded object key=31489rqxagrbsv5brpdv0sbja6cxn05k.narinfo error="server returned 404: 404 page not found\n"18842026/10/25 19:01:07 WARN Failed to register uploaded object key=vxnk8ra861gj8xxcgd0pbki0fmvxh0b7.narinfo error="server returned 404: 404 page not found\n"18852026/10/25 19:01:07 WARN Failed to register uploaded object key=q0wjvnxrhvy1mhkrbmwc93rpwsjs543h.narinfo error="server returned 404: 404 page not found\n"18862026/10/25 19:01:07 WARN Failed to register uploaded object key=9jh0r6h51hccpcxxgn3p16m5l2qzj92s.narinfo error="server returned 404: 404 page not found\n"18872026/10/25 19:01:07 INFO Completed push id=1 objects=8 duration=5.692887ms18882026/10/25 19:01:07 INFO Upload complete. (89ms)1889=== NAME TestClientPushesUseOnePush1890 client_pushes_test.go:97: Retrieved narinfo from S3:1891 StorePath: /build/TestClientPushesUseOnePush1017268582/001/store/j21icasxxg0pwvxd3dlp2x6vw8xbglsz-shared-dep1892 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1893 Compression: zstd1894 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821895 NarSize: 1361896 References: 1897 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18982026/10/25 19:01:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18992026/10/25 19:01:07 WARN Failed to register uploaded object key=31489rqxagrbsv5brpdv0sbja6cxn05k.narinfo error="server returned 404: 404 page not found\n"19002026/10/25 19:01:07 INFO Completed push id=1 objects=4 duration=5.045407ms19012026/10/25 19:01:07 INFO Upload complete. (142ms)1902 client_pushes_test.go:97: Retrieved narinfo from S3:1903 StorePath: /build/TestClientPushesUseOnePush1017268582/001/store/hi87xjxa1b34x96h7kmzfm2qydzxv2vp-a1904 URL: nar/07glr5z13rd0ijg2vwa28cdjpinf66c7wg4g84zx87s5c4zzx0w8.nar.zst1905 Compression: zstd1906 NarHash: sha256:07glr5z13rd0ijg2vwa28cdjpinf66c7wg4g84zx87s5c4zzx0w81907 NarSize: 2161908 References: /build/TestClientPushesUseOnePush1017268582/001/store/j21icasxxg0pwvxd3dlp2x6vw8xbglsz-shared-dep1909 CA: text:sha256:02pzd4q356s52f6cm4smggcvljqxcyjg980f5ijggy1fyfaznyrn1910=== NAME TestClientCADerivations1911 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3476806060/001/store/q0wjvnxrhvy1mhkrbmwc93rpwsjs543h-ca-test1912 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1913 Compression: zstd1914 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1915 NarSize: 1441916 References: 1917 Deriver: /build/TestClientCADerivations3476806060/001/store/b75jnbaadvx2qy447vx541jaq6lh0pq1-ca-test.drv1918 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1919 client_ca_test.go:185: Checking for realisation files in S3...1920=== NAME TestClientPushesUseOnePush1921 client_pushes_test.go:97: Retrieved narinfo from S3:1922 StorePath: /build/TestClientPushesUseOnePush1017268582/001/store/l7s6bscy5by79vjw35s882gzkj9pr9xw-b1923 URL: nar/07glr5z13rd0ijg2vwa28cdjpinf66c7wg4g84zx87s5c4zzx0w8.nar.zst1924 Compression: zstd1925 NarHash: sha256:07glr5z13rd0ijg2vwa28cdjpinf66c7wg4g84zx87s5c4zzx0w81926 NarSize: 2161927 References: /build/TestClientPushesUseOnePush1017268582/001/store/j21icasxxg0pwvxd3dlp2x6vw8xbglsz-shared-dep1928 CA: text:sha256:02pzd4q356s52f6cm4smggcvljqxcyjg980f5ijggy1fyfaznyrn1929=== NAME TestClientCADerivations1930 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1931 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19322026/10/25 19:01:07 INFO Completed upload id=1 objects=6 duration=4.776228ms19332026/10/25 19:01:07 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1934--- PASS: TestClientPushesUseOnePush (0.50s)1935=== CONT TestClientErrorHandling/InvalidAuthToken19362026/10/25 19:01:07 INFO Completed upload id=2 objects=6 duration=1.37178ms19372026/10/25 19:01:07 INFO Upload complete. (117ms)1938=== NAME TestClientFallsBackToClosures1939 client_pushes_test.go:112: Retrieved narinfo from S3:1940 StorePath: /build/TestClientFallsBackToClosures1514511355/001/store/31489rqxagrbsv5brpdv0sbja6cxn05k-shared-dep1941 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1942 Compression: zstd1943 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821944 NarSize: 1361945 References: 1946 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1947 client_pushes_test.go:112: Retrieved narinfo from S3:1948 StorePath: /build/TestClientFallsBackToClosures1514511355/001/store/9jh0r6h51hccpcxxgn3p16m5l2qzj92s-a1949 URL: nar/1rncjifslfdjmxvjv90n5wjisf59xzcsp2r6f1371l4z0ydah64d.nar.zst1950 Compression: zstd1951 NarHash: sha256:1rncjifslfdjmxvjv90n5wjisf59xzcsp2r6f1371l4z0ydah64d1952 NarSize: 2161953 References: /build/TestClientFallsBackToClosures1514511355/001/store/31489rqxagrbsv5brpdv0sbja6cxn05k-shared-dep1954 CA: text:sha256:10snwdb6zx4j0pf646wdfrbpjpvqhbl5x16rd4har2x5jmylbk1g19552026/10/25 19:01:07 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/present1956 client_pushes_test.go:112: Retrieved narinfo from S3:1957 StorePath: /build/TestClientFallsBackToClosures1514511355/001/store/vxnk8ra861gj8xxcgd0pbki0fmvxh0b7-b1958 URL: nar/1rncjifslfdjmxvjv90n5wjisf59xzcsp2r6f1371l4z0ydah64d.nar.zst1959 Compression: zstd1960 NarHash: sha256:1rncjifslfdjmxvjv90n5wjisf59xzcsp2r6f1371l4z0ydah64d1961 NarSize: 2161962 References: /build/TestClientFallsBackToClosures1514511355/001/store/31489rqxagrbsv5brpdv0sbja6cxn05k-shared-dep1963 CA: text:sha256:10snwdb6zx4j0pf646wdfrbpjpvqhbl5x16rd4har2x5jmylbk1g1964--- PASS: TestClientFallsBackToClosures (0.52s)1965=== CONT TestCacheConfigHandler/full_config,_no_issuer1966=== CONT TestCacheConfigHandler/no_signing_keys1967=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1968=== CONT TestCacheConfigHandler/no_cache_url_configured1969--- PASS: TestCacheConfigHandler (0.00s)1970 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1971 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1972 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1973 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1974=== CONT TestResolveDBConnectionString/flag_wins1975=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1976=== CONT TestResolveDBConnectionString/nothing_configured1977=== CONT TestResolveDBConnectionString/missing_file_is_an_error1978=== CONT TestResolveDBConnectionString/file_when_flag_empty1979=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1980--- PASS: TestResolveDBConnectionString (0.00s)1981 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1982 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1983 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1984 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1985 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1986=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19872026/10/25 19:01:07 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]1988=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19892026/10/25 19:01:07 WARN Authentication failed token_preview=eyJhbGciOi...VCL4XzQSRg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1990=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1991=== CONT TestService_RequireScope_OIDC/builder_may_write1992--- PASS: TestService_AuthMiddleware_OIDC (0.26s)1993 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1994 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1995 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1996 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1997=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1998=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19992026/10/25 19:01:07 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]2000=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2001=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2002=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2003=== CONT TestService_RequireScope_OIDC/writer_implies_read2004=== CONT TestService_RequireScope_OIDC/reader_may_read2005=== CONT TestService_RequireScope_OIDC/static_token_may_write2006=== CONT TestService_RequireScope_OIDC/static_token_may_admin2007=== CONT TestService_RequireScope_OIDC/reader_may_not_write2008=== CONT TestService_RequireScope_OIDC/ops_may_not_write2009=== CONT TestService_RequireScope_OIDC/ops_may_admin2010=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2011--- PASS: TestService_RequireScope_OIDC (0.25s)2012 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2013 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2014 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2015 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2016 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2017 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2018 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20262026/10/25 19:01:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures20272026/10/25 19:01:07 INFO Garbage collection started20282026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=020292026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period20302026/10/25 19:01:07 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=020312026/10/25 19:01:07 INFO Vacuumed table table=pending_closures20322026/10/25 19:01:07 INFO Vacuumed table table=pending_objects20332026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads20342026/10/25 19:01:07 INFO Vacuumed table table=closures20352026/10/25 19:01:07 INFO Vacuumed table table=objects20362026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures20372026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=020382026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period20392026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=020402026/10/25 19:01:07 WARN Request failed, retrying attempt=2 backoff=210.312724ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20412026/10/25 19:01:07 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=020422026/10/25 19:01:07 INFO Vacuumed table table=pending_closures20432026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period20442026/10/25 19:01:07 INFO Vacuumed table table=pending_objects20452026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads20462026/10/25 19:01:07 INFO Vacuumed table table=closures20472026/10/25 19:01:07 INFO Vacuumed table table=objects20482026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=020492026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period20502026/10/25 19:01:07 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:45907/bucket98/?delete=\": context canceled"2051--- PASS: TestGCEndsOnShutdown (0.00s)2052 --- PASS: TestGCEndsOnShutdown/before_the_run (0.23s)2053 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.30s)2054 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.30s)20552026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures20562026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=020572026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period20582026/10/25 19:01:07 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=020592026/10/25 19:01:07 INFO Vacuumed table table=pending_closures20602026/10/25 19:01:07 INFO Vacuumed table table=pending_objects20612026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads20622026/10/25 19:01:07 INFO Vacuumed table table=closures20632026/10/25 19:01:07 INFO Vacuumed table table=objects2064--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2065 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.29s)2066 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.30s)20672026/10/25 19:01:07 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20682026/10/25 19:01:07 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2069=== NAME TestClientCADerivations2070 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2071 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2072 error: binary cache 's3://bucket81?endpoint=http://localhost:45907®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3476806060/001/store'2073 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12074--- PASS: TestClientCADerivations (0.79s)20752026/10/25 19:01:07 WARN Request failed, retrying attempt=3 backoff=384.066472ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2076--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2077 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2078 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2079 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.63s)2080=== NAME TestOrphanedObjectsGCStressTest2081 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2082 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2083--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2084 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.71s)2085 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.73s)2086--- PASS: TestDeleteClosuresRacingPins (1.07s)20872026/10/25 19:01:08 INFO lead: released remote=192.0.2.1:12342088--- PASS: TestLeadEndsOnShutdown (1.47s)20892026/10/25 19:01:08 INFO lead: released remote=192.0.2.1:12342090--- PASS: TestPendingClosureWriteTimeout (0.08s)2091 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2092 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2093 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2094 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (0.99s)20952026/10/25 19:01:08 WARN Request failed, retrying attempt=4 backoff=854.673838ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20962026/10/25 19:01:08 INFO lead: acquired remote=192.0.2.1:12342097=== NAME TestOrphanedObjectsGCStressTest2098 orphaned_objects_gc_test.go:503: Stress test completed successfully:2099 orphaned_objects_gc_test.go:504: - Active objects preserved: 202100 orphaned_objects_gc_test.go:505: - Objects deleted: 2102101 orphaned_objects_gc_test.go:506: - Total GC'd: 2102102--- PASS: TestOrphanedObjectsGCStressTest (3.03s)21032026/10/25 19:01:08 WARN Request failed, retrying attempt=5 backoff=1.678107146s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21042026/10/25 19:01:09 INFO lead: released remote=192.0.2.1:12342105--- PASS: TestLeadElectsOneAndHandsOver (2.89s)21062026/10/25 19:01:09 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02107=== NAME TestClientIntegration2108 client_integration_test.go:323: Objects in database after GC:2109 client_integration_test.go:323: Successfully deleted all objects with GC --force2110--- PASS: TestClientIntegration (2.50s)21112026/10/25 19:01:09 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021122026/10/25 19:01:09 INFO Received create pin request method=POST path=/api/pins/myapp21132026/10/25 19:01:09 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC455078195/001/store/f92picq8d6sgjbh8f0mywyvl1a6f21j1-pinned-file.txt narinfo_key=f92picq8d6sgjbh8f0mywyvl1a6f21j1.narinfo21142026/10/25 19:01:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures21152026/10/25 19:01:09 INFO Garbage collection started21162026/10/25 19:01:09 INFO Aborted multipart uploads count=0 kept=021172026/10/25 19:01:09 WARN Force mode enabled - objects will be deleted immediately without grace period21182026/10/25 19:01:09 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=021192026/10/25 19:01:09 INFO Vacuumed table table=pending_closures21202026/10/25 19:01:09 INFO Vacuumed table table=pending_objects21212026/10/25 19:01:09 INFO Vacuumed table table=multipart_uploads21222026/10/25 19:01:09 INFO Vacuumed table table=closures21232026/10/25 19:01:09 INFO Vacuumed table table=objects2124--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.87s)21252026/10/25 19:01:10 WARN Rate limiter enabled after throttle name=s3-test rate=521262026/10/25 19:01:10 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2127=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2128 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102129 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002130--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.74s)21312026/10/25 19:01:10 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-config21322026/10/25 19:01:10 WARN Request failed, retrying attempt=2 backoff=181.261399ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21332026/10/25 19:01:10 WARN Request failed, retrying attempt=3 backoff=367.209836ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21342026/10/25 19:01:11 WARN Request failed, retrying attempt=4 backoff=769.834136ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2135=== NAME TestPinProtectsFromGC2136 client_integration_test.go:840: Pin successfully protected closure from garbage collection2137--- PASS: TestPinProtectsFromGC (4.59s)2138--- PASS: TestConnectWaitsForAPeerMigration (5.16s)21392026/10/25 19:01:12 WARN Request failed, retrying attempt=5 backoff=1.465825709s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/10/25 19:01:12 INFO Aborted multipart uploads count=1 kept=021412026/10/25 19:01:12 INFO Received cleanup request method=DELETE path=/api/pending_closures21422026/10/25 19:01:12 INFO Aborted multipart uploads count=1 kept=02143--- PASS: TestPendingCleanupUsesOneCutoff (6.65s)21442026/10/25 19:01:13 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"21452026/10/25 19:01:13 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-config21462026/10/25 19:01:13 WARN Request failed, retrying attempt=2 backoff=213.078989ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21472026/10/25 19:01:13 WARN Request failed, retrying attempt=3 backoff=391.171148ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21482026/10/25 19:01:14 WARN Request failed, retrying attempt=4 backoff=767.170687ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21492026/10/25 19:01:15 WARN Request failed, retrying attempt=5 backoff=1.653962599s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21502026/10/25 19:01:16 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_closures21512026/10/25 19:01:16 WARN Request failed, retrying attempt=2 backoff=190.966175ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21522026/10/25 19:01:16 WARN Request failed, retrying attempt=3 backoff=434.752525ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21532026/10/25 19:01:17 WARN Request failed, retrying attempt=4 backoff=874.382159ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21542026/10/25 19:01:18 WARN Request failed, retrying attempt=5 backoff=1.727532479s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2155--- PASS: TestClientErrorHandling (0.00s)2156 --- PASS: TestClientErrorHandling/InvalidStorePath (0.21s)2157 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.23s)2158 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.74s)2159PASS21602026-10-25 19:01:20.239 UTC [127] LOG: received smart shutdown request21612026-10-25 19:01:20.243 UTC [127] LOG: background worker "logical replication launcher" (PID 137) exited with exit code 121622026-10-25 19:01:20.249 UTC [132] LOG: shutting down21632026-10-25 19:01:20.249 UTC [132] LOG: checkpoint starting: shutdown immediate21642026-10-25 19:01:21.144 UTC [132] LOG: checkpoint complete: wrote 10377 buffers (63.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.238 s, sync=0.615 s, total=0.896 s; sync files=34045, longest=0.089 s, average=0.001 s; distance=494011 kB, estimate=494011 kB; lsn=0/1F9D49F8, redo lsn=0/1F9D49F821652026-10-25 19:01:21.218 UTC [127] LOG: database system is shut down2166Running OIDC tests...2167=== RUN TestAudienceForIssuer2168=== PAUSE TestAudienceForIssuer2169=== RUN TestGlobMatch2170=== PAUSE TestGlobMatch2171=== RUN TestValidateToken_ValidToken2172=== PAUSE TestValidateToken_ValidToken2173=== RUN TestValidateToken_WrongAudience2174=== PAUSE TestValidateToken_WrongAudience2175=== RUN TestValidateToken_Expired2176=== PAUSE TestValidateToken_Expired2177=== RUN TestValidateToken_BoundClaimsMismatch2178=== PAUSE TestValidateToken_BoundClaimsMismatch2179=== RUN TestValidateToken_BoundSubjectMismatch2180=== PAUSE TestValidateToken_BoundSubjectMismatch2181=== RUN TestValidateToken_MultipleProviders2182=== PAUSE TestValidateToken_MultipleProviders2183=== RUN TestValidateToken_NoMatchingProvider2184=== PAUSE TestValidateToken_NoMatchingProvider2185=== RUN TestValidateToken_KubernetesServiceAccount2186=== PAUSE TestValidateToken_KubernetesServiceAccount2187=== RUN TestNewValidator_KubernetesRequiresCA2188=== PAUSE TestNewValidator_KubernetesRequiresCA2189=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2190=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2191=== RUN TestPins_ReservedForMatchingRule2192=== PAUSE TestPins_ReservedForMatchingRule2193=== RUN TestPins_TopLevelShorthand2194=== PAUSE TestPins_TopLevelShorthand2195=== RUN TestPins_ConfigValidation2196=== PAUSE TestPins_ConfigValidation2197=== RUN TestScopes_LegacyProviderDefaultsToWrite2198=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2199=== RUN TestScopes_Rules2200=== PAUSE TestScopes_Rules2201=== RUN TestScopes_ConfigValidation2202=== PAUSE TestScopes_ConfigValidation2203=== CONT TestAudienceForIssuer2204=== CONT TestValidateToken_KubernetesServiceAccount2205=== CONT TestValidateToken_BoundClaimsMismatch2206--- PASS: TestAudienceForIssuer (0.00s)2207=== CONT TestValidateToken_NoMatchingProvider2208=== CONT TestValidateToken_ValidToken2209=== CONT TestValidateToken_MultipleProviders2210=== CONT TestGlobMatch2211=== RUN TestGlobMatch/foo_foo2212=== PAUSE TestGlobMatch/foo_foo2213=== CONT TestValidateToken_BoundSubjectMismatch2214=== CONT TestPins_ConfigValidation2215=== CONT TestScopes_Rules2216=== CONT TestScopes_LegacyProviderDefaultsToWrite2217=== CONT TestScopes_ConfigValidation2218=== CONT TestPins_ReservedForMatchingRule2219=== CONT TestValidateToken_Expired2220=== CONT TestPins_TopLevelShorthand2221=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2222=== CONT TestNewValidator_KubernetesRequiresCA2223=== CONT TestValidateToken_WrongAudience2224=== RUN TestGlobMatch/foo_bar2225=== PAUSE TestGlobMatch/foo_bar2226=== RUN TestGlobMatch/*_2227=== PAUSE TestGlobMatch/*_2228=== RUN TestGlobMatch/*_anything2229=== PAUSE TestGlobMatch/*_anything2230=== RUN TestGlobMatch/foo*_foo2231=== PAUSE TestGlobMatch/foo*_foo2232=== RUN TestGlobMatch/foo*_foobar2233=== PAUSE TestGlobMatch/foo*_foobar2234=== RUN TestGlobMatch/foo*_bar2235=== PAUSE TestGlobMatch/foo*_bar2236=== RUN TestGlobMatch/*bar_bar2237--- PASS: TestPins_ConfigValidation (0.00s)2238--- PASS: TestScopes_ConfigValidation (0.00s)2239=== PAUSE TestGlobMatch/*bar_bar2240=== RUN TestGlobMatch/*bar_foobar2241=== PAUSE TestGlobMatch/*bar_foobar2242=== RUN TestGlobMatch/*bar_foo2243=== PAUSE TestGlobMatch/*bar_foo2244=== RUN TestGlobMatch/foo*bar_foobar2245=== PAUSE TestGlobMatch/foo*bar_foobar2246=== RUN TestGlobMatch/foo*bar_foo123bar2247=== PAUSE TestGlobMatch/foo*bar_foo123bar2248=== RUN TestGlobMatch/foo*bar_foobarbaz2249=== PAUSE TestGlobMatch/foo*bar_foobarbaz2250=== RUN TestGlobMatch/*/*_foo/bar2251=== PAUSE TestGlobMatch/*/*_foo/bar2252=== RUN TestGlobMatch/*/*_foo2253=== PAUSE TestGlobMatch/*/*_foo2254=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2255=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2256=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02257=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02258=== RUN TestGlobMatch/refs/*/main_refs/heads/main2259=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2260=== RUN TestGlobMatch/fo?_foo2261=== PAUSE TestGlobMatch/fo?_foo2262=== RUN TestGlobMatch/fo?_fo2263=== PAUSE TestGlobMatch/fo?_fo2264=== RUN TestGlobMatch/fo?_fooo2265=== PAUSE TestGlobMatch/fo?_fooo2266=== RUN TestGlobMatch/?oo_foo2267=== PAUSE TestGlobMatch/?oo_foo2268=== RUN TestGlobMatch/?oo_boo2269=== PAUSE TestGlobMatch/?oo_boo2270=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2271=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2272=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2273=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2274=== CONT TestGlobMatch/foo_foo2275=== CONT TestGlobMatch/?oo_boo2276=== CONT TestGlobMatch/?oo_foo2277=== CONT TestGlobMatch/fo?_fooo2278=== CONT TestGlobMatch/fo?_fo2279=== CONT TestGlobMatch/fo?_foo2280=== CONT TestGlobMatch/refs/*/main_refs/heads/main2281=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02282=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2283=== CONT TestGlobMatch/*/*_foo/bar2284=== CONT TestGlobMatch/foo_bar2285=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2286=== CONT TestGlobMatch/foo*bar_foobarbaz2287=== CONT TestGlobMatch/foo*bar_foobar2288=== CONT TestGlobMatch/*bar_foo2289=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2290=== CONT TestGlobMatch/*bar_foobar2291=== CONT TestGlobMatch/*/*_foo2292=== CONT TestGlobMatch/*bar_bar2293=== CONT TestGlobMatch/foo*bar_foo123bar2294=== CONT TestGlobMatch/foo*_bar2295=== CONT TestGlobMatch/foo*_foobar2296=== CONT TestGlobMatch/foo*_foo2297=== CONT TestGlobMatch/*_anything2298=== CONT TestGlobMatch/*_2299--- PASS: TestGlobMatch (0.01s)2300 --- PASS: TestGlobMatch/foo_foo (0.00s)2301 --- PASS: TestGlobMatch/?oo_boo (0.00s)2302 --- PASS: TestGlobMatch/?oo_foo (0.00s)2303 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2304 --- PASS: TestGlobMatch/fo?_fo (0.00s)2305 --- PASS: TestGlobMatch/fo?_foo (0.00s)2306 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2307 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2308 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2309 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2310 --- PASS: TestGlobMatch/foo_bar (0.00s)2311 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2312 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2313 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2314 --- PASS: TestGlobMatch/*bar_foo (0.00s)2315 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2316 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2317 --- PASS: TestGlobMatch/*/*_foo (0.00s)2318 --- PASS: TestGlobMatch/*bar_bar (0.00s)2319 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2320 --- PASS: TestGlobMatch/foo*_bar (0.00s)2321 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2322 --- PASS: TestGlobMatch/foo*_foo (0.00s)2323 --- PASS: TestGlobMatch/*_anything (0.00s)2324 --- PASS: TestGlobMatch/*_ (0.00s)23252026/10/25 19:01:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37189/oidc23262026/10/25 19:01:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36279/oidc2327--- PASS: TestValidateToken_ValidToken (0.03s)2328--- PASS: TestPins_ReservedForMatchingRule (0.02s)23292026/10/25 19:01:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36219/oidc23302026/10/25 19:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36101/oidc2331--- PASS: TestValidateToken_Expired (0.04s)2332--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.04s)23332026/10/25 19:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46371/oidc23342026/10/25 19:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39015/oidc2335--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)2336--- PASS: TestScopes_Rules (0.05s)23372026/10/25 19:01:23 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38557/oidc23382026/10/25 19:01:23 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:43571/oidc2339--- PASS: TestValidateToken_MultipleProviders (0.07s)23402026/10/25 19:01:23 http: TLS handshake error from 127.0.0.1:38530: remote error: tls: bad certificate2341--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)23422026/10/25 19:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45881/oidc2343--- PASS: TestValidateToken_WrongAudience (0.09s)23442026/10/25 19:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33717/oidc23452026/10/25 19:01:23 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232346--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)2347--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)23482026/10/25 19:01:23 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40595/oidc2349--- PASS: TestValidateToken_NoMatchingProvider (0.13s)23502026/10/25 19:01:23 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:455132351--- PASS: TestValidateToken_KubernetesServiceAccount (0.15s)23522026/10/25 19:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44619/oidc2353--- PASS: TestPins_TopLevelShorthand (0.20s)2354PASS2355Running hook tests...2356=== RUN TestSendPathsEmpty2357=== PAUSE TestSendPathsEmpty2358=== RUN TestQueueEnqueueAndFetch2359=== PAUSE TestQueueEnqueueAndFetch2360=== RUN TestQueueDeduplication2361=== PAUSE TestQueueDeduplication2362=== RUN TestQueueRemove2363=== PAUSE TestQueueRemove2364=== RUN TestQueueFetchBatchLimit2365=== PAUSE TestQueueFetchBatchLimit2366=== RUN TestQueueRetryMovesToBack2367=== PAUSE TestQueueRetryMovesToBack2368=== RUN TestQueueFetchRemoveLifecycle2369=== PAUSE TestQueueFetchRemoveLifecycle2370=== RUN TestQueueConcurrentWriters2371=== PAUSE TestQueueConcurrentWriters2372=== RUN TestQueueRemoveLargeClosure2373=== PAUSE TestQueueRemoveLargeClosure2374=== RUN TestServerClientIntegration2375--- PASS: TestServerClientIntegration (0.00s)2376=== RUN TestServerQueueError23772026/10/25 19:01:23 ERROR Failed to queue paths error="permission denied" count=12378--- PASS: TestServerQueueError (0.00s)2379=== RUN TestGetListenerSocketActivation2380 server_test.go:218: === RUN TestGetListenerSocketActivation2381 --- PASS: TestGetListenerSocketActivation (0.00s)2382 PASS2383 2384--- PASS: TestGetListenerSocketActivation (0.01s)2385=== RUN TestServerStalledClientDoesNotBlockShutdown2386=== PAUSE TestServerStalledClientDoesNotBlockShutdown2387=== RUN TestServerBacksOffOnAcceptErrors2388=== PAUSE TestServerBacksOffOnAcceptErrors2389=== RUN TestDrainIsolatesPoisonPath2390=== PAUSE TestDrainIsolatesPoisonPath2391=== RUN TestRunNotBlockedByPoisonHead2392=== PAUSE TestRunNotBlockedByPoisonHead2393=== RUN TestDrainGivesUpWhenServerDown2394=== PAUSE TestDrainGivesUpWhenServerDown2395=== RUN TestFailedPathPrunedByLaterClosure2396=== PAUSE TestFailedPathPrunedByLaterClosure2397=== RUN TestWorkerUploadsAndRemoves2398=== PAUSE TestWorkerUploadsAndRemoves2399=== RUN TestWorkerSkipsGCdPaths2400=== PAUSE TestWorkerSkipsGCdPaths2401=== RUN TestWorkerPrunesClosureDeps2402=== PAUSE TestWorkerPrunesClosureDeps2403=== RUN TestDrainTimeout2404=== PAUSE TestDrainTimeout2405=== RUN TestWorkerRemoveFailureIsNotProgress2406=== PAUSE TestWorkerRemoveFailureIsNotProgress2407=== RUN TestWorkerKeepsPathItCannotStat2408=== PAUSE TestWorkerKeepsPathItCannotStat2409=== CONT TestSendPathsEmpty2410=== CONT TestWorkerRemoveFailureIsNotProgress2411--- PASS: TestSendPathsEmpty (0.00s)2412=== CONT TestWorkerKeepsPathItCannotStat2413=== CONT TestDrainIsolatesPoisonPath2414=== CONT TestServerBacksOffOnAcceptErrors2415=== CONT TestQueueFetchBatchLimit24162026/10/25 19:01:23 ERROR Accept failed error="too many open files"2417=== CONT TestQueueRemove2418=== CONT TestQueueDeduplication2419=== CONT TestQueueEnqueueAndFetch2420=== CONT TestWorkerUploadsAndRemoves2421=== CONT TestDrainTimeout2422=== CONT TestWorkerPrunesClosureDeps2423=== CONT TestQueueRetryMovesToBack2424=== CONT TestWorkerSkipsGCdPaths2425=== CONT TestServerStalledClientDoesNotBlockShutdown2426=== CONT TestDrainGivesUpWhenServerDown2427=== CONT TestFailedPathPrunedByLaterClosure2428=== CONT TestQueueFetchRemoveLifecycle2429=== CONT TestQueueRemoveLargeClosure2430=== CONT TestRunNotBlockedByPoisonHead2431=== CONT TestQueueConcurrentWriters24322026/10/25 19:01:23 ERROR Accept failed error="too many open files"24332026/10/25 19:01:23 INFO Uploading batch count=224342026/10/25 19:01:23 INFO Uploading batch count=424352026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=424362026/10/25 19:01:23 INFO Uploading batch count=224372026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=224382026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown688750320/002/a24392026/10/25 19:01:23 INFO Upload queue status pending=224402026/10/25 19:01:23 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4101914784/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat4101914784/002/locked/aaa: permission denied"24412026/10/25 19:01:23 INFO Uploading batch count=124422026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=12443--- PASS: TestQueueFetchBatchLimit (0.02s)24442026/10/25 19:01:23 INFO Upload queue status pending=224452026/10/25 19:01:23 INFO Uploading batch count=124462026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown688750320/002/b2447--- PASS: TestQueueDeduplication (0.02s)24482026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3192067962/002/bbb24492026/10/25 19:01:23 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4101914784/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat4101914784/002/locked/aaa: permission denied"24502026/10/25 19:01:23 INFO Upload queue status pending=324512026/10/25 19:01:23 INFO Upload queue status pending=22452--- PASS: TestQueueEnqueueAndFetch (0.02s)24532026/10/25 19:01:23 ERROR Accept failed error="too many open files"24542026/10/25 19:01:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2550031543/002/nonexistent24552026/10/25 19:01:23 INFO Uploading batch count=224562026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=224572026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown688750320/002/c24582026/10/25 19:01:23 INFO Uploading batch count=224592026/10/25 19:01:23 INFO Uploading batch count=12460--- PASS: TestQueueRetryMovesToBack (0.02s)24612026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=12462--- PASS: TestQueueRemove (0.02s)24632026/10/25 19:01:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress4288582981/002/nonexistent24642026/10/25 19:01:23 INFO Uploading batch count=124652026/10/25 19:01:23 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12466--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24672026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown688750320/002/d24682026/10/25 19:01:23 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4101914784/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat4101914784/002/locked/aaa: permission denied"24692026/10/25 19:01:23 INFO Uploading batch count=124702026/10/25 19:01:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress4288582981/002/nonexistent24712026/10/25 19:01:23 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124722026/10/25 19:01:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress4288582981/002/nonexistent24732026/10/25 19:01:23 INFO Uploading batch count=124742026/10/25 19:01:23 ERROR Drain finished with paths left in queue remaining=124752026/10/25 19:01:23 INFO Uploading batch count=124762026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=124772026/10/25 19:01:23 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124782026/10/25 19:01:23 ERROR Drain finished with paths left in queue remaining=124792026/10/25 19:01:23 INFO Uploading batch count=224802026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=224812026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown688750320/002/e2482--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)24832026/10/25 19:01:23 INFO Uploading batch count=124842026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=124852026/10/25 19:01:23 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown688750320/002/f2486--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)24872026/10/25 19:01:23 INFO Uploading batch count=124882026/10/25 19:01:23 ERROR Upload failed error="upload failed" count=124892026/10/25 19:01:23 ERROR Drain finished with paths left in queue remaining=1024902026/10/25 19:01:23 ERROR Drain finished with paths left in queue remaining=12491--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2492--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2493--- PASS: TestDrainIsolatesPoisonPath (0.02s)2494--- PASS: TestWorkerPrunesClosureDeps (0.03s)2495--- PASS: TestWorkerSkipsGCdPaths (0.03s)2496--- PASS: TestWorkerUploadsAndRemoves (0.04s)24972026/10/25 19:01:23 ERROR Accept failed error="too many open files"2498--- PASS: TestQueueRemoveLargeClosure (0.05s)24992026/10/25 19:01:23 ERROR Accept failed error="too many open files"25002026/10/25 19:01:23 ERROR Accept failed error="too many open files"25012026/10/25 19:01:23 ERROR Failed to decode request error="read unix /build/TestServerStalledClientDoesNotBlockShutdown3327375872/001/test.sock->@: i/o timeout"25022026/10/25 19:01:23 ERROR Failed to write response error="write unix /build/TestServerStalledClientDoesNotBlockShutdown3327375872/001/test.sock->@: i/o timeout"2503--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25042026/10/25 19:01:23 ERROR Upload failed error="context deadline exceeded" count=225052026/10/25 19:01:23 ERROR Drain finished with paths left in queue remaining=42506--- PASS: TestDrainTimeout (0.21s)2507--- PASS: TestQueueConcurrentWriters (0.28s)25082026/10/25 19:01:23 ERROR Accept failed error="too many open files"25092026/10/25 19:01:23 ERROR Accept failed error="too many open files"2510--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25112026/10/25 19:01:24 INFO Uploading batch count=125122026/10/25 19:01:24 INFO Uploading batch count=125132026/10/25 19:01:24 INFO Uploading batch count=125142026/10/25 19:01:24 ERROR Upload failed error="upload failed" count=125152026/10/25 19:01:24 INFO Uploading batch count=125162026/10/25 19:01:24 ERROR Upload failed error="upload failed" count=125172026/10/25 19:01:24 INFO Uploading batch count=125182026/10/25 19:01:24 ERROR Upload failed error="upload failed" count=125192026/10/25 19:01:24 INFO Uploading batch count=125202026/10/25 19:01:24 ERROR Upload failed error="upload failed" count=125212026/10/25 19:01:24 ERROR Drain finished with paths left in queue remaining=12522--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2523PASS2524Running signing tests...2525=== RUN TestExternalSigner2526=== PAUSE TestExternalSigner2527=== RUN TestExternalSignerWrongPublicKey2528=== PAUSE TestExternalSignerWrongPublicKey2529=== RUN TestExternalSignerErrors2530=== PAUSE TestExternalSignerErrors2531=== RUN TestExternalSignerRestartsAfterCrash2532=== PAUSE TestExternalSignerRestartsAfterCrash2533=== RUN TestExternalSignerProgramErrorKeepsProcess2534=== PAUSE TestExternalSignerProgramErrorKeepsProcess2535=== RUN TestExternalSignerClose2536=== PAUSE TestExternalSignerClose2537=== RUN TestExternalSignerRejectsInvalidPublicKey2538=== PAUSE TestExternalSignerRejectsInvalidPublicKey2539=== RUN TestExternalSignerCancellation2540=== PAUSE TestExternalSignerCancellation2541=== RUN TestGenerateFingerprint2542=== PAUSE TestGenerateFingerprint2543=== RUN TestParseSigningKey2544=== PAUSE TestParseSigningKey2545=== RUN TestSign2546=== PAUSE TestSign2547=== RUN TestSignBatch2548=== PAUSE TestSignBatch2549=== RUN TestNilKeyPublicKey2550=== PAUSE TestNilKeyPublicKey2551=== RUN TestSignErrors2552=== PAUSE TestSignErrors2553=== CONT TestExternalSigner2554=== CONT TestExternalSignerCancellation2555=== CONT TestExternalSignerProgramErrorKeepsProcess2556=== CONT TestExternalSignerClose2557=== CONT TestSign2558=== CONT TestNilKeyPublicKey2559=== CONT TestSignErrors2560=== CONT TestParseSigningKey2561=== RUN TestParseSigningKey/valid_32-byte_key2562=== PAUSE TestParseSigningKey/valid_32-byte_key2563=== CONT TestSignBatch2564=== CONT TestExternalSignerErrors2565=== CONT TestGenerateFingerprint2566=== RUN TestExternalSignerErrors/wrong_signature_name2567=== PAUSE TestExternalSignerErrors/wrong_signature_name2568=== RUN TestGenerateFingerprint/basic_with_references2569=== PAUSE TestGenerateFingerprint/basic_with_references2570=== RUN TestGenerateFingerprint/no_references2571=== PAUSE TestGenerateFingerprint/no_references2572=== CONT TestExternalSignerWrongPublicKey2573=== CONT TestExternalSignerRejectsInvalidPublicKey2574--- PASS: TestNilKeyPublicKey (0.00s)2575=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2576=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2577=== RUN TestParseSigningKey/no_colon2578=== PAUSE TestParseSigningKey/no_colon2579=== RUN TestParseSigningKey/empty_name2580=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2581=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2582=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2583=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2584=== RUN TestGenerateFingerprint/invalid_nar_hash_length2585=== CONT TestExternalSignerRestartsAfterCrash2586=== RUN TestSignErrors/nil_key2587=== PAUSE TestSignErrors/nil_key2588=== RUN TestSignErrors/nil_narinfo2589=== PAUSE TestSignErrors/nil_narinfo2590=== PAUSE TestParseSigningKey/empty_name2591=== RUN TestExternalSignerRejectsInvalidPublicKey/#002592=== RUN TestExternalSignerErrors/wrong_id2593=== PAUSE TestExternalSignerErrors/wrong_id2594--- PASS: TestSign (0.00s)2595--- PASS: TestSignBatch (0.00s)2596=== RUN TestSignErrors/invalid_narinfo2597=== PAUSE TestSignErrors/invalid_narinfo2598=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2599=== RUN TestParseSigningKey/invalid_base642600=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002601=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2602=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2603=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2604=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2605=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2606=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2607=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2608=== RUN TestExternalSignerErrors/missing_signature_name2609=== PAUSE TestExternalSignerErrors/missing_signature_name2610=== RUN TestExternalSignerErrors/null2611=== PAUSE TestExternalSignerErrors/null2612=== RUN TestSignErrors/canceled2613=== PAUSE TestSignErrors/canceled2614=== CONT TestSignErrors/nil_key2615=== CONT TestSignErrors/nil_narinfo2616=== CONT TestSignErrors/invalid_narinfo2617=== RUN TestGenerateFingerprint/invalid_store_path_prefix2618=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2619=== RUN TestGenerateFingerprint/invalid_reference_prefix2620=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2621=== CONT TestSignErrors/canceled2622--- PASS: TestExternalSignerClose (0.00s)2623=== PAUSE TestParseSigningKey/invalid_base642624=== RUN TestParseSigningKey/wrong_length2625=== PAUSE TestParseSigningKey/wrong_length2626=== CONT TestParseSigningKey/valid_32-byte_key2627=== CONT TestParseSigningKey/empty_name2628=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2629=== CONT TestParseSigningKey/invalid_base642630=== RUN TestExternalSignerErrors/null_signatures2631=== PAUSE TestExternalSignerErrors/null_signatures2632=== RUN TestExternalSignerErrors/wrong_signatures_shape2633=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2634=== CONT TestGenerateFingerprint/basic_with_references2635=== CONT TestGenerateFingerprint/invalid_store_path_prefix2636=== CONT TestGenerateFingerprint/invalid_nar_hash_length2637=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2638=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2639=== CONT TestGenerateFingerprint/no_references2640=== CONT TestGenerateFingerprint/invalid_reference_prefix2641--- PASS: TestSignErrors (0.00s)2642 --- PASS: TestSignErrors/nil_key (0.00s)2643 --- PASS: TestSignErrors/nil_narinfo (0.00s)2644 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2645 --- PASS: TestSignErrors/canceled (0.00s)2646=== CONT TestParseSigningKey/no_colon2647=== CONT TestParseSigningKey/wrong_length2648=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2649=== CONT TestExternalSignerRejectsInvalidPublicKey/#002650=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2651=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2652=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2653=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2654=== RUN TestExternalSignerErrors/too_few_signatures2655=== PAUSE TestExternalSignerErrors/too_few_signatures2656=== RUN TestExternalSignerErrors/exit_at_startup2657=== PAUSE TestExternalSignerErrors/exit_at_startup2658=== RUN TestExternalSignerErrors/wrong_shape2659=== PAUSE TestExternalSignerErrors/wrong_shape2660=== RUN TestExternalSignerErrors/unrequested_key2661=== PAUSE TestExternalSignerErrors/unrequested_key2662=== RUN TestExternalSignerErrors/invalid_signature_base642663=== PAUSE TestExternalSignerErrors/invalid_signature_base642664=== RUN TestExternalSignerErrors/wrong_signature_length2665=== PAUSE TestExternalSignerErrors/wrong_signature_length2666=== RUN TestExternalSignerErrors/program_error2667=== PAUSE TestExternalSignerErrors/program_error2668=== RUN TestExternalSignerErrors/exit_on_request2669--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2670=== PAUSE TestExternalSignerErrors/exit_on_request2671--- PASS: TestGenerateFingerprint (0.00s)2672 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2673 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2674 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2675 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2676 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2677 --- PASS: TestGenerateFingerprint/no_references (0.00s)2678 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2679--- PASS: TestParseSigningKey (0.00s)2680 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2681 --- PASS: TestParseSigningKey/empty_name (0.00s)2682 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2683 --- PASS: TestParseSigningKey/no_colon (0.00s)2684 --- PASS: TestParseSigningKey/wrong_length (0.00s)2685 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2686=== RUN TestExternalSignerErrors/invalid_JSON2687=== PAUSE TestExternalSignerErrors/invalid_JSON2688=== RUN TestExternalSignerErrors/missing_signatures2689=== PAUSE TestExternalSignerErrors/missing_signatures2690--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2691 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2692 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2693 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2694 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2695 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2696--- PASS: TestExternalSignerWrongPublicKey (0.00s)2697=== CONT TestExternalSignerErrors/wrong_signature_name2698=== CONT TestExternalSignerErrors/missing_signatures2699=== CONT TestExternalSignerErrors/invalid_JSON2700=== CONT TestExternalSignerErrors/exit_on_request2701=== CONT TestExternalSignerErrors/too_few_signatures2702=== CONT TestExternalSignerErrors/wrong_signatures_shape2703=== CONT TestExternalSignerErrors/null_signatures2704=== CONT TestExternalSignerErrors/null2705=== CONT TestExternalSignerErrors/missing_signature_name2706=== CONT TestExternalSignerErrors/exit_at_startup2707=== CONT TestExternalSignerErrors/program_error2708=== CONT TestExternalSignerErrors/wrong_signature_length2709=== CONT TestExternalSignerErrors/wrong_id2710=== CONT TestExternalSignerErrors/unrequested_key2711=== CONT TestExternalSignerErrors/invalid_signature_base642712=== CONT TestExternalSignerErrors/wrong_shape2713--- PASS: TestExternalSigner (0.01s)2714--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2715--- PASS: TestExternalSignerErrors (0.00s)2716 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2717 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2718 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2719 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2720 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2721 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2722 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2723 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2724 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2725 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2726 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2727 --- PASS: TestExternalSignerErrors/program_error (0.01s)2728 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2729 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2730 --- PASS: TestExternalSignerErrors/null (0.01s)2731 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2732--- PASS: TestExternalSignerCancellation (0.02s)2733PASS2734Running OpenBao signer tests...2735=== RUN TestSign2736=== PAUSE TestSign2737=== RUN TestSignErrors2738=== PAUSE TestSignErrors2739=== RUN TestServe2740=== PAUSE TestServe2741=== RUN TestServeRejectsGarbage2742=== PAUSE TestServeRejectsGarbage2743=== CONT TestSign2744=== CONT TestServe2745=== CONT TestSignErrors2746=== CONT TestServeRejectsGarbage2747=== RUN TestSignErrors/invalid_json2748=== PAUSE TestSignErrors/invalid_json2749=== RUN TestSignErrors/no_prefix2750=== PAUSE TestSignErrors/no_prefix2751=== RUN TestSignErrors/invalid_base642752--- PASS: TestServeRejectsGarbage (0.00s)2753=== PAUSE TestSignErrors/invalid_base642754=== RUN TestSignErrors/http_error2755=== PAUSE TestSignErrors/http_error2756=== CONT TestSignErrors/invalid_json2757--- PASS: TestServe (0.00s)2758=== CONT TestSignErrors/no_prefix2759=== CONT TestSignErrors/http_error2760=== CONT TestSignErrors/invalid_base642761--- PASS: TestSign (0.00s)2762--- PASS: TestSignErrors (0.00s)2763 --- PASS: TestSignErrors/invalid_json (0.00s)2764 --- PASS: TestSignErrors/no_prefix (0.00s)2765 --- PASS: TestSignErrors/http_error (0.00s)2766 --- PASS: TestSignErrors/invalid_base64 (0.00s)2767PASS