niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #419
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestPartSizeForNAR20=== PAUSE TestPartSizeForNAR21=== RUN TestUploadMultipart_SupersededByPeer22=== PAUSE TestUploadMultipart_SupersededByPeer23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.08s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestSupersededNARStillUploadsListing28=== PAUSE TestSupersededNARStillUploadsListing29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestScriptTokenEmptyCommand115=== CONT TestDoWithRetry_BodyReplayedViaGetBody116=== CONT TestClientSignaturesByStorePath117=== CONT TestScriptTokenNoExpiryRerunsEveryCall118=== CONT TestStreamPushReportsSkippedPaths119=== CONT TestSetClientTLSDoesNotMutateDefaultTransport120=== CONT TestStreamPushReportsSignatures121=== CONT TestStreamPushRequestLine122=== CONT TestStreamPushGivesUpOnDeadServer123=== CONT TestStreamPushIsolatesFailures1242026/10/20 08:17:31 ERROR Upload failed error="connection refused" count=201252026/10/20 08:17:31 ERROR Server seems unavailable, giving up on batch untried=171262026/10/20 08:17:31 ERROR Upload failed error=boom count=1127=== CONT TestSetClientTLS128=== CONT TestStreamPushBatchesUnderLoad129=== CONT TestStreamPushReportsEveryPath130=== CONT TestShellSplitErrors131=== CONT TestShellSplit132=== CONT TestDoWithRetry_FinalResponseBodyReadable133=== CONT TestRetryTimeoutOutlastsMaxRetries134=== CONT TestStreamPushStopsWhenCanceled135=== CONT TestFileTokenEmpty136=== CONT TestScriptTokenScriptFails137=== CONT TestFileTokenMissing138=== CONT TestScriptTokenBadJSON139=== CONT TestFileTokenReadsAndCaches140=== CONT TestScriptTokenEmptyToken141=== CONT TestStaticToken142=== CONT TestScriptTokenCachesUntilRefresh143--- PASS: TestScriptTokenEmptyCommand (0.00s)144--- PASS: TestClientSignaturesByStorePath (0.00s)145--- PASS: TestStreamPushReportsSkippedPaths (0.00s)146--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)147=== CONT TestSetClientTLSErrors148--- PASS: TestShellSplitErrors (0.00s)149--- PASS: TestStaticToken (0.00s)150=== CONT TestUploadMultipart_PartsInParallel151=== CONT TestDumpPathSingleFile152--- PASS: TestStreamPushReportsEveryPath (0.00s)1532026/10/20 08:17:31 WARN Rate limiter enabled after throttle name=server-test rate=5154--- PASS: TestShellSplit (0.00s)155--- PASS: TestStreamPushStopsWhenCanceled (0.00s)156--- PASS: TestFileTokenReadsAndCaches (0.00s)157--- PASS: TestFileTokenEmpty (0.00s)158=== CONT TestSupersededNARStillUploadsListing159=== CONT TestUploadMultipart_SupersededByPeer160=== CONT TestDumpPathMatchesNix161=== RUN TestSetClientTLSErrors/missing_cert_file162=== CONT TestPartSizeForNAR163=== CONT TestParsePathInfoJSONMultiplePaths164--- PASS: TestScriptTokenEmptyToken (0.01s)165--- PASS: TestScriptTokenScriptFails (0.01s)166--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)167=== CONT TestRateLimiterFeedback168=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess169=== RUN TestSupersededNARStillUploadsListing/small_NAR170=== CONT TestResolveStorePath171=== RUN TestRateLimiterFeedback/429_enables_limiter172=== RUN TestUploadMultipart_SupersededByPeer/exists1732026/10/20 08:17:31 WARN Rate limiter enabled after throttle name=server-test rate=5174=== RUN TestPartSizeForNAR/zero_stays_at_minimum175=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum176=== RUN TestPartSizeForNAR/small_stays_at_minimum177=== PAUSE TestSupersededNARStillUploadsListing/small_NAR178=== RUN TestSupersededNARStillUploadsListing/dump_cut_short179=== PAUSE TestPartSizeForNAR/small_stays_at_minimum180--- PASS: TestFileTokenMissing (0.04s)181=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer182=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum183=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum184=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts1852026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:36011186=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1872026/10/20 08:17:31 ERROR Upload failed error="bad path" count=2188=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths189=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths190=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths191--- PASS: TestDoServerRequestAttachesToken (0.06s)192=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun1932026/10/20 08:17:31 ERROR Upload failed error=boom count=1194--- PASS: TestStreamPushIsolatesFailures (0.06s)195--- PASS: TestStreamPushReportsSignatures (0.06s)196=== CONT TestParsePathInfoJSON197=== RUN TestParsePathInfoJSON/Nix_format198--- PASS: TestResolveStorePath (0.00s)1992026/10/20 08:17:31 WARN Rate limiter backed off name=server-test rate=5200=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short2012026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:36011202=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails203=== PAUSE TestUploadMultipart_SupersededByPeer/exists204=== RUN TestUploadMultipart_SupersededByPeer/missing205=== PAUSE TestUploadMultipart_SupersededByPeer/missing206=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts207=== RUN TestPartSizeForNAR/1_TiB208=== PAUSE TestPartSizeForNAR/1_TiB209=== RUN TestPartSizeForNAR/5_TiB_S3_max_object210=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object211=== RUN TestPartSizeForNAR/capped_at_5_GiB212=== PAUSE TestPartSizeForNAR/capped_at_5_GiB213=== CONT TestPathInfoHashCompatibility214=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)215=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)216=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon217=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon218=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI219=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI220=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512221=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512222=== PAUSE TestSetClientTLSErrors/missing_cert_file223=== RUN TestSetClientTLSErrors/missing_key_file224=== PAUSE TestSetClientTLSErrors/missing_key_file225=== RUN TestSetClientTLSErrors/missing_ca_file226=== PAUSE TestSetClientTLSErrors/missing_ca_file227=== CONT TestGetStorePathHash228=== RUN TestGetStorePathHash/valid_store_path229=== PAUSE TestGetStorePathHash/valid_store_path230=== RUN TestGetStorePathHash/basename_without_hyphen_should_error231=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error232=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error233=== PAUSE TestRateLimiterFeedback/429_enables_limiter234=== RUN TestRateLimiterFeedback/503_enables_limiter235=== PAUSE TestRateLimiterFeedback/503_enables_limiter236=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter237=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter238=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter239=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter240--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.06s)241=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error242=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error243=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error244=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica245--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)246=== CONT TestConvertHashToNix32247=== RUN TestConvertHashToNix32/SRI_format_to_Nix32248=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32249=== RUN TestConvertHashToNix32/already_Nix32_format250=== PAUSE TestConvertHashToNix32/already_Nix32_format251=== RUN TestConvertHashToNix32/invalid_format252=== PAUSE TestConvertHashToNix32/invalid_format253=== CONT TestEncodeNixBase32254=== RUN TestEncodeNixBase32/test_string_hash255=== PAUSE TestEncodeNixBase32/test_string_hash256=== RUN TestEncodeNixBase32/empty_input257=== PAUSE TestEncodeNixBase32/empty_input258=== CONT TestDumpPathWriterError2592026/10/20 08:17:31 WARN Rate limiter enabled after throttle name=server-test rate=52602026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:39399261=== PAUSE TestParsePathInfoJSON/Nix_format262=== RUN TestParsePathInfoJSON/Lix_format263=== PAUSE TestParsePathInfoJSON/Lix_format264=== RUN TestParsePathInfoJSON/empty_input265=== PAUSE TestParsePathInfoJSON/empty_input266=== RUN TestParsePathInfoJSON/whitespace_only267=== CONT TestEncodeNixBase32WithRealHash268=== PAUSE TestParsePathInfoJSON/whitespace_only269=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths270=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths271=== CONT TestUploadMultipart_SupersededByPeer/exists2722026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:42797273=== CONT TestPartSizeForNAR/zero_stays_at_minimum274=== CONT TestPartSizeForNAR/5_TiB_S3_max_object275=== CONT TestUploadMultipart_SupersededByPeer/missing276=== RUN TestSetClientTLS/rejects_connection_without_client_cert277=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert278=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA279=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA280=== RUN TestSetClientTLS/preserves_debug_logging_transport281=== PAUSE TestSetClientTLS/preserves_debug_logging_transport282=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)283=== CONT TestPartSizeForNAR/1_TiB284=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts285=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum286=== CONT TestPartSizeForNAR/small_stays_at_minimum287=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512288=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI289=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon290=== CONT TestPartSizeForNAR/capped_at_5_GiB291=== CONT TestRateLimiterFeedback/429_enables_limiter292=== RUN TestParsePathInfoJSON/invalid_JSON293=== PAUSE TestParsePathInfoJSON/invalid_JSON2942026/10/20 08:17:31 INFO Garbage collection started2952026/10/20 08:17:31 WARN Rate limiter backed off name=server-test rate=5296=== CONT TestConvertHashToNix32/SRI_format_to_Nix32297=== CONT TestEncodeNixBase32/test_string_hash298=== CONT TestConvertHashToNix32/invalid_format299=== CONT TestConvertHashToNix32/already_Nix32_format300=== CONT TestPathInfoCACompatibility301=== RUN TestPathInfoCACompatibility/null_ca_field302=== PAUSE TestPathInfoCACompatibility/null_ca_field303=== RUN TestPathInfoCACompatibility/old_string_format_-_text304=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text305=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive306=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive307=== RUN TestPathInfoCACompatibility/new_structured_format_-_text308=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text309=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method310=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method311=== CONT TestRegisterUploadedObjectReusesConnections312=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter313=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry3142026/10/20 08:17:31 WARN Rate limiter enabled after throttle name=server-test rate=53152026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:43333316=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error317=== CONT TestRateLimiterFeedback/503_enables_limiter3182026/10/20 08:17:31 WARN Rate limiter backed off name=server-test rate=5319=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error320=== RUN TestSetClientTLSErrors/invalid_ca_file321=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails322--- PASS: TestEncodeNixBase32WithRealHash (0.00s)323--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.08s)324--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)325 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)326 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)327=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA328=== CONT TestFilterOversizedClosures329=== RUN TestFilterOversizedClosures/no_limit_keeps_everything330=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything3312026/10/20 08:17:31 INFO Garbage collection started332=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped333=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped334=== RUN TestFilterOversizedClosures/all_closures_skipped335=== PAUSE TestFilterOversizedClosures/all_closures_skipped336=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter337=== CONT TestParsePathInfoJSON/Nix_format338=== CONT TestGetStorePathHash/valid_store_path339=== CONT TestPathInfoCACompatibility/null_ca_field340=== CONT TestCaseHackSuffix341=== CONT TestGetStorePathHash/basename_without_hyphen_should_error342=== CONT TestEncodeNixBase32/empty_input343=== CONT TestSetClientTLS/rejects_connection_without_client_cert344=== PAUSE TestSetClientTLSErrors/invalid_ca_file3452026/10/20 08:17:31 WARN Rate limiter enabled after throttle name=server-test rate=5346=== CONT TestSetClientTLS/preserves_debug_logging_transport3472026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:44181348=== CONT TestParsePathInfoJSON/invalid_JSON349=== CONT TestParsePathInfoJSON/Lix_format350--- PASS: TestPathInfoHashCompatibility (0.00s)351 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)352 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)353 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)354 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)3552026/10/20 08:17:31 WARN Rate limiter backed off name=server-test rate=5356=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3572026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:42797358=== CONT TestPathInfoCACompatibility/new_structured_format_-_text359=== CONT TestFilterOversizedClosures/no_limit_keeps_everything360=== CONT TestFilterOversizedClosures/all_closures_skipped3612026/10/20 08:17:31 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50362=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped363=== CONT TestSetClientTLSErrors/invalid_ca_file3642026/10/20 08:17:31 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=2000365=== CONT TestSetClientTLSErrors/missing_ca_file366=== CONT TestPathInfoCACompatibility/old_string_format_-_text3672026/10/20 08:17:31 WARN Rate limiter enabled after throttle name=s3-test rate=53682026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:46425369=== CONT TestSetClientTLSErrors/missing_key_file3702026/10/20 08:17:31 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=0371=== CONT TestParsePathInfoJSON/whitespace_only372=== CONT TestParsePathInfoJSON/empty_input373=== CONT TestSupersededNARStillUploadsListing/small_NAR374=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails375--- PASS: TestConvertHashToNix32 (0.00s)376 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)377 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)378 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)379--- PASS: TestDumpPathSingleFile (0.23s)380--- PASS: TestScriptTokenBadJSON (0.38s)381--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.05s)382--- PASS: TestPartSizeForNAR (0.01s)383 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)384 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)385 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)386 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)387 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)388 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)389 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)390--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.73s)3912026/10/20 08:17:31 INFO Uploading abc-hello (1.0GB)392--- PASS: TestStreamPushBatchesUnderLoad (0.74s)393=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3942026/10/20 08:17:31 INFO Uploading abc-hello (1.0GB)3952026/10/20 08:17:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:42797396--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.71s)3972026/10/20 08:17:31 WARN Garbage collection finished on another replica. Its statistics are not available here398=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive399=== CONT TestSetClientTLSErrors/missing_cert_file400--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)401 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.17s)402 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.71s)403--- PASS: TestRateLimiterFeedback (0.28s)404 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.33s)405 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.71s)406 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)407 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.54s)408--- PASS: TestParsePathInfoJSON (0.29s)409 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)410 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)411 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)412 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)413 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)4142026/10/20 08:17:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:38213/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:38213/api/uploads/complete415--- PASS: TestEncodeNixBase32 (0.00s)416 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)417 --- PASS: TestEncodeNixBase32/empty_input (0.00s)4182026/10/20 08:17:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"419--- PASS: TestPathInfoCACompatibility (0.00s)420 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)421 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)422 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)423 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)424 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)425--- PASS: TestFilterOversizedClosures (0.27s)426 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)427 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)428 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)429--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (1.01s)4302026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:42797431--- PASS: TestGetStorePathHash (0.27s)432 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)433 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)434 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)435 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)436--- PASS: TestCaseHackSuffix (0.29s)4372026/10/20 08:17:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:38213/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:38213/api/uploads/complete4382026/10/20 08:17:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4392026/10/20 08:17:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:38213/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:38213/api/uploads/complete4402026/10/20 08:17:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"441--- PASS: TestSetClientTLSErrors (0.77s)442 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)443 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)444 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)445 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)446--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.02s)447--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.02s)4482026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:42797449--- PASS: TestStreamPushRequestLine (1.07s)4502026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:427974512026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:427974522026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:427974532026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:427974542026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:427974552026/10/20 08:17:32 http: TLS handshake error from 127.0.0.1:32998: remote error: tls: bad certificate456--- PASS: TestSetClientTLS (0.07s)457 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.29s)458 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.29s)459 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.29s)4602026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:427974612026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:427974622026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:427974632026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:427974642026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:42797465--- PASS: TestDumpPathWriterError (1.03s)466--- PASS: TestRegisterUploadedObjectReusesConnections (1.01s)4672026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:427974682026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:427974692026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:427974702026/10/20 08:17:32 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:42797471--- PASS: TestRetryTimeoutOutlastsMaxRetries (1.07s)4722026/10/20 08:17:32 INFO Uploading abc-hello (1.0GB)473--- PASS: TestDumpPathMatchesNix (1.10s)4742026/10/20 08:17:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:42775/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:42775/part/24752026/10/20 08:17:32 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"476--- PASS: TestSupersededNARStillUploadsListing (0.35s)477 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.29s)478 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.29s)479 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.84s)480--- PASS: TestUploadMultipart_PartsInParallel (1.61s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "nixbld".484This user must also own the server process.485486The database cluster will be initialized with locale "C".487The default database encoding has accordingly been set to "SQL_ASCII".488The default text search configuration will be set to "english".489490Data page checksums are enabled.491492creating directory /build/postgres3371324972/data ... ok493creating subdirectories ... ok494selecting dynamic shared memory implementation ... posix495selecting default "max_connections" ... 100496selecting default "shared_buffers" ... 128MB497selecting default time zone ... UTC498creating configuration files ... ok499running bootstrap script ... ok500performing post-bootstrap initialization ... ok501syncing data to disk ... ok502503initdb: warning: enabling "trust" authentication for local connections504initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.505506Success. You can now start the database server using:507508 pg_ctl -D /build/postgres3371324972/data -l logfile start509510/build/postgres3371324972:5432 - no response5112026-10-20 08:17:34.011 UTC [130] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5122026-10-20 08:17:34.012 UTC [130] LOG: listening on Unix socket "/build/postgres3371324972/.s.PGSQL.5432"5132026-10-20 08:17:34.016 UTC [137] LOG: database system was shut down at 2026-10-20 08:17:33 UTC5142026-10-20 08:17:34.019 UTC [130] LOG: database system is ready to accept connections515/build/postgres3371324972:5432 - accepting connections516=== RUN TestService_AuthMiddleware517=== PAUSE TestService_AuthMiddleware518=== RUN TestService_AuthMiddleware_MTLSProxyHeader519=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader520=== RUN TestService_AuthMiddleware_MTLSBoundSubjects521=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects522=== RUN TestService_ReadAuthMiddleware523=== PAUSE TestService_ReadAuthMiddleware524=== RUN TestService_AuthMiddleware_OIDC525=== PAUSE TestService_AuthMiddleware_OIDC526=== RUN TestService_RequireScope_OIDC527=== PAUSE TestService_RequireScope_OIDC528=== RUN TestService_ReadScope_PublicByDefault529=== PAUSE TestService_ReadScope_PublicByDefault530=== RUN TestCacheConfigHandler531=== PAUSE TestCacheConfigHandler532=== RUN TestCacheStatsHandler533=== PAUSE TestCacheStatsHandler534=== RUN TestClientCADerivations535=== PAUSE TestClientCADerivations536=== RUN TestClientErrorHandling537=== PAUSE TestClientErrorHandling538=== RUN TestClientIntegration539=== PAUSE TestClientIntegration540=== RUN TestClientMultipleUploads541=== PAUSE TestClientMultipleUploads542=== RUN TestClientWithDependencies543=== PAUSE TestClientWithDependencies544=== RUN TestClientSharedPathCommittedMidPush545=== PAUSE TestClientSharedPathCommittedMidPush546=== RUN TestPinProtectsFromGC547=== PAUSE TestPinProtectsFromGC548=== RUN TestClientPushesUseOnePush549=== PAUSE TestClientPushesUseOnePush550=== RUN TestClientFallsBackToClosures551=== PAUSE TestClientFallsBackToClosures552=== RUN TestDeleteClosuresRacingPins553=== PAUSE TestDeleteClosuresRacingPins554=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock555=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== RUN TestResolveDBConnectionString557=== PAUSE TestResolveDBConnectionString558=== RUN TestConnectWaitsForAPeerMigration559=== PAUSE TestConnectWaitsForAPeerMigration560=== RUN TestLeadElectsOneAndHandsOver561=== PAUSE TestLeadElectsOneAndHandsOver562=== RUN TestLeadIncumbentWinsAfterRestart5632026/10/20 08:17:36 INFO lead: acquired remote=192.0.2.1:12345642026/10/20 08:17:36 INFO lead: released remote=192.0.2.1:12345652026/10/20 08:17:37 INFO lead: acquired remote=192.0.2.1:12345662026/10/20 08:17:38 INFO lead: released remote=192.0.2.1:1234567--- PASS: TestLeadIncumbentWinsAfterRestart (2.10s)568=== RUN TestLeadIncumbentAnnouncesAtOnce569=== PAUSE TestLeadIncumbentAnnouncesAtOnce570=== RUN TestLeadEndsOnShutdown571=== PAUSE TestLeadEndsOnShutdown572=== RUN TestLeadEndsWhenItsConnectionHangs5732026/10/20 08:17:38 INFO lead: acquired remote=192.0.2.1:12345742026-10-20 08:17:39.645 UTC [385] FATAL: terminating connection due to administrator command5752026/10/20 08:17:39 INFO lead: acquired remote=192.0.2.1:12345762026/10/20 08:17:40 WARN lead: lock connection lost error="timeout: context deadline exceeded"5772026/10/20 08:17:40 INFO lead: released remote=192.0.2.1:12345782026/10/20 08:17:41 INFO lead: released remote=192.0.2.1:1234579--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)580=== RUN TestGCAdvisoryLockBlocksConcurrentRun581=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun582=== RUN TestGCBugBareHashReferences583=== PAUSE TestGCBugBareHashReferences584=== RUN TestGCMetrics585=== PAUSE TestGCMetrics586=== RUN TestPushDedupSurvivesConcurrentGC587=== PAUSE TestPushDedupSurvivesConcurrentGC588=== RUN TestDeduplicatedObjectsRecordedAsPending589=== PAUSE TestDeduplicatedObjectsRecordedAsPending590=== RUN TestGCSweepSkipsPendingObjects591=== PAUSE TestGCSweepSkipsPendingObjects592=== RUN TestTombstonedObjectOfferedWithoutWaiting593=== PAUSE TestTombstonedObjectOfferedWithoutWaiting594=== RUN TestGCSweepDeliversEachKeyOnce595=== PAUSE TestGCSweepDeliversEachKeyOnce596=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection597=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== RUN TestForceGCDuringPushOffersSweptObject599=== PAUSE TestForceGCDuringPushOffersSweptObject600=== RUN TestFailedS3DeleteKeepsTombstone601=== PAUSE TestFailedS3DeleteKeepsTombstone602=== RUN TestSweepSkipsRowsLockedByPush603=== PAUSE TestSweepSkipsRowsLockedByPush604=== RUN TestRegisterCompletedObjectNeedsPendingRow605=== PAUSE TestRegisterCompletedObjectNeedsPendingRow606=== RUN TestGetExistingObjectsLocksRows607=== PAUSE TestGetExistingObjectsLocksRows608=== RUN TestSweepRechecksPendingAfterLocking609=== PAUSE TestSweepRechecksPendingAfterLocking610=== RUN TestPushWaitsForSweepHoldingRow611=== PAUSE TestPushWaitsForSweepHoldingRow612=== RUN TestCommitRacingPendingCleanupKeepsObjects613=== PAUSE TestCommitRacingPendingCleanupKeepsObjects614=== RUN TestGCEndsOnShutdown615=== PAUSE TestGCEndsOnShutdown616=== RUN TestGCTaskStore_StartNew617=== PAUSE TestGCTaskStore_StartNew618=== RUN TestGCTaskStore_DeduplicateSameParams619=== PAUSE TestGCTaskStore_DeduplicateSameParams620=== RUN TestGCTaskStore_ConflictDifferentParams621=== PAUSE TestGCTaskStore_ConflictDifferentParams622=== RUN TestGCTaskStore_GetEmpty623=== PAUSE TestGCTaskStore_GetEmpty624=== RUN TestGCTaskStore_GetReturnsLatest625=== PAUSE TestGCTaskStore_GetReturnsLatest626=== RUN TestGCTaskStore_CompletedAllowsNewTask627=== PAUSE TestGCTaskStore_CompletedAllowsNewTask628=== RUN TestGCTaskStore_PhaseUpdates629=== PAUSE TestGCTaskStore_PhaseUpdates630=== RUN TestGCTaskStore_Fail631=== PAUSE TestGCTaskStore_Fail632=== RUN TestGracefulShutdownDrainsInflight633=== PAUSE TestGracefulShutdownDrainsInflight634=== RUN TestService_healthCheckHandler635=== PAUSE TestService_healthCheckHandler636=== RUN TestService_readinessHandler637=== PAUSE TestService_readinessHandler638=== RUN TestGenerateLandingPage639=== PAUSE TestGenerateLandingPage640=== RUN TestCacheConfigHandlerMaxNarSize641=== PAUSE TestCacheConfigHandlerMaxNarSize642=== RUN TestCreatePendingClosureRejectsOversizedNAR643=== PAUSE TestCreatePendingClosureRejectsOversizedNAR644=== RUN TestNARDeduplicationMetadataUploadBug645=== PAUSE TestNARDeduplicationMetadataUploadBug646=== RUN TestMetricsInventory647=== PAUSE TestMetricsInventory648=== RUN TestMetricsCommit649=== PAUSE TestMetricsCommit650=== RUN TestService_NativeMTLS651=== PAUSE TestService_NativeMTLS652=== RUN TestServerTLSConfig653=== PAUSE TestServerTLSConfig654=== RUN TestMultipartCleanup655=== PAUSE TestMultipartCleanup656=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded657=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== RUN TestPendingCleanupUsesOneCutoff659=== PAUSE TestPendingCleanupUsesOneCutoff660=== RUN TestObjectStatsTrigger661=== PAUSE TestObjectStatsTrigger662=== RUN TestObjectStatsLargeCommit663=== PAUSE TestObjectStatsLargeCommit664=== RUN TestOrphanedObjectsGC665=== PAUSE TestOrphanedObjectsGC666=== RUN TestOrphanedObjectsGCStressTest667=== PAUSE TestOrphanedObjectsGCStressTest668=== RUN TestCreatePin_ReservedPins669=== PAUSE TestCreatePin_ReservedPins670=== RUN TestPresentReportsOnlyClosureRoots671=== PAUSE TestPresentReportsOnlyClosureRoots672=== RUN TestPresentRefreshesOnlyStaleClosures673=== PAUSE TestPresentRefreshesOnlyStaleClosures674=== RUN TestPresentNotReportedWhileGCDeletesClosure675=== PAUSE TestPresentNotReportedWhileGCDeletesClosure676=== RUN TestParseSingleRange677=== PAUSE TestParseSingleRange678=== RUN TestProxyHeadersOnlyTrustedOnSocket6792026/10/20 08:17:41 INFO Starting HTTP server address=127.0.0.1:359516802026/10/20 08:17:41 INFO Starting HTTP server address=proxy.sock6812026/10/20 08:17:41 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6822026/10/20 08:17:41 INFO Shutdown signal received, draining in-flight requests timeout=10s683--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.28s)684=== RUN TestIsValidCachePath685=== PAUSE TestIsValidCachePath686=== RUN TestReadProxyNarinfo687=== PAUSE TestReadProxyNarinfo688=== RUN TestReadProxyNarinfoAlreadyDecompressed689=== PAUSE TestReadProxyNarinfoAlreadyDecompressed690=== RUN TestReadProxyContentNegotiation691=== PAUSE TestReadProxyContentNegotiation692=== RUN TestReadProxyNarStreaming693=== PAUSE TestReadProxyNarStreaming694=== RUN TestReadProxy404695=== PAUSE TestReadProxy404696=== RUN TestReadProxyInvalidPath697=== PAUSE TestReadProxyInvalidPath698=== RUN TestReadProxyHead699=== PAUSE TestReadProxyHead700=== RUN TestReadProxyOutlastsServerWriteTimeout701=== PAUSE TestReadProxyOutlastsServerWriteTimeout702=== RUN TestReadProxyConditionalGet703=== PAUSE TestReadProxyConditionalGet704=== RUN TestReadProxyRootRedirectsToIndexHTML705=== PAUSE TestReadProxyRootRedirectsToIndexHTML706=== RUN TestReadProxyDisabled707=== PAUSE TestReadProxyDisabled708=== RUN TestReadRedirectNar709=== PAUSE TestReadRedirectNar710=== RUN TestReadRedirectKeepsNarinfoProxied711=== PAUSE TestReadRedirectKeepsNarinfoProxied712=== RUN TestReadProxyRangeRequest713=== PAUSE TestReadProxyRangeRequest714=== RUN TestReadRedirectUsesPublicS3URL715=== PAUSE TestReadRedirectUsesPublicS3URL716=== RUN TestPush_OverlappingRootsStoreOneRowPerKey717=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey718=== RUN TestPush_CompleteCommitsEveryRoot719=== PAUSE TestPush_CompleteCommitsEveryRoot720=== RUN TestPush_RepeatedRootCommitsOnce721=== PAUSE TestPush_RepeatedRootCommitsOnce722=== RUN TestPush_CompleteWaitsForCleanupOfThePush723=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush724=== RUN TestPush_RootsAreLockedInByteOrder725=== PAUSE TestPush_RootsAreLockedInByteOrder726=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit727=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit728=== RUN TestPush_RejectsBadRequests729=== PAUSE TestPush_RejectsBadRequests730=== RUN TestPush_SignsNarinfosOfItsPendingObjects731=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects732=== RUN TestRedundantMultipartUpload733=== PAUSE TestRedundantMultipartUpload734=== RUN TestCompleteMultipartUpload_ErrorButObjectExists735=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists736=== RUN TestCompletedNarNotReofferedAcrossClosures737=== PAUSE TestCompletedNarNotReofferedAcrossClosures738=== RUN TestPresignedUploadRegisteredBeforeCommit739=== PAUSE TestPresignedUploadRegisteredBeforeCommit740=== RUN TestService_Rustfstest741=== PAUSE TestService_Rustfstest742=== RUN TestParseSize743=== PAUSE TestParseSize744=== RUN TestSkippedUploadsHandler745=== PAUSE TestSkippedUploadsHandler746=== RUN TestSystemdListenerNotActivated747--- PASS: TestSystemdListenerNotActivated (0.00s)748=== RUN TestWatchdogBeatsWhenHealthy749--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)750=== RUN TestWatchdogSkipsWhenUnhealthy7512026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/20 08:17:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"761--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)762=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle763=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== RUN TestProxyWriteTimeout765=== PAUSE TestProxyWriteTimeout766=== RUN TestPendingClosureWriteTimeout767=== PAUSE TestPendingClosureWriteTimeout768=== RUN TestIsValidUploadKey769=== PAUSE TestIsValidUploadKey770=== RUN TestUploadHandlersRejectInvalidKeys771=== PAUSE TestUploadHandlersRejectInvalidKeys772=== RUN TestUploadHandlersRejectOversizedBody773=== PAUSE TestUploadHandlersRejectOversizedBody774=== RUN TestService_cleanupPendingClosuresHandler775=== PAUSE TestService_cleanupPendingClosuresHandler776=== RUN TestService_createPendingClosureHandler777=== PAUSE TestService_createPendingClosureHandler778=== RUN TestService_verifyS3Integrity779=== PAUSE TestService_verifyS3Integrity780=== RUN TestCompleteMultipartUnregistered781=== PAUSE TestCompleteMultipartUnregistered782=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT783=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT784=== CONT TestSkippedUploadsHandler785=== CONT TestService_AuthMiddleware786=== CONT TestParseSize7872026/10/20 08:17:41 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000788=== CONT TestUploadHandlersRejectOversizedBody789=== CONT TestService_Rustfstest790=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT791=== CONT TestPresignedUploadRegisteredBeforeCommit792=== CONT TestCompleteMultipartUnregistered793=== CONT TestCompletedNarNotReofferedAcrossClosures794=== CONT TestService_verifyS3Integrity795=== CONT TestGCTaskStore_CompletedAllowsNewTask796=== CONT TestPush_RootsAreLockedInByteOrder797=== CONT TestCompleteMultipartUpload_ErrorButObjectExists798=== CONT TestService_createPendingClosureHandler799=== CONT TestRedundantMultipartUpload800=== CONT TestService_cleanupPendingClosuresHandler801=== CONT TestPush_SignsNarinfosOfItsPendingObjects802=== CONT TestPush_RejectsBadRequests803=== CONT TestPendingClosureWriteTimeout804=== RUN TestPendingClosureWriteTimeout/empty805=== PAUSE TestPendingClosureWriteTimeout/empty806=== CONT TestGCTaskStore_GetReturnsLatest807=== CONT TestUploadHandlersRejectInvalidKeys808=== CONT TestGCTaskStore_GetEmpty809=== CONT TestIsValidUploadKey810=== CONT TestGCTaskStore_ConflictDifferentParams811=== CONT TestPresentNotReportedWhileGCDeletesClosure812=== CONT TestGCTaskStore_DeduplicateSameParams813--- PASS: TestParseSize (0.00s)814=== CONT TestPresentRefreshesOnlyStaleClosures815=== CONT TestPresentReportsOnlyClosureRoots816=== RUN TestPendingClosureWriteTimeout/400_objects817=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info818=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info819=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal820=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal821=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key822=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key823=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key824=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key825=== CONT TestPush_CompleteWaitsForCleanupOfThePush826=== CONT TestGCTaskStore_StartNew827=== CONT TestCreatePin_ReservedPins828=== RUN TestIsValidUploadKey/narinfo829=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale830=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale831=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh832--- PASS: TestSkippedUploadsHandler (0.01s)833=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit834=== CONT TestPush_RepeatedRootCommitsOnce835=== PAUSE TestPendingClosureWriteTimeout/400_objects836=== PAUSE TestIsValidUploadKey/narinfo837=== RUN TestIsValidUploadKey/nar_zst838=== PAUSE TestIsValidUploadKey/nar_zst839--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)840--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)841--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)842--- PASS: TestGCTaskStore_GetEmpty (0.00s)843--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)844--- PASS: TestGCTaskStore_StartNew (0.00s)845=== RUN TestIsValidUploadKey/nar_xz846=== PAUSE TestIsValidUploadKey/nar_xz847=== RUN TestPendingClosureWriteTimeout/670k_objects848=== PAUSE TestPendingClosureWriteTimeout/670k_objects849=== RUN TestIsValidUploadKey/nar_plain850=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline851=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline852=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh853=== PAUSE TestIsValidUploadKey/nar_plain854=== RUN TestIsValidUploadKey/listing855=== CONT TestGCEndsOnShutdown856=== RUN TestGCEndsOnShutdown/before_the_run857=== CONT TestPush_CompleteCommitsEveryRoot858=== PAUSE TestIsValidUploadKey/listing859=== PAUSE TestGCEndsOnShutdown/before_the_run860=== RUN TestIsValidUploadKey/build_log861=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete862=== PAUSE TestIsValidUploadKey/build_log863=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete864=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark865=== RUN TestIsValidUploadKey/build_log_home-manager_file866=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark867=== PAUSE TestIsValidUploadKey/build_log_home-manager_file868=== CONT TestOrphanedObjectsGCStressTest869=== RUN TestIsValidUploadKey/build_log_plus_in_name870=== PAUSE TestIsValidUploadKey/build_log_plus_in_name871=== RUN TestIsValidUploadKey/build_log_question_mark872=== PAUSE TestIsValidUploadKey/build_log_question_mark873=== RUN TestIsValidUploadKey/build_log_equals874=== PAUSE TestIsValidUploadKey/build_log_equals875=== RUN TestIsValidUploadKey/realisation876=== PAUSE TestIsValidUploadKey/realisation877=== RUN TestIsValidUploadKey/realisation_plus_in_output878=== PAUSE TestIsValidUploadKey/realisation_plus_in_output879=== RUN TestIsValidUploadKey/nix-cache-info880=== PAUSE TestIsValidUploadKey/nix-cache-info881=== RUN TestIsValidUploadKey/index.html882=== PAUSE TestIsValidUploadKey/index.html883=== RUN TestIsValidUploadKey/narinfo_key,_nar_type884=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type885=== RUN TestIsValidUploadKey/nar_key,_narinfo_type886=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type887=== RUN TestIsValidUploadKey/listing_key,_narinfo_type888=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type889=== RUN TestIsValidUploadKey/traversal890=== PAUSE TestIsValidUploadKey/traversal891=== RUN TestIsValidUploadKey/traversal_nar892=== PAUSE TestIsValidUploadKey/traversal_nar893=== RUN TestIsValidUploadKey/absolute894=== PAUSE TestIsValidUploadKey/absolute895=== RUN TestIsValidUploadKey/empty_key896=== PAUSE TestIsValidUploadKey/empty_key897=== RUN TestIsValidUploadKey/unknown_type898=== PAUSE TestIsValidUploadKey/unknown_type899=== CONT TestPush_OverlappingRootsStoreOneRowPerKey900=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure901=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure902=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart903=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart904=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts905=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts906=== CONT TestCommitRacingPendingCleanupKeepsObjects9072026/10/20 08:17:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38079/oidc9082026/10/20 08:17:42 INFO Received push request method=POST path=/api/pushes9092026/10/20 08:17:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9102026/10/20 08:17:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst911--- PASS: TestCompleteMultipartUnregistered (0.74s)912=== CONT TestReadRedirectUsesPublicS3URL9132026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9142026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9152026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9162026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9172026-10-20 08:17:42.534 UTC [482] ERROR: could not obtain lock on row in relation "closures"9182026-10-20 08:17:42.534 UTC [482] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9192026-10-20 08:17:42.535 UTC [482] ERROR: could not obtain lock on row in relation "closures"9202026-10-20 08:17:42.535 UTC [482] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9212026-10-20 08:17:42.535 UTC [482] ERROR: could not obtain lock on row in relation "closures"9222026-10-20 08:17:42.535 UTC [482] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9232026-10-20 08:17:42.536 UTC [482] ERROR: could not obtain lock on row in relation "closures"9242026-10-20 08:17:42.536 UTC [482] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9252026-10-20 08:17:42.536 UTC [482] ERROR: could not obtain lock on row in relation "closures"9262026-10-20 08:17:42.536 UTC [482] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT927--- PASS: TestPush_RootsAreLockedInByteOrder (0.78s)928=== CONT TestPushWaitsForSweepHoldingRow9292026/10/20 08:17:42 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9302026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9312026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures932--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.81s)933=== CONT TestReadProxyRangeRequest9342026/10/20 08:17:42 INFO Received push request method=POST path=/api/pushes9352026/10/20 08:17:42 INFO Received cleanup request method=DELETE path=/api/pending_closures9362026/10/20 08:17:42 INFO Aborted multipart uploads count=0 kept=09372026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9382026/10/20 08:17:42 INFO Received cleanup request method=DELETE path=/api/pending_closures9392026/10/20 08:17:42 INFO Aborted multipart uploads count=1 kept=09402026/10/20 08:17:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9412026-10-20 08:17:42.656 UTC [461] ERROR: Closure does not exist: id=19422026-10-20 08:17:42.656 UTC [461] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9432026-10-20 08:17:42.656 UTC [461] STATEMENT: -- name: CommitPendingClosure :one944 SELECT commit_pending_closure($1::bigint)::bigint945 946--- PASS: TestService_cleanupPendingClosuresHandler (0.70s)947=== CONT TestReadRedirectKeepsNarinfoProxied948--- PASS: TestPresentReportsOnlyClosureRoots (0.70s)949=== CONT TestSweepRechecksPendingAfterLocking950--- PASS: TestService_Rustfstest (0.92s)951=== CONT TestOrphanedObjectsGC9522026/10/20 08:17:42 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"953--- PASS: TestService_AuthMiddleware (0.97s)954=== CONT TestReadRedirectNar9552026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9562026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures957--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.05s)958=== CONT TestGetExistingObjectsLocksRows9592026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9602026/10/20 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures9612026/10/20 08:17:42 INFO Received push request method=POST path=/api/pushes962--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.91s)963=== CONT TestObjectStatsLargeCommit964--- PASS: TestPresentRefreshesOnlyStaleClosures (0.92s)965=== CONT TestReadProxyDisabled9662026/10/20 08:17:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9672026/10/20 08:17:42 WARN Refused reserved pin name=worker-x86_64-linux9682026/10/20 08:17:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9692026/10/20 08:17:42 INFO Received create pin request method=POST path=/api/pins/my-app9702026/10/20 08:17:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux971--- PASS: TestCreatePin_ReservedPins (0.95s)972=== CONT TestRegisterCompletedObjectNeedsPendingRow9732026/10/20 08:17:42 INFO Received push request method=POST path=/api/pushes9742026-10-20 08:17:42.931 UTC [495] ERROR: Push does not exist: id=19752026-10-20 08:17:42.931 UTC [495] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9762026-10-20 08:17:42.931 UTC [495] STATEMENT: SELECT commit_push($1)977--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.97s)978=== CONT TestReadProxyRootRedirectsToIndexHTML9792026/10/20 08:17:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9802026/10/20 08:17:42 INFO Received complete push request method=POST path=/api/pushes/1/complete9812026/10/20 08:17:42 INFO Received push request method=POST path=/api/pushes9822026/10/20 08:17:42 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LjgyOThmZDYwLTE5YjgtNDFlMC1iZjE3LWYwNGU4ZTYxMTFkNXgxNzkyNDg0MjYyNTIwMTg4MDUx parts=109832026/10/20 08:17:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9842026/10/20 08:17:43 INFO Completed upload id=1 objects=2 duration=8.087312ms9852026/10/20 08:17:43 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009862026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures9872026/10/20 08:17:43 INFO Received complete push request method=POST path=/api/pushes/1/complete9882026/10/20 08:17:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures9892026/10/20 08:17:43 INFO Aborted multipart uploads count=0 kept=09902026/10/20 08:17:43 INFO Received push request method=POST path=/api/pushes9912026/10/20 08:17:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9922026/10/20 08:17:43 INFO Received complete push request method=POST path=/api/pushes/1/complete9932026/10/20 08:17:43 INFO Completed push id=1 objects=4 duration=12.087808ms9942026/10/20 08:17:43 INFO Received push request method=POST path=/api/pushes9952026/10/20 08:17:43 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3Ljk2YjYzZWUxLWQ0ZDItNGRmNS1hY2E3LTY5NWE4Nzg0OTQ4OHgxNzkyNDg0MjYyNTc0MTk5NTUz parts=129962026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures997--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.30s)998=== CONT TestObjectStatsTrigger9992026/10/20 08:17:43 INFO Aborted multipart uploads count=0 kept=01000=== RUN TestPush_RejectsBadRequests/no_roots1001=== PAUSE TestPush_RejectsBadRequests/no_roots1002=== RUN TestPush_RejectsBadRequests/no_objects1003=== PAUSE TestPush_RejectsBadRequests/no_objects1004=== RUN TestPush_RejectsBadRequests/bad_root1005=== PAUSE TestPush_RejectsBadRequests/bad_root1006=== RUN TestPush_RejectsBadRequests/root_not_in_objects1007=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1008=== CONT TestReadProxyConditionalGet10092026/10/20 08:17:43 INFO Aborted multipart uploads count=0 kept=010102026/10/20 08:17:43 INFO Received push request method=POST path=/api/pushes10112026/10/20 08:17:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10122026/10/20 08:17:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10132026/10/20 08:17:43 INFO Signed narinfos id=1 count=110142026/10/20 08:17:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10152026/10/20 08:17:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10162026/10/20 08:17:43 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10172026/10/20 08:17:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10182026/10/20 08:17:43 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10192026/10/20 08:17:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10202026/10/20 08:17:43 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110212026/10/20 08:17:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10222026/10/20 08:17:43 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1023--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (1.20s)1024=== CONT TestDeleteClosuresRacingPins10252026/10/20 08:17:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LmJiMWY4N2Q1LWIzMTktNGU3Mi1hMjRjLTc4YzU0MmJjZTZiM3gxNzkyNDg0MjYyNzcwNTcyMTg1 parts=1010262026/10/20 08:17:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10272026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/20 08:17:43 INFO Completed upload id=1 objects=2 duration=5.64801ms10292026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures10302026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures10312026/10/20 08:17:43 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10322026/10/20 08:17:43 WARN Found objects in DB but missing from S3, will re-upload count=11033--- PASS: TestService_verifyS3Integrity (1.42s)1034=== CONT TestPendingCleanupUsesOneCutoff10352026/10/20 08:17:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10362026/10/20 08:17:43 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LjBkNmYzMzA4LWM3ZmItNGI1Yy04ZjE0LTk1YmFmNTk4N2MxNngxNzkyNDg0MjYzMTY4ODg3NzE31037--- PASS: TestReadRedirectUsesPublicS3URL (0.71s)1038=== CONT TestReadProxyOutlastsServerWriteTimeout10392026/10/20 08:17:43 WARN Force mode enabled - objects will be deleted immediately without grace period10402026/10/20 08:17:43 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=010412026/10/20 08:17:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LjBkNmYzMzA4LWM3ZmItNGI1Yy04ZjE0LTk1YmFmNTk4N2MxNngxNzkyNDg0MjYzMTY4ODg3NzE3 parts=110422026/10/20 08:17:43 INFO Completed push id=1 objects=6 duration=265.64451ms1043--- PASS: TestPush_CompleteCommitsEveryRoot (1.27s)10442026/10/20 08:17:43 WARN Force mode enabled - objects will be deleted immediately without grace period1045=== CONT TestClientFallsBackToClosures1046--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.28s)1047=== CONT TestReadProxyHead10482026/10/20 08:17:43 INFO Vacuumed table table=pending_closures10492026/10/20 08:17:43 INFO Completed push id=1 objects=4 duration=232.203411ms1050--- PASS: TestPush_RepeatedRootCommitsOnce (1.27s)1051=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10522026/10/20 08:17:43 INFO Vacuumed table table=pending_objects10532026/10/20 08:17:43 INFO Vacuumed table table=multipart_uploads10542026/10/20 08:17:43 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=01055--- PASS: TestReadProxyRangeRequest (0.68s)1056=== CONT TestReadProxyInvalidPath10572026/10/20 08:17:43 INFO Vacuumed table table=pending_closures10582026/10/20 08:17:43 INFO Vacuumed table table=closures10592026/10/20 08:17:43 INFO Vacuumed table table=pending_objects10602026/10/20 08:17:43 INFO Vacuumed table table=objects10612026/10/20 08:17:43 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=010622026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures10632026/10/20 08:17:43 INFO Vacuumed table table=multipart_uploads10642026/10/20 08:17:43 INFO Vacuumed table table=pending_closures10652026/10/20 08:17:43 INFO Vacuumed table table=closures10662026/10/20 08:17:43 INFO Vacuumed table table=pending_objects1067--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.14s)1068=== CONT TestMultipartCleanup10692026/10/20 08:17:43 INFO Vacuumed table table=objects10702026/10/20 08:17:43 INFO Vacuumed table table=multipart_uploads10712026/10/20 08:17:43 INFO Vacuumed table table=closures10722026/10/20 08:17:43 INFO Vacuumed table table=objects10732026/10/20 08:17:43 INFO Received complete push request method=POST path=/api/pushes/2/complete10742026/10/20 08:17:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10752026/10/20 08:17:43 INFO Completed push id=2 objects=4 duration=11.851026ms1076--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.34s)1077=== CONT TestReadProxy40410782026/10/20 08:17:43 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001079--- PASS: TestService_createPendingClosureHandler (1.35s)1080=== CONT TestReadProxyNarStreaming1081--- PASS: TestReadRedirectKeepsNarinfoProxied (0.66s)1082=== CONT TestReadProxyContentNegotiation10832026/10/20 08:17:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LmYxZDhhMDRkLTgwMTItNDU0YS1hNmYyLTk4YjI1MGQ5MmRjZXgxNzkyNDg0MjYyODI0NzM2NDQ3 parts=1210842026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures10852026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures10862026/10/20 08:17:43 INFO Aborted multipart uploads count=0 kept=01087--- PASS: TestReadRedirectNar (0.65s)1088=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1089--- PASS: TestGetExistingObjectsLocksRows (0.63s)1090=== CONT TestSweepSkipsRowsLockedByPush1091--- PASS: TestReadProxyDisabled (0.60s)1092=== CONT TestReadProxyNarinfoAlreadyDecompressed1093--- PASS: TestObjectStatsTrigger (0.48s)1094=== CONT TestFailedS3DeleteKeepsTombstone1095--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.63s)1096=== CONT TestReadProxyNarinfo1097--- PASS: TestReadProxyConditionalGet (0.47s)1098=== CONT TestForceGCDuringPushOffersSweptObject1099=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1100=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1101=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1102=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1103=== CONT TestIsValidCachePath1104=== RUN TestIsValidCachePath/narinfo1105=== PAUSE TestIsValidCachePath/narinfo1106=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1107=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1108=== RUN TestIsValidCachePath/nar_zst1109=== PAUSE TestIsValidCachePath/nar_zst1110=== RUN TestIsValidCachePath/nar_xz1111=== PAUSE TestIsValidCachePath/nar_xz1112=== RUN TestIsValidCachePath/nar_bz21113=== PAUSE TestIsValidCachePath/nar_bz21114=== RUN TestIsValidCachePath/nar_uncompressed1115=== PAUSE TestIsValidCachePath/nar_uncompressed1116=== RUN TestIsValidCachePath/ls1117=== PAUSE TestIsValidCachePath/ls1118=== RUN TestIsValidCachePath/log1119=== PAUSE TestIsValidCachePath/log1120=== RUN TestIsValidCachePath/realisation1121=== PAUSE TestIsValidCachePath/realisation1122=== RUN TestIsValidCachePath/nix-cache-info1123=== PAUSE TestIsValidCachePath/nix-cache-info1124=== RUN TestIsValidCachePath/index.html1125=== PAUSE TestIsValidCachePath/index.html1126=== RUN TestIsValidCachePath/traversal_parent1127=== PAUSE TestIsValidCachePath/traversal_parent1128=== RUN TestIsValidCachePath/traversal_in_middle1129=== PAUSE TestIsValidCachePath/traversal_in_middle1130=== RUN TestIsValidCachePath/invalid_char_e1131=== PAUSE TestIsValidCachePath/invalid_char_e1132=== RUN TestIsValidCachePath/invalid_char_u1133=== PAUSE TestIsValidCachePath/invalid_char_u1134=== RUN TestIsValidCachePath/random_path1135=== PAUSE TestIsValidCachePath/random_path1136=== RUN TestIsValidCachePath/empty1137=== PAUSE TestIsValidCachePath/empty1138=== RUN TestIsValidCachePath/leading_slash1139=== PAUSE TestIsValidCachePath/leading_slash1140=== RUN TestIsValidCachePath/wrong_extension1141=== PAUSE TestIsValidCachePath/wrong_extension1142=== RUN TestIsValidCachePath/short_hash1143=== PAUSE TestIsValidCachePath/short_hash1144=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1145--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.67s)1146=== CONT TestServerTLSConfig1147=== RUN TestServerTLSConfig/no_client_CA1148=== PAUSE TestServerTLSConfig/no_client_CA1149=== RUN TestServerTLSConfig/missing_CA_file1150=== PAUSE TestServerTLSConfig/missing_CA_file1151=== RUN TestServerTLSConfig/not_a_PEM_file1152=== PAUSE TestServerTLSConfig/not_a_PEM_file1153=== CONT TestParseSingleRange1154=== RUN TestParseSingleRange/none1155=== PAUSE TestParseSingleRange/none1156=== RUN TestParseSingleRange/unknown_unit1157=== PAUSE TestParseSingleRange/unknown_unit1158=== RUN TestParseSingleRange/multi-range_ignored1159=== PAUSE TestParseSingleRange/multi-range_ignored1160=== RUN TestParseSingleRange/malformed_no_dash1161=== PAUSE TestParseSingleRange/malformed_no_dash1162=== RUN TestParseSingleRange/malformed_both_empty1163=== PAUSE TestParseSingleRange/malformed_both_empty1164=== RUN TestParseSingleRange/malformed_end_before_start1165=== PAUSE TestParseSingleRange/malformed_end_before_start1166=== RUN TestParseSingleRange/closed1167=== PAUSE TestParseSingleRange/closed1168=== RUN TestParseSingleRange/open-ended1169=== PAUSE TestParseSingleRange/open-ended1170=== RUN TestParseSingleRange/end_clamped_to_size1171=== PAUSE TestParseSingleRange/end_clamped_to_size1172=== RUN TestParseSingleRange/suffix1173=== PAUSE TestParseSingleRange/suffix1174=== RUN TestParseSingleRange/suffix_exceeds_size1175=== PAUSE TestParseSingleRange/suffix_exceeds_size1176=== RUN TestParseSingleRange/single_byte1177=== PAUSE TestParseSingleRange/single_byte1178=== RUN TestParseSingleRange/start_past_EOF1179=== PAUSE TestParseSingleRange/start_past_EOF1180=== RUN TestParseSingleRange/start_far_past_EOF1181=== PAUSE TestParseSingleRange/start_far_past_EOF1182=== CONT TestGCSweepDeliversEachKeyOnce1183--- PASS: TestPushWaitsForSweepHoldingRow (1.23s)1184=== CONT TestService_NativeMTLS11852026/10/20 08:17:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11862026/10/20 08:17:43 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LmFkNTlhOGFhLWQ1NGMtNDRkYi05MGZhLTA4OGQyOWQ0YzY4NHgxNzkyNDg0MjYzMzcxNzM5OTQ2 error="Get \"http://127.0.0.1:1/bucket16/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11872026/10/20 08:17:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NGU4ZDc1ZjctZjE1OS00ZGJlLTgxYWEtZWE3Nzk5YmEwMzc3LmJkZTZlZDBiLTFhOGUtNGZlNS05MDk1LTI2YTAyZDkzYjZjZXgxNzkyNDg0MjYzMzQ4NTc2NjAw parts=1211882026/10/20 08:17:43 INFO Received cleanup request method=DELETE path=/api/pending_closures11892026/10/20 08:17:43 INFO Aborted multipart uploads count=1 kept=01190--- PASS: TestRedundantMultipartUpload (1.87s)1191=== CONT TestTombstonedObjectOfferedWithoutWaiting11922026/10/20 08:17:43 WARN Force mode enabled - objects will be deleted immediately without grace period11932026/10/20 08:17:43 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=011942026/10/20 08:17:43 INFO Vacuumed table table=pending_closures11952026/10/20 08:17:43 INFO Vacuumed table table=pending_objects11962026/10/20 08:17:43 INFO Vacuumed table table=multipart_uploads11972026/10/20 08:17:43 INFO Vacuumed table table=closures1198=== NAME TestOrphanedObjectsGC1199 orphaned_objects_gc_test.go:287: GC Test Summary:1200 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1201 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1202 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1203 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1204 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1205--- PASS: TestOrphanedObjectsGC (1.26s)1206=== CONT TestMetricsCommit12072026/10/20 08:17:43 INFO Vacuumed table table=objects1208--- PASS: TestSweepRechecksPendingAfterLocking (1.28s)1209=== CONT TestGCAdvisoryLockBlocksConcurrentRun12102026/10/20 08:17:43 INFO Received uploads request method=POST path=/api/pending_closures12112026/10/20 08:17:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12122026/10/20 08:17:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1213--- PASS: TestService_NativeMTLS (0.24s)1214=== CONT TestMetricsInventory12152026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=012162026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=01217--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.60s)1218=== CONT TestGCSweepSkipsPendingObjects12192026/10/20 08:17:44 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1220--- PASS: TestReadProxyNarinfo (0.57s)1221=== CONT TestNARDeduplicationMetadataUploadBug12222026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=012232026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures1224--- PASS: TestReadProxyNarStreaming (0.88s)1225=== CONT TestDeduplicatedObjectsRecordedAsPending12262026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures1227--- PASS: TestReadProxyContentNegotiation (0.90s)1228=== CONT TestCreatePendingClosureRejectsOversizedNAR12292026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures1230--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1231=== CONT TestPushDedupSurvivesConcurrentGC1232--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.99s)1233=== CONT TestLeadEndsOnShutdown12342026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures1235--- PASS: TestReadProxyInvalidPath (1.01s)1236=== CONT TestGCMetrics1237--- PASS: TestReadProxy404 (1.03s)1238=== CONT TestCacheConfigHandlerMaxNarSize1239--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1240=== CONT TestClientPushesUseOnePush1241--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.76s)1242=== CONT TestLeadIncumbentAnnouncesAtOnce12432026/10/20 08:17:44 INFO Received cleanup request method=DELETE path=/api/pending_closures12442026/10/20 08:17:44 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket54/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12452026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=112462026/10/20 08:17:44 INFO Received cleanup request method=DELETE path=/api/pending_closures1247--- PASS: TestReadProxyHead (1.12s)1248=== CONT TestPinProtectsFromGC12492026/10/20 08:17:44 INFO Aborted multipart uploads count=1 kept=01250--- PASS: TestMultipartCleanup (1.09s)1251=== CONT TestLeadElectsOneAndHandsOver12522026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures1253--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.58s)1254=== CONT TestConnectWaitsForAPeerMigration12552026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period12562026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period12572026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period12582026/10/20 08:17:44 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=012592026/10/20 08:17:44 INFO Vacuumed table table=pending_closures12602026/10/20 08:17:44 INFO Vacuumed table table=pending_objects12612026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads12622026/10/20 08:17:44 INFO Vacuumed table table=closures12632026/10/20 08:17:44 INFO Vacuumed table table=objects12642026/10/20 08:17:44 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12652026/10/20 08:17:44 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."12662026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=012672026/10/20 08:17:44 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=01268--- PASS: TestFailedS3DeleteKeepsTombstone (0.91s)1269=== CONT TestResolveDBConnectionString1270=== RUN TestResolveDBConnectionString/flag_wins1271=== PAUSE TestResolveDBConnectionString/flag_wins1272=== RUN TestResolveDBConnectionString/file_when_flag_empty1273=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1274=== RUN TestResolveDBConnectionString/missing_file_is_an_error1275=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1276=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1277=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1278=== RUN TestResolveDBConnectionString/nothing_configured1279=== PAUSE TestResolveDBConnectionString/nothing_configured1280=== CONT TestCacheStatsHandler12812026/10/20 08:17:44 INFO Vacuumed table table=pending_closures12822026/10/20 08:17:44 INFO Vacuumed table table=pending_objects12832026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads12842026/10/20 08:17:44 INFO Vacuumed table table=closures12852026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period12862026/10/20 08:17:44 INFO Vacuumed table table=objects1287--- PASS: TestGCSweepDeliversEachKeyOnce (0.85s)1288=== CONT TestCacheConfigHandler1289=== RUN TestCacheConfigHandler/full_config,_no_issuer1290=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1291=== RUN TestCacheConfigHandler/no_cache_url_configured1292=== PAUSE TestCacheConfigHandler/no_cache_url_configured1293=== RUN TestCacheConfigHandler/no_signing_keys1294=== PAUSE TestCacheConfigHandler/no_signing_keys1295=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1296=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1297=== CONT TestClientSharedPathCommittedMidPush12982026/10/20 08:17:44 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=012992026/10/20 08:17:44 INFO Vacuumed table table=pending_closures13002026/10/20 08:17:44 INFO Vacuumed table table=pending_objects13012026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads13022026/10/20 08:17:44 INFO Vacuumed table table=closures13032026/10/20 08:17:44 INFO Vacuumed table table=objects1304--- PASS: TestSweepSkipsRowsLockedByPush (1.05s)1305=== CONT TestService_ReadScope_PublicByDefault13062026/10/20 08:17:44 INFO lead: acquired remote=192.0.2.1:123413072026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures13082026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures1309--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.39s)1310=== CONT TestClientWithDependencies13112026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=013122026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period13132026/10/20 08:17:44 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=013142026/10/20 08:17:44 INFO Vacuumed table table=pending_closures13152026/10/20 08:17:44 INFO Vacuumed table table=pending_objects13162026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads13172026/10/20 08:17:44 INFO Vacuumed table table=closures13182026/10/20 08:17:44 INFO Vacuumed table table=objects1319--- PASS: TestGCMetrics (0.37s)1320=== CONT TestGCBugBareHashReferences1321--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.25s)1322=== CONT TestService_RequireScope_OIDC13232026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=013242026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures13252026/10/20 08:17:44 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=013262026/10/20 08:17:44 INFO Vacuumed table table=pending_closures1327=== NAME TestNARDeduplicationMetadataUploadBug1328 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1030863406/001/store/d9xljqm2mc7bqsh03dgfw0yvc8ffhxgr-file1.txt13292026/10/20 08:17:44 INFO Vacuumed table table=pending_objects13302026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads13312026/10/20 08:17:44 INFO Received push request method=POST path=/api/pushes13322026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=013332026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures13342026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period13352026/10/20 08:17:44 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=013362026/10/20 08:17:44 INFO Vacuumed table table=closures13372026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures13382026/10/20 08:17:44 INFO Vacuumed table table=pending_closures13392026/10/20 08:17:44 INFO Vacuumed table table=objects13402026/10/20 08:17:44 INFO Vacuumed table table=pending_objects13412026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads13422026/10/20 08:17:44 INFO Vacuumed table table=closures13432026/10/20 08:17:44 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13442026/10/20 08:17:44 INFO Uploading 2gf6h8874pymk1zy5pigm93sikai9410-shared-dep (136B)13452026/10/20 08:17:44 INFO Uploading hhxh307741p1kv14amclx56kbb9zfd71-a (216B)13462026/10/20 08:17:44 INFO Vacuumed table table=objects13472026/10/20 08:17:44 INFO Aborted multipart uploads count=0 kept=013482026/10/20 08:17:44 INFO Received complete push request method=POST path=/api/pushes/1/complete13492026/10/20 08:17:44 WARN Force mode enabled - objects will be deleted immediately without grace period13502026/10/20 08:17:44 WARN Failed to register uploaded object key=dla2y08khwvd2sh6lbkypabnnmxybizz.ls error="server returned 404: 404 page not found\n"13512026/10/20 08:17:44 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=013522026/10/20 08:17:44 WARN Failed to register uploaded object key=hhxh307741p1kv14amclx56kbb9zfd71.ls error="server returned 404: 404 page not found\n"13532026/10/20 08:17:44 WARN Failed to register uploaded object key=nar/0g333y3vv5gw47zawqfwj3zfdhaxml8cnlwqq78yg315qdcafnkw.nar.zst error="server returned 404: 404 page not found\n"13542026/10/20 08:17:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13552026/10/20 08:17:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13562026/10/20 08:17:44 INFO Vacuumed table table=pending_closures13572026/10/20 08:17:44 WARN Failed to register uploaded object key=2gf6h8874pymk1zy5pigm93sikai9410.ls error="server returned 404: 404 page not found\n"13582026/10/20 08:17:44 INFO Signed narinfos id=1 count=213592026/10/20 08:17:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13602026/10/20 08:17:44 INFO Vacuumed table table=pending_objects13612026/10/20 08:17:44 INFO Signed narinfos id=2 count=21362--- PASS: TestGCSweepSkipsPendingObjects (0.65s)1363=== CONT TestClientMultipleUploads13642026/10/20 08:17:44 INFO Vacuumed table table=multipart_uploads13652026/10/20 08:17:44 INFO Uploading 4 narinfos13662026/10/20 08:17:44 INFO Vacuumed table table=closures13672026/10/20 08:17:44 INFO Completed push id=1 objects=4 duration=11.28112ms13682026/10/20 08:17:44 INFO Vacuumed table table=objects13692026/10/20 08:17:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1370--- PASS: TestPushDedupSurvivesConcurrentGC (0.52s)1371=== CONT TestGCTaskStore_Fail1372--- PASS: TestGCTaskStore_Fail (0.00s)1373=== CONT TestClientIntegration13742026/10/20 08:17:44 INFO Completed upload id=2 objects=2 duration=1.18679ms13752026/10/20 08:17:44 WARN Failed to register uploaded object key=2gf6h8874pymk1zy5pigm93sikai9410.narinfo error="server returned 404: 404 page not found\n"13762026/10/20 08:17:44 WARN Failed to register uploaded object key=hhxh307741p1kv14amclx56kbb9zfd71.narinfo error="server returned 404: 404 page not found\n"1377--- PASS: TestMetricsInventory (0.73s)1378=== CONT TestGCTaskStore_PhaseUpdates1379--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1380=== CONT TestService_AuthMiddleware_OIDC13812026/10/20 08:17:44 WARN Failed to register uploaded object key=dla2y08khwvd2sh6lbkypabnnmxybizz.narinfo error="server returned 404: 404 page not found\n"13822026/10/20 08:17:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13832026/10/20 08:17:44 WARN Failed to register uploaded object key=2gf6h8874pymk1zy5pigm93sikai9410.narinfo error="server returned 404: 404 page not found\n"1384=== CONT TestClientCADerivations1385--- PASS: TestMetricsCommit (0.80s)13862026/10/20 08:17:44 INFO Completed upload id=2 objects=6 duration=7.327065ms13872026/10/20 08:17:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13882026/10/20 08:17:44 INFO Completed upload id=1 objects=6 duration=1.19907ms13892026/10/20 08:17:44 INFO Upload complete. (129ms)1390=== NAME TestClientFallsBackToClosures1391 client_pushes_test.go:112: Retrieved narinfo from S3:1392 StorePath: /build/TestClientFallsBackToClosures1439042696/001/store/2gf6h8874pymk1zy5pigm93sikai9410-shared-dep1393 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1394 Compression: zstd1395 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821396 NarSize: 1361397 References: 1398 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13992026/10/20 08:17:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40355/oidc1400 client_pushes_test.go:112: Retrieved narinfo from S3:1401 StorePath: /build/TestClientFallsBackToClosures1439042696/001/store/hhxh307741p1kv14amclx56kbb9zfd71-a1402 URL: nar/0g333y3vv5gw47zawqfwj3zfdhaxml8cnlwqq78yg315qdcafnkw.nar.zst1403 Compression: zstd1404 NarHash: sha256:0g333y3vv5gw47zawqfwj3zfdhaxml8cnlwqq78yg315qdcafnkw1405 NarSize: 2161406 References: /build/TestClientFallsBackToClosures1439042696/001/store/2gf6h8874pymk1zy5pigm93sikai9410-shared-dep1407 CA: text:sha256:0i5ph3ay65nlb4z770nqzndryijvcbapb37ijhp1ip7kqbc5mhfv1408 client_pushes_test.go:112: Retrieved narinfo from S3:1409 StorePath: /build/TestClientFallsBackToClosures1439042696/001/store/dla2y08khwvd2sh6lbkypabnnmxybizz-b1410 URL: nar/0g333y3vv5gw47zawqfwj3zfdhaxml8cnlwqq78yg315qdcafnkw.nar.zst1411 Compression: zstd1412 NarHash: sha256:0g333y3vv5gw47zawqfwj3zfdhaxml8cnlwqq78yg315qdcafnkw1413 NarSize: 2161414 References: /build/TestClientFallsBackToClosures1439042696/001/store/2gf6h8874pymk1zy5pigm93sikai9410-shared-dep1415 CA: text:sha256:0i5ph3ay65nlb4z770nqzndryijvcbapb37ijhp1ip7kqbc5mhfv1416--- PASS: TestClientFallsBackToClosures (1.53s)1417=== CONT TestService_ReadAuthMiddleware14182026/10/20 08:17:44 INFO lead: acquired remote=192.0.2.1:123414192026/10/20 08:17:44 INFO lead: released remote=192.0.2.1:12341420--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.45s)1421=== CONT TestProxyWriteTimeout1422=== RUN TestProxyWriteTimeout/narinfo1423=== PAUSE TestProxyWriteTimeout/narinfo1424=== RUN TestProxyWriteTimeout/1_GiB_nar1425=== PAUSE TestProxyWriteTimeout/1_GiB_nar1426=== RUN TestProxyWriteTimeout/10_GiB_nar1427=== PAUSE TestProxyWriteTimeout/10_GiB_nar1428=== RUN TestProxyWriteTimeout/unknown_size1429=== PAUSE TestProxyWriteTimeout/unknown_size1430=== CONT TestClientErrorHandling1431=== RUN TestClientErrorHandling/InvalidStorePath1432=== PAUSE TestClientErrorHandling/InvalidStorePath1433=== RUN TestClientErrorHandling/InvalidAuthToken1434=== PAUSE TestClientErrorHandling/InvalidAuthToken1435=== RUN TestClientErrorHandling/ServerNotAvailable1436=== PAUSE TestClientErrorHandling/ServerNotAvailable1437=== CONT TestService_AuthMiddleware_MTLSProxyHeader14382026/10/20 08:17:44 INFO lead: acquired remote=192.0.2.1:123414392026/10/20 08:17:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33523/oidc14402026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures14412026/10/20 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures14422026/10/20 08:17:44 INFO Received cleanup request method=DELETE path=/api/pending_closures14432026/10/20 08:17:44 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"1444--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.93s)1445=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1446--- PASS: TestCacheStatsHandler (0.47s)1447=== CONT TestGracefulShutdownDrainsInflight14482026/10/20 08:17:44 INFO Starting HTTP server address=127.0.0.1:3966714492026/10/20 08:17:44 INFO Shutdown signal received, draining in-flight requests timeout=10s1450--- PASS: TestService_ReadScope_PublicByDefault (0.47s)1451=== CONT TestService_readinessHandler1452--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1453=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1454--- PASS: TestObjectStatsLargeCommit (2.17s)1455=== CONT TestService_healthCheckHandler1456=== NAME TestOrphanedObjectsGCStressTest1457 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14582026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1459--- PASS: TestGCBugBareHashReferences (0.64s)1460=== CONT TestGenerateLandingPage1461--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.49s)1462=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14632026/10/20 08:17:45 INFO Received uploads request method=POST path=/1464=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14652026/10/20 08:17:45 INFO Received request for more parts method=POST path=/1466=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14672026/10/20 08:17:45 INFO Received complete multipart upload request method=POST path=/1468=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14692026/10/20 08:17:45 INFO Received uploads request method=POST path=/1470--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1471 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1472 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1473 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1474 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1475=== CONT TestPendingClosureWriteTimeout/empty1476=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline14772026/10/20 08:17:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14782026/10/20 08:17:45 INFO Uploading d9xljqm2mc7bqsh03dgfw0yvc8ffhxgr-file1.txt (160B)1479--- PASS: TestGenerateLandingPage (0.00s)1480=== CONT TestPendingClosureWriteTimeout/670k_objects1481=== CONT TestPendingClosureWriteTimeout/400_objects1482=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1483=== NAME TestPinProtectsFromGC1484 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC1119046147/001/store/pp57yx9l67rq3gcbpk1g8qsy3mbxqm44-pinned-file.txt1485 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC1119046147/001/store/ai2gdcsabmbdd2gcq8jgnql1mbpisydc-unpinned-file.txt1486=== NAME TestOrphanedObjectsGCStressTest1487 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion14882026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"14892026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14902026/10/20 08:17:45 WARN Failed to register uploaded object key=d9xljqm2mc7bqsh03dgfw0yvc8ffhxgr.ls error="server returned 404: 404 page not found\n"14912026/10/20 08:17:45 INFO Signed narinfos id=1 count=114922026/10/20 08:17:45 INFO Uploading 1 narinfos14932026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/1/complete14942026/10/20 08:17:45 WARN Failed to register uploaded object key=d9xljqm2mc7bqsh03dgfw0yvc8ffhxgr.narinfo error="server returned 404: 404 page not found\n"14952026/10/20 08:17:45 INFO Completed push id=1 objects=3 duration=11.907866ms14962026/10/20 08:17:45 INFO Upload complete. (526ms)1497=== NAME TestNARDeduplicationMetadataUploadBug1498 metadata_upload_test.go:54: Retrieved narinfo from S3:1499 StorePath: /build/TestNARDeduplicationMetadataUploadBug1030863406/001/store/d9xljqm2mc7bqsh03dgfw0yvc8ffhxgr-file1.txt1500 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1501 Compression: zstd1502 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1503 NarSize: 1601504 References: 1505 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1506 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1507 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1508 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1509=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1510=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1511=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1512=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1513=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1514=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1515=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1516=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1517=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1518=== NAME TestClientWithDependencies1519 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies779332634/001/store/ac7kq1fmqqrpa5xvhmqd4s4k5g73wfn0-test-script1520=== NAME TestNARDeduplicationMetadataUploadBug1521 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1030863406/001/store/c8vcaplsnscbmrn42vzbwlbxzwawkvhi-file2.txt15222026/10/20 08:17:45 WARN readiness check failed error="closed pool"1523--- PASS: TestService_readinessHandler (0.45s)1524=== CONT TestGCEndsOnShutdown/before_the_run15252026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes15262026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1527=== NAME TestClientMultipleUploads1528 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2825381376/001/store/cl52s0m8b9zlihffmvsfy7k5cvsy600w-test-file-0.txt1529=== NAME TestClientWithDependencies1530 client_integration_test.go:615: Found 1 dependencies (including self)15312026/10/20 08:17:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15322026/10/20 08:17:45 INFO Uploading pp57yx9l67rq3gcbpk1g8qsy3mbxqm44-pinned-file.txt (128B)15332026/10/20 08:17:45 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15342026/10/20 08:17:45 INFO Uploading qk101a4mjfawhsfqa7qr0idby3w2n1cd-shared-dep (136B)15352026/10/20 08:17:45 INFO Uploading 63jm30anjbj0x7rkljf435x36r329zrn-top (224B)15362026/10/20 08:17:45 WARN Failed to register uploaded object key=pp57yx9l67rq3gcbpk1g8qsy3mbxqm44.ls error="server returned 404: 404 page not found\n"15372026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15382026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15392026/10/20 08:17:45 INFO Signed narinfos id=1 count=115402026/10/20 08:17:45 WARN Failed to register uploaded object key=qk101a4mjfawhsfqa7qr0idby3w2n1cd.ls error="server returned 404: 404 page not found\n"15412026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15422026/10/20 08:17:45 INFO Uploading 1 narinfos15432026/10/20 08:17:45 WARN Failed to register uploaded object key=63jm30anjbj0x7rkljf435x36r329zrn.ls error="server returned 404: 404 page not found\n"15442026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15452026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/0h0a8a9y7wrmav78538vlm57lrp13mv1vpzi8rafl1fijaq7al16.nar.zst error="server returned 404: 404 page not found\n"15462026/10/20 08:17:45 INFO Signed narinfos id=1 count=215472026/10/20 08:17:45 INFO Uploading 2 narinfos15482026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/1/complete15492026/10/20 08:17:45 WARN Failed to register uploaded object key=pp57yx9l67rq3gcbpk1g8qsy3mbxqm44.narinfo error="server returned 404: 404 page not found\n"15502026/10/20 08:17:45 WARN Failed to register uploaded object key=63jm30anjbj0x7rkljf435x36r329zrn.narinfo error="server returned 404: 404 page not found\n"15512026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/1/complete15522026/10/20 08:17:45 WARN Failed to register uploaded object key=qk101a4mjfawhsfqa7qr0idby3w2n1cd.narinfo error="server returned 404: 404 page not found\n"15532026/10/20 08:17:45 INFO Completed push id=1 objects=3 duration=10.950218ms15542026/10/20 08:17:45 INFO Upload complete. (112ms)15552026/10/20 08:17:45 INFO Completed push id=1 objects=6 duration=8.797099ms15562026/10/20 08:17:45 INFO Upload complete. (104ms)1557=== NAME TestClientSharedPathCommittedMidPush1558 client_integration_test.go:680: Retrieved narinfo from S3:1559 StorePath: /build/TestClientSharedPathCommittedMidPush1357974535/001/store/qk101a4mjfawhsfqa7qr0idby3w2n1cd-shared-dep1560 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1561 Compression: zstd1562 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821563 NarSize: 1361564 References: 1565 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1566=== RUN TestService_RequireScope_OIDC/builder_may_write1567=== PAUSE TestService_RequireScope_OIDC/builder_may_write1568=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1569=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1570=== RUN TestService_RequireScope_OIDC/ops_may_admin1571=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1572=== RUN TestService_RequireScope_OIDC/ops_may_not_write1573=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1574=== RUN TestService_RequireScope_OIDC/reader_may_not_write1575=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1576=== RUN TestService_RequireScope_OIDC/static_token_may_admin1577=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1578=== RUN TestService_RequireScope_OIDC/static_token_may_write1579=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1580=== RUN TestService_RequireScope_OIDC/reader_may_read1581=== PAUSE TestService_RequireScope_OIDC/reader_may_read1582=== RUN TestService_RequireScope_OIDC/writer_implies_read1583=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1584=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1585=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1586=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1587=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1588=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1589=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1590=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1591=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1592=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1593=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1594=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1595=== NAME TestClientSharedPathCommittedMidPush1596 client_integration_test.go:680: Retrieved narinfo from S3:1597 StorePath: /build/TestClientSharedPathCommittedMidPush1357974535/001/store/63jm30anjbj0x7rkljf435x36r329zrn-top1598 URL: nar/0h0a8a9y7wrmav78538vlm57lrp13mv1vpzi8rafl1fijaq7al16.nar.zst1599 Compression: zstd1600 NarHash: sha256:0h0a8a9y7wrmav78538vlm57lrp13mv1vpzi8rafl1fijaq7al161601 NarSize: 2241602 References: /build/TestClientSharedPathCommittedMidPush1357974535/001/store/qk101a4mjfawhsfqa7qr0idby3w2n1cd-shared-dep1603 CA: text:sha256:16r2kw3mh6f3d7yx2gapdpqy7lkmph8dzkbkxvj0x90s680ymri716042026/10/20 08:17:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16052026/10/20 08:17:45 WARN mTLS auth: bound subjects configured but subject DN unavailable16062026/10/20 08:17:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1607--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.60s)1608=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1609--- PASS: TestClientSharedPathCommittedMidPush (1.02s)1610=== CONT TestIsValidUploadKey/narinfo1611=== CONT TestIsValidUploadKey/realisation_plus_in_output1612=== CONT TestIsValidUploadKey/unknown_type1613=== CONT TestIsValidUploadKey/empty_key1614=== CONT TestIsValidUploadKey/absolute1615=== CONT TestIsValidUploadKey/traversal_nar1616=== CONT TestIsValidUploadKey/traversal1617=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1618=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1619=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1620=== CONT TestIsValidUploadKey/index.html1621=== CONT TestIsValidUploadKey/build_log_home-manager_file1622=== CONT TestIsValidUploadKey/realisation1623=== CONT TestIsValidUploadKey/build_log_equals1624=== CONT TestIsValidUploadKey/build_log_question_mark1625=== CONT TestIsValidUploadKey/build_log_plus_in_name1626=== CONT TestIsValidUploadKey/nar_plain1627=== CONT TestIsValidUploadKey/build_log1628=== CONT TestIsValidUploadKey/listing1629=== CONT TestIsValidUploadKey/nar_xz1630=== CONT TestIsValidUploadKey/nar_zst1631=== CONT TestIsValidUploadKey/nix-cache-info1632--- PASS: TestIsValidUploadKey (0.00s)1633 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1634 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1635 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1636 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1637 --- PASS: TestIsValidUploadKey/absolute (0.00s)1638 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1639 --- PASS: TestIsValidUploadKey/traversal (0.00s)1640 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1641 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1642 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1643 --- PASS: TestIsValidUploadKey/index.html (0.00s)1644 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1645 --- PASS: TestIsValidUploadKey/realisation (0.00s)1646 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1647 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1648 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1649 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1650 --- PASS: TestIsValidUploadKey/build_log (0.00s)1651 --- PASS: TestIsValidUploadKey/listing (0.00s)1652 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1653 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1654 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1655=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16562026/10/20 08:17:45 INFO Received uploads request method=POST path=/16572026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes16582026/10/20 08:17:45 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16592026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16602026/10/20 08:17:45 INFO Signed narinfos id=2 count=116612026/10/20 08:17:45 INFO Uploading 1 narinfos16622026/10/20 08:17:45 WARN Failed to register uploaded object key=c8vcaplsnscbmrn42vzbwlbxzwawkvhi.ls error="server returned 404: 404 page not found\n"1663--- PASS: TestService_healthCheckHandler (0.44s)1664=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16652026/10/20 08:17:45 INFO Received request for more parts method=POST path=/16662026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/2/complete16672026/10/20 08:17:45 WARN Failed to register uploaded object key=c8vcaplsnscbmrn42vzbwlbxzwawkvhi.narinfo error="server returned 404: 404 page not found\n"16682026/10/20 08:17:45 INFO Completed push id=2 objects=3 duration=3.734313ms16692026/10/20 08:17:45 INFO Upload complete. (84ms)1670=== NAME TestNARDeduplicationMetadataUploadBug1671 metadata_upload_test.go:76: Retrieved narinfo from S3:1672 StorePath: /build/TestNARDeduplicationMetadataUploadBug1030863406/001/store/c8vcaplsnscbmrn42vzbwlbxzwawkvhi-file2.txt1673 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1674 Compression: zstd1675 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1676 NarSize: 1601677 References: 1678 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1679 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1680 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1681 {"version":1,"root":{"type":"regular","size":44}}1682--- PASS: TestNARDeduplicationMetadataUploadBug (1.40s)1683=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16842026/10/20 08:17:45 INFO Received complete multipart upload request method=POST path=/16852026/10/20 08:17:45 INFO Received uploads request method=POST path=/api/pending_closures1686--- PASS: TestService_ReadAuthMiddleware (0.80s)1687=== CONT TestPush_RejectsBadRequests/no_roots16882026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1689=== CONT TestPush_RejectsBadRequests/bad_root16902026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1691=== CONT TestPush_RejectsBadRequests/no_objects16922026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1693=== CONT TestPush_RejectsBadRequests/root_not_in_objects16942026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1695=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1696--- PASS: TestPush_RejectsBadRequests (1.15s)1697 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1698 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1699 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1700 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1701=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17022026/10/20 08:17:45 INFO lead: released remote=192.0.2.1:12341703--- PASS: TestLeadEndsOnShutdown (1.34s)1704=== CONT TestIsValidCachePath/narinfo1705=== CONT TestIsValidCachePath/index.html1706=== CONT TestIsValidCachePath/short_hash1707=== CONT TestIsValidCachePath/wrong_extension1708=== CONT TestIsValidCachePath/leading_slash1709=== CONT TestIsValidCachePath/empty1710=== CONT TestIsValidCachePath/random_path1711=== CONT TestIsValidCachePath/invalid_char_u1712=== CONT TestIsValidCachePath/invalid_char_e1713=== CONT TestIsValidCachePath/traversal_in_middle1714=== CONT TestIsValidCachePath/traversal_parent1715=== CONT TestIsValidCachePath/nar_uncompressed1716=== CONT TestIsValidCachePath/nix-cache-info1717=== CONT TestIsValidCachePath/realisation1718=== CONT TestIsValidCachePath/log1719=== CONT TestIsValidCachePath/ls1720=== CONT TestIsValidCachePath/nar_bz21721=== CONT TestIsValidCachePath/nar_zst1722=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1723=== CONT TestIsValidCachePath/nar_xz1724--- PASS: TestIsValidCachePath (0.00s)1725 --- PASS: TestIsValidCachePath/narinfo (0.00s)1726 --- PASS: TestIsValidCachePath/index.html (0.00s)1727 --- PASS: TestIsValidCachePath/short_hash (0.00s)1728 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1729 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1730 --- PASS: TestIsValidCachePath/empty (0.00s)1731 --- PASS: TestIsValidCachePath/random_path (0.00s)1732 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1733 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1734 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1735 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1736 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1737 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1738 --- PASS: TestIsValidCachePath/realisation (0.00s)1739 --- PASS: TestIsValidCachePath/log (0.00s)1740 --- PASS: TestIsValidCachePath/ls (0.00s)1741 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1742 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1743 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1744 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1745=== CONT TestServerTLSConfig/no_client_CA1746=== CONT TestServerTLSConfig/not_a_PEM_file1747=== CONT TestServerTLSConfig/missing_CA_file1748--- PASS: TestServerTLSConfig (0.00s)1749 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1750 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1751 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1752=== CONT TestParseSingleRange/none1753=== CONT TestParseSingleRange/start_far_past_EOF1754=== CONT TestParseSingleRange/start_past_EOF1755=== CONT TestParseSingleRange/single_byte1756=== CONT TestParseSingleRange/suffix_exceeds_size1757=== CONT TestParseSingleRange/suffix1758=== CONT TestParseSingleRange/end_clamped_to_size1759=== CONT TestParseSingleRange/open-ended1760=== CONT TestParseSingleRange/closed1761=== CONT TestParseSingleRange/malformed_end_before_start1762=== CONT TestParseSingleRange/malformed_both_empty1763=== CONT TestParseSingleRange/malformed_no_dash1764=== CONT TestParseSingleRange/multi-range_ignored1765=== CONT TestParseSingleRange/unknown_unit1766=== CONT TestResolveDBConnectionString/flag_wins1767=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1768=== CONT TestResolveDBConnectionString/nothing_configured1769=== CONT TestResolveDBConnectionString/missing_file_is_an_error1770--- PASS: TestParseSingleRange (0.00s)1771 --- PASS: TestParseSingleRange/none (0.00s)1772 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1773 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1774 --- PASS: TestParseSingleRange/single_byte (0.00s)1775 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1776 --- PASS: TestParseSingleRange/suffix (0.00s)1777 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1778 --- PASS: TestParseSingleRange/open-ended (0.00s)1779 --- PASS: TestParseSingleRange/closed (0.00s)1780 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1781 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1782 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1783 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1784 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1785=== CONT TestResolveDBConnectionString/file_when_flag_empty1786=== CONT TestCacheConfigHandler/full_config,_no_issuer1787=== CONT TestCacheConfigHandler/no_signing_keys1788=== CONT TestCacheConfigHandler/no_cache_url_configured1789=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1790--- PASS: TestResolveDBConnectionString (0.00s)1791 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1792 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1793 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1794 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1795 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1796--- PASS: TestCacheConfigHandler (0.00s)1797 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1798 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1799 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1800 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1801=== CONT TestProxyWriteTimeout/narinfo1802=== CONT TestProxyWriteTimeout/10_GiB_nar1803=== CONT TestProxyWriteTimeout/1_GiB_nar1804=== CONT TestProxyWriteTimeout/unknown_size1805--- PASS: TestProxyWriteTimeout (0.00s)1806 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1807 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1808 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1809 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1810=== CONT TestClientErrorHandling/InvalidStorePath1811=== CONT TestClientErrorHandling/InvalidAuthToken1812=== NAME TestOrphanedObjectsGCStressTest1813 orphaned_objects_gc_test.go:503: Stress test completed successfully:1814 orphaned_objects_gc_test.go:504: - Active objects preserved: 201815 orphaned_objects_gc_test.go:505: - Objects deleted: 2101816 orphaned_objects_gc_test.go:506: - Total GC'd: 2101817--- PASS: TestOrphanedObjectsGCStressTest (3.65s)1818=== CONT TestClientErrorHandling/ServerNotAvailable18192026/10/20 08:17:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18202026/10/20 08:17:45 INFO Received uploads request method=POST path=/api/pending_closures1821=== NAME TestClientMultipleUploads1822 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2825381376/001/store/pf1yk4f8vkcwx7hd052r1aj6a16bf4jz-test-file-1.txt1823=== NAME TestClientIntegration1824 client_integration_test.go:286: Created store path: /build/TestClientIntegration1307407818/002/store/w59dn64nmwslbms5dc94fhf544sgz769-test-file.txt1825=== NAME TestClientCADerivations1826 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3827986602/001/store/pqyqnnv4c8sp9v7al79ywh4l5jakczyx-ca-test1827=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1828=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18292026/10/20 08:17:45 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]1830=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1831=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18322026/10/20 08:17:45 WARN Authentication failed token_preview=eyJhbGciOi...W1YA4fLyBQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1833=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1834=== CONT TestService_RequireScope_OIDC/builder_may_write1835--- PASS: TestService_AuthMiddleware_OIDC (0.57s)1836 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1837 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1838 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1839 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1840=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read18412026/10/20 08:17:45 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]1842=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1843=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1844=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1845=== CONT TestService_RequireScope_OIDC/writer_implies_read1846=== CONT TestService_RequireScope_OIDC/reader_may_read1847=== CONT TestService_RequireScope_OIDC/static_token_may_write1848=== CONT TestService_RequireScope_OIDC/static_token_may_admin1849=== CONT TestService_RequireScope_OIDC/ops_may_admin1850=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1851=== CONT TestService_RequireScope_OIDC/reader_may_not_write1852=== CONT TestService_RequireScope_OIDC/ops_may_not_write1853--- PASS: TestService_RequireScope_OIDC (0.83s)1854 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1855 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1856 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1857 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1858 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1859 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1860 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1861 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1862 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1863 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1864 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1865 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1866 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1867 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1868=== NAME TestClientCADerivations1869 client_ca_test.go:139: Found 1 dependencies (including self)1870=== NAME TestClientMultipleUploads1871 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2825381376/001/store/4j4gijdrz27rgkhwkr91kamaxiqbyzm2-test-file-2.txt18722026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes18732026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes18742026/10/20 08:17:45 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/present18752026/10/20 08:17:45 INFO Aborted multipart uploads count=0 kept=018762026/10/20 08:17:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18772026/10/20 08:17:45 INFO Uploading ac7kq1fmqqrpa5xvhmqd4s4k5g73wfn0-test-script (136B)18782026/10/20 08:17:45 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18792026/10/20 08:17:45 INFO Uploading 2mj34z9a41algdvljlxdln77h3xikgnc-b (216B)18802026/10/20 08:17:45 INFO Uploading r66aqngvaxk4kq1aba2431dnq2smn9qv-shared-dep (136B)18812026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18822026/10/20 08:17:45 WARN Failed to register uploaded object key=vdl1fbbg9dz87i7vwnivi77z5s23xfal.ls error="server returned 404: 404 page not found\n"18832026/10/20 08:17:45 WARN Failed to register uploaded object key=log/2clq05gjcfpckyjw226g1av31rdilfc6-test-script.drv error="server returned 404: 404 page not found\n"18842026/10/20 08:17:45 WARN Failed to register uploaded object key=2mj34z9a41algdvljlxdln77h3xikgnc.ls error="server returned 404: 404 page not found\n"18852026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/0qyfyikz7cgl2gn4pa5cc2rc5rp8k7bqbwyywjk48zf35fzs1qj6.nar.zst error="server returned 404: 404 page not found\n"18862026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18872026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18882026/10/20 08:17:45 WARN Failed to register uploaded object key=ac7kq1fmqqrpa5xvhmqd4s4k5g73wfn0.ls error="server returned 404: 404 page not found\n"18892026/10/20 08:17:45 WARN Failed to register uploaded object key=r66aqngvaxk4kq1aba2431dnq2smn9qv.ls error="server returned 404: 404 page not found\n"18902026/10/20 08:17:45 INFO Signed narinfos id=1 count=118912026/10/20 08:17:45 INFO Uploading 1 narinfos18922026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18932026/10/20 08:17:45 INFO Signed narinfos id=1 count=318942026/10/20 08:17:45 INFO Uploading 3 narinfos18952026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/1/complete18962026/10/20 08:17:45 WARN Failed to register uploaded object key=r66aqngvaxk4kq1aba2431dnq2smn9qv.narinfo error="server returned 404: 404 page not found\n"18972026/10/20 08:17:45 WARN Failed to register uploaded object key=ac7kq1fmqqrpa5xvhmqd4s4k5g73wfn0.narinfo error="server returned 404: 404 page not found\n"18982026/10/20 08:17:45 WARN Failed to register uploaded object key=2mj34z9a41algdvljlxdln77h3xikgnc.narinfo error="server returned 404: 404 page not found\n"18992026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/1/complete19002026/10/20 08:17:45 WARN Failed to register uploaded object key=vdl1fbbg9dz87i7vwnivi77z5s23xfal.narinfo error="server returned 404: 404 page not found\n"19012026/10/20 08:17:45 INFO Aborted multipart uploads count=0 kept=019022026/10/20 08:17:45 INFO Completed push id=1 objects=4 duration=8.721938ms19032026/10/20 08:17:45 INFO Upload complete. (348ms)19042026/10/20 08:17:45 INFO Completed push id=1 objects=8 duration=8.932979ms19052026/10/20 08:17:45 INFO Upload complete. (403ms)1906=== NAME TestClientPushesUseOnePush1907 client_pushes_test.go:97: Retrieved narinfo from S3:1908 StorePath: /build/TestClientPushesUseOnePush3736428454/001/store/r66aqngvaxk4kq1aba2431dnq2smn9qv-shared-dep1909 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1910 Compression: zstd1911 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821912 NarSize: 1361913 References: 1914 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1915=== NAME TestClientWithDependencies1916 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies779332634/001/store) requires matching store prefix1917=== NAME TestClientPushesUseOnePush1918 client_pushes_test.go:97: Retrieved narinfo from S3:1919 StorePath: /build/TestClientPushesUseOnePush3736428454/001/store/vdl1fbbg9dz87i7vwnivi77z5s23xfal-a1920 URL: nar/0qyfyikz7cgl2gn4pa5cc2rc5rp8k7bqbwyywjk48zf35fzs1qj6.nar.zst1921 Compression: zstd1922 NarHash: sha256:0qyfyikz7cgl2gn4pa5cc2rc5rp8k7bqbwyywjk48zf35fzs1qj61923 NarSize: 2161924 References: /build/TestClientPushesUseOnePush3736428454/001/store/r66aqngvaxk4kq1aba2431dnq2smn9qv-shared-dep1925 CA: text:sha256:1c401ch6fk2z7h5gdxvq1mkiq5kvs2rd1qgcd7lz65f0wrr5v8wh1926 client_pushes_test.go:97: Retrieved narinfo from S3:1927 StorePath: /build/TestClientPushesUseOnePush3736428454/001/store/2mj34z9a41algdvljlxdln77h3xikgnc-b1928 URL: nar/0qyfyikz7cgl2gn4pa5cc2rc5rp8k7bqbwyywjk48zf35fzs1qj6.nar.zst1929 Compression: zstd1930 NarHash: sha256:0qyfyikz7cgl2gn4pa5cc2rc5rp8k7bqbwyywjk48zf35fzs1qj61931 NarSize: 2161932 References: /build/TestClientPushesUseOnePush3736428454/001/store/r66aqngvaxk4kq1aba2431dnq2smn9qv-shared-dep1933 CA: text:sha256:1c401ch6fk2z7h5gdxvq1mkiq5kvs2rd1qgcd7lz65f0wrr5v8wh1934--- PASS: TestClientWithDependencies (1.24s)1935--- PASS: TestClientPushesUseOnePush (1.50s)19362026/10/20 08:17:45 WARN Request failed, retrying attempt=2 backoff=183.795703ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19372026/10/20 08:17:45 WARN Force mode enabled - objects will be deleted immediately without grace period19382026/10/20 08:17:45 WARN Force mode enabled - objects will be deleted immediately without grace period19392026/10/20 08:17:45 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:36679/bucket95/?delete=\": context canceled"19402026/10/20 08:17:45 INFO Received push request method=POST path=/api/pushes1941--- PASS: TestGCEndsOnShutdown (0.00s)1942 --- PASS: TestGCEndsOnShutdown/before_the_run (0.30s)1943 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.45s)1944 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.44s)19452026/10/20 08:17:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19462026/10/20 08:17:45 INFO Uploading w59dn64nmwslbms5dc94fhf544sgz769-test-file.txt (152B)19472026/10/20 08:17:45 WARN Failed to register uploaded object key=w59dn64nmwslbms5dc94fhf544sgz769.ls error="server returned 404: 404 page not found\n"19482026/10/20 08:17:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19492026/10/20 08:17:45 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19502026/10/20 08:17:45 INFO Signed narinfos id=1 count=119512026/10/20 08:17:45 INFO Uploading 1 narinfos19522026/10/20 08:17:45 INFO Received complete push request method=POST path=/api/pushes/1/complete19532026/10/20 08:17:45 WARN Failed to register uploaded object key=w59dn64nmwslbms5dc94fhf544sgz769.narinfo error="server returned 404: 404 page not found\n"19542026/10/20 08:17:45 INFO Completed push id=1 objects=3 duration=6.976002ms19552026/10/20 08:17:45 INFO Upload complete. (144ms)19562026/10/20 08:17:45 INFO Received uploads request method=POST path=/api/pending_closures19572026/10/20 08:17:45 INFO Aborted multipart uploads count=0 kept=019582026/10/20 08:17:45 INFO Received uploads request method=POST path=/api/pending_closures19592026/10/20 08:17:45 INFO Aborted multipart uploads count=0 kept=019602026/10/20 08:17:46 INFO lead: released remote=192.0.2.1:123419612026/10/20 08:17:46 WARN Force mode enabled - objects will be deleted immediately without grace period19622026/10/20 08:17:46 WARN Force mode enabled - objects will be deleted immediately without grace period19632026/10/20 08:17:46 INFO Received push request method=POST path=/api/pushes19642026/10/20 08:17:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19652026/10/20 08:17:46 INFO Uploading ai2gdcsabmbdd2gcq8jgnql1mbpisydc-unpinned-file.txt (128B)19662026/10/20 08:17:46 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=019672026/10/20 08:17:46 INFO Vacuumed table table=pending_closures19682026/10/20 08:17:46 INFO Vacuumed table table=pending_objects19692026/10/20 08:17:46 INFO Vacuumed table table=multipart_uploads19702026/10/20 08:17:46 INFO Vacuumed table table=closures19712026/10/20 08:17:46 INFO Vacuumed table table=objects19722026/10/20 08:17:46 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"19732026/10/20 08:17:46 WARN Failed to register uploaded object key=ai2gdcsabmbdd2gcq8jgnql1mbpisydc.ls error="server returned 404: 404 page not found\n"19742026/10/20 08:17:46 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19752026/10/20 08:17:46 INFO Signed narinfos id=2 count=119762026/10/20 08:17:46 INFO Uploading 1 narinfos19772026/10/20 08:17:46 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=019782026/10/20 08:17:46 INFO Vacuumed table table=pending_closures19792026/10/20 08:17:46 INFO Vacuumed table table=pending_objects19802026/10/20 08:17:46 INFO Vacuumed table table=multipart_uploads19812026/10/20 08:17:46 INFO Vacuumed table table=closures19822026/10/20 08:17:46 INFO Received complete push request method=POST path=/api/pushes/2/complete19832026/10/20 08:17:46 WARN Failed to register uploaded object key=ai2gdcsabmbdd2gcq8jgnql1mbpisydc.narinfo error="server returned 404: 404 page not found\n"19842026/10/20 08:17:46 INFO Vacuumed table table=objects19852026/10/20 08:17:46 INFO Completed push id=2 objects=3 duration=2.196079ms19862026/10/20 08:17:46 INFO Upload complete. (112ms)19872026/10/20 08:17:46 INFO lead: acquired remote=192.0.2.1:12341988--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)1989 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.48s)1990 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.50s)19912026/10/20 08:17:46 WARN Request failed, retrying attempt=3 backoff=379.971922ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19922026/10/20 08:17:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19932026/10/20 08:17:46 INFO Received push request method=POST path=/api/pushes19942026/10/20 08:17:46 INFO All 1 paths already cached1995=== NAME TestClientIntegration1996 client_integration_test.go:312: Retrieved narinfo from S3:1997 StorePath: /build/TestClientIntegration1307407818/002/store/w59dn64nmwslbms5dc94fhf544sgz769-test-file.txt1998 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1999 Compression: zstd2000 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12001 NarSize: 1522002 References: 2003 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk120042026/10/20 08:17:46 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)20052026/10/20 08:17:46 INFO Uploading cl52s0m8b9zlihffmvsfy7k5cvsy600w-test-file-0.txt (160B)20062026/10/20 08:17:46 INFO Uploading pf1yk4f8vkcwx7hd052r1aj6a16bf4jz-test-file-1.txt (160B)20072026/10/20 08:17:46 INFO Uploading 4j4gijdrz27rgkhwkr91kamaxiqbyzm2-test-file-2.txt (160B)2008 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2009 client_integration_test.go:313: Decompressed .ls content (64 bytes):2010 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2011 client_integration_test.go:316: Testing garbage collection...20122026/10/20 08:17:46 WARN Failed to register uploaded object key=cl52s0m8b9zlihffmvsfy7k5cvsy600w.ls error="server returned 404: 404 page not found\n"20132026/10/20 08:17:46 WARN Failed to register uploaded object key=pf1yk4f8vkcwx7hd052r1aj6a16bf4jz.ls error="server returned 404: 404 page not found\n"20142026/10/20 08:17:46 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20152026/10/20 08:17:46 WARN Failed to register uploaded object key=4j4gijdrz27rgkhwkr91kamaxiqbyzm2.ls error="server returned 404: 404 page not found\n"20162026/10/20 08:17:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20172026/10/20 08:17:46 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20182026/10/20 08:17:46 INFO Signed narinfos id=1 count=320192026/10/20 08:17:46 INFO Uploading 3 narinfos20202026/10/20 08:17:46 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20212026/10/20 08:17:46 WARN Failed to register uploaded object key=pf1yk4f8vkcwx7hd052r1aj6a16bf4jz.narinfo error="server returned 404: 404 page not found\n"20222026/10/20 08:17:46 INFO Received complete push request method=POST path=/api/pushes/1/complete20232026/10/20 08:17:46 WARN Failed to register uploaded object key=cl52s0m8b9zlihffmvsfy7k5cvsy600w.narinfo error="server returned 404: 404 page not found\n"20242026/10/20 08:17:46 WARN Failed to register uploaded object key=4j4gijdrz27rgkhwkr91kamaxiqbyzm2.narinfo error="server returned 404: 404 page not found\n"20252026/10/20 08:17:46 INFO Completed push id=1 objects=9 duration=7.420286ms20262026/10/20 08:17:46 INFO Upload complete. (203ms)2027=== NAME TestClientMultipleUploads2028 client_integration_test.go:369: Uploaded 3 paths in 326.647793ms2029--- PASS: TestClientMultipleUploads (1.40s)2030--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2031 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.83s)2032 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.85s)20332026/10/20 08:17:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20342026/10/20 08:17:46 INFO Received push request method=POST path=/api/pushes20352026/10/20 08:17:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures20362026/10/20 08:17:46 INFO Garbage collection started20372026/10/20 08:17:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures20382026/10/20 08:17:46 INFO Garbage collection started20392026/10/20 08:17:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20402026/10/20 08:17:46 INFO Uploading pqyqnnv4c8sp9v7al79ywh4l5jakczyx-ca-test (144B)20412026/10/20 08:17:46 INFO Aborted multipart uploads count=0 kept=020422026/10/20 08:17:46 WARN Failed to register uploaded object key=pqyqnnv4c8sp9v7al79ywh4l5jakczyx.ls error="server returned 404: 404 page not found\n"20432026/10/20 08:17:46 WARN Failed to register uploaded object key=log/x18ywqvykyy606605f127l74h8cikq9q-ca-test.drv error="server returned 404: 404 page not found\n"20442026/10/20 08:17:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20452026/10/20 08:17:46 INFO Signed narinfos id=1 count=120462026/10/20 08:17:46 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20472026/10/20 08:17:46 INFO Uploading 1 narinfos20482026/10/20 08:17:46 INFO Aborted multipart uploads count=0 kept=020492026/10/20 08:17:46 INFO Received complete push request method=POST path=/api/pushes/1/complete20502026/10/20 08:17:46 WARN Failed to register uploaded object key=pqyqnnv4c8sp9v7al79ywh4l5jakczyx.narinfo error="server returned 404: 404 page not found\n"20512026/10/20 08:17:46 INFO Completed push id=1 objects=4 duration=9.241482ms20522026/10/20 08:17:46 INFO Upload complete. (380ms)2053=== NAME TestClientCADerivations2054 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3827986602/001/store/pqyqnnv4c8sp9v7al79ywh4l5jakczyx-ca-test2055 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2056 Compression: zstd2057 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2058 NarSize: 1442059 References: 2060 Deriver: /build/TestClientCADerivations3827986602/001/store/x18ywqvykyy606605f127l74h8cikq9q-ca-test.drv2061 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2062 client_ca_test.go:185: Checking for realisation files in S3...2063 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2064 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20652026/10/20 08:17:46 WARN Force mode enabled - objects will be deleted immediately without grace period20662026/10/20 08:17:46 WARN Force mode enabled - objects will be deleted immediately without grace period20672026/10/20 08:17:46 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=020682026/10/20 08:17:46 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=020692026/10/20 08:17:46 INFO Vacuumed table table=pending_closures20702026/10/20 08:17:46 INFO Vacuumed table table=pending_closures20712026/10/20 08:17:46 INFO Vacuumed table table=pending_objects20722026/10/20 08:17:46 INFO Vacuumed table table=pending_objects20732026/10/20 08:17:46 INFO Vacuumed table table=multipart_uploads20742026/10/20 08:17:46 INFO Vacuumed table table=multipart_uploads20752026/10/20 08:17:46 INFO Vacuumed table table=closures20762026/10/20 08:17:46 INFO Vacuumed table table=closures20772026/10/20 08:17:46 INFO Vacuumed table table=objects20782026/10/20 08:17:46 INFO Vacuumed table table=objects2079--- PASS: TestPendingClosureWriteTimeout (0.00s)2080 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2081 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2082 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2083 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.16s)20842026/10/20 08:17:46 WARN Request failed, retrying attempt=4 backoff=722.747383ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2085--- PASS: TestUploadHandlersRejectOversizedBody (0.38s)2086 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2087 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2088 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.16s)20892026/10/20 08:17:47 INFO lead: released remote=192.0.2.1:12342090--- PASS: TestLeadElectsOneAndHandsOver (2.75s)20912026/10/20 08:17:47 WARN Request failed, retrying attempt=5 backoff=1.743332973s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2092--- PASS: TestDeleteClosuresRacingPins (4.49s)20932026/10/20 08:17:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02094=== NAME TestClientIntegration2095 client_integration_test.go:323: Objects in database after GC:2096 client_integration_test.go:323: Successfully deleted all objects with GC --force20972026/10/20 08:17:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02098--- PASS: TestClientIntegration (3.53s)20992026/10/20 08:17:48 INFO Received create pin request method=POST path=/api/pins/myapp21002026/10/20 08:17:48 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1119046147/001/store/pp57yx9l67rq3gcbpk1g8qsy3mbxqm44-pinned-file.txt narinfo_key=pp57yx9l67rq3gcbpk1g8qsy3mbxqm44.narinfo21012026/10/20 08:17:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures21022026/10/20 08:17:48 INFO Garbage collection started21032026/10/20 08:17:48 INFO Aborted multipart uploads count=0 kept=02104--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.17s)21052026/10/20 08:17:48 WARN Force mode enabled - objects will be deleted immediately without grace period21062026/10/20 08:17:48 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=021072026/10/20 08:17:48 INFO Vacuumed table table=pending_closures21082026/10/20 08:17:48 INFO Vacuumed table table=pending_objects21092026/10/20 08:17:48 INFO Vacuumed table table=multipart_uploads21102026/10/20 08:17:48 INFO Vacuumed table table=closures21112026/10/20 08:17:48 INFO Vacuumed table table=objects21122026/10/20 08:17:49 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-config21132026/10/20 08:17:49 WARN Request failed, retrying attempt=2 backoff=216.342092ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21142026/10/20 08:17:49 WARN Request failed, retrying attempt=3 backoff=395.30653ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2115=== NAME TestClientCADerivations2116 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2117 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2118 error: binary cache 's3://bucket83?endpoint=http://localhost:36679®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3827986602/001/store'2119 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12120--- PASS: TestClientCADerivations (4.75s)2121--- PASS: TestConnectWaitsForAPeerMigration (5.15s)21222026/10/20 08:17:49 WARN Request failed, retrying attempt=4 backoff=846.524692ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2123=== NAME TestPinProtectsFromGC2124 client_integration_test.go:840: Pin successfully protected closure from garbage collection2125--- PASS: TestPinProtectsFromGC (5.92s)21262026/10/20 08:17:50 WARN Request failed, retrying attempt=5 backoff=1.747449321s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21272026/10/20 08:17:50 INFO Aborted multipart uploads count=1 kept=021282026/10/20 08:17:50 INFO Received cleanup request method=DELETE path=/api/pending_closures21292026/10/20 08:17:50 INFO Aborted multipart uploads count=1 kept=02130--- PASS: TestPendingCleanupUsesOneCutoff (7.70s)21312026/10/20 08:17:50 WARN Rate limiter enabled after throttle name=s3-test rate=521322026/10/20 08:17:50 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2133=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2134 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102135 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002136--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.95s)21372026/10/20 08:17:52 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"21382026/10/20 08:17:52 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-config21392026/10/20 08:17:52 WARN Request failed, retrying attempt=2 backoff=209.20251ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/10/20 08:17:52 WARN Request failed, retrying attempt=3 backoff=390.862449ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/10/20 08:17:53 WARN Request failed, retrying attempt=4 backoff=811.562465ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21422026/10/20 08:17:53 WARN Request failed, retrying attempt=5 backoff=1.58182846s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/10/20 08:17:55 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_closures21442026/10/20 08:17:55 WARN Request failed, retrying attempt=2 backoff=185.021381ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21452026/10/20 08:17:55 WARN Request failed, retrying attempt=3 backoff=389.261315ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21462026/10/20 08:17:56 WARN Request failed, retrying attempt=4 backoff=736.557152ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21472026/10/20 08:17:56 WARN Request failed, retrying attempt=5 backoff=1.752073918s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2148--- PASS: TestClientErrorHandling (0.00s)2149 --- PASS: TestClientErrorHandling/InvalidStorePath (0.45s)2150 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.67s)2151 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.05s)2152PASS21532026-10-20 08:17:58.989 UTC [130] LOG: received smart shutdown request21542026-10-20 08:17:58.994 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 121552026-10-20 08:17:59.007 UTC [135] LOG: shutting down21562026-10-20 08:17:59.008 UTC [135] LOG: checkpoint starting: shutdown immediate21572026-10-20 08:17:59.667 UTC [135] LOG: checkpoint complete: wrote 10331 buffers (63.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.209 s, sync=0.412 s, total=0.660 s; sync files=34046, longest=0.004 s, average=0.001 s; distance=531577 kB, estimate=531577 kB; lsn=0/21E84130, redo lsn=0/21E8413021582026-10-20 08:17:59.785 UTC [130] LOG: database system is shut down2159Running OIDC tests...2160=== RUN TestAudienceForIssuer2161=== PAUSE TestAudienceForIssuer2162=== RUN TestGlobMatch2163=== PAUSE TestGlobMatch2164=== RUN TestValidateToken_ValidToken2165=== PAUSE TestValidateToken_ValidToken2166=== RUN TestValidateToken_WrongAudience2167=== PAUSE TestValidateToken_WrongAudience2168=== RUN TestValidateToken_Expired2169=== PAUSE TestValidateToken_Expired2170=== RUN TestValidateToken_BoundClaimsMismatch2171=== PAUSE TestValidateToken_BoundClaimsMismatch2172=== RUN TestValidateToken_BoundSubjectMismatch2173=== PAUSE TestValidateToken_BoundSubjectMismatch2174=== RUN TestValidateToken_MultipleProviders2175=== PAUSE TestValidateToken_MultipleProviders2176=== RUN TestValidateToken_NoMatchingProvider2177=== PAUSE TestValidateToken_NoMatchingProvider2178=== RUN TestValidateToken_KubernetesServiceAccount2179=== PAUSE TestValidateToken_KubernetesServiceAccount2180=== RUN TestNewValidator_KubernetesRequiresCA2181=== PAUSE TestNewValidator_KubernetesRequiresCA2182=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2183=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2184=== RUN TestPins_ReservedForMatchingRule2185=== PAUSE TestPins_ReservedForMatchingRule2186=== RUN TestPins_TopLevelShorthand2187=== PAUSE TestPins_TopLevelShorthand2188=== RUN TestPins_ConfigValidation2189=== PAUSE TestPins_ConfigValidation2190=== RUN TestScopes_LegacyProviderDefaultsToWrite2191=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2192=== RUN TestScopes_Rules2193=== PAUSE TestScopes_Rules2194=== RUN TestScopes_ConfigValidation2195=== PAUSE TestScopes_ConfigValidation2196=== CONT TestAudienceForIssuer2197--- PASS: TestAudienceForIssuer (0.00s)2198=== CONT TestValidateToken_NoMatchingProvider2199=== CONT TestValidateToken_KubernetesServiceAccount2200=== CONT TestPins_ConfigValidation2201=== CONT TestValidateToken_Expired2202=== CONT TestScopes_Rules2203--- PASS: TestPins_ConfigValidation (0.00s)2204=== CONT TestScopes_LegacyProviderDefaultsToWrite2205=== CONT TestValidateToken_ValidToken2206=== CONT TestGlobMatch2207=== RUN TestGlobMatch/foo_foo2208=== PAUSE TestGlobMatch/foo_foo2209=== RUN TestGlobMatch/foo_bar2210=== PAUSE TestGlobMatch/foo_bar2211=== RUN TestGlobMatch/*_2212=== PAUSE TestGlobMatch/*_2213=== RUN TestGlobMatch/*_anything2214=== PAUSE TestGlobMatch/*_anything2215=== RUN TestGlobMatch/foo*_foo2216=== PAUSE TestGlobMatch/foo*_foo2217=== RUN TestGlobMatch/foo*_foobar2218=== PAUSE TestGlobMatch/foo*_foobar2219=== RUN TestGlobMatch/foo*_bar2220=== PAUSE TestGlobMatch/foo*_bar2221=== RUN TestGlobMatch/*bar_bar2222=== PAUSE TestGlobMatch/*bar_bar2223=== RUN TestGlobMatch/*bar_foobar2224=== PAUSE TestGlobMatch/*bar_foobar2225=== RUN TestGlobMatch/*bar_foo2226=== PAUSE TestGlobMatch/*bar_foo2227=== RUN TestGlobMatch/foo*bar_foobar2228=== PAUSE TestGlobMatch/foo*bar_foobar2229=== RUN TestGlobMatch/foo*bar_foo123bar2230=== PAUSE TestGlobMatch/foo*bar_foo123bar2231=== RUN TestGlobMatch/foo*bar_foobarbaz2232=== PAUSE TestGlobMatch/foo*bar_foobarbaz2233=== RUN TestGlobMatch/*/*_foo/bar2234=== PAUSE TestGlobMatch/*/*_foo/bar2235=== RUN TestGlobMatch/*/*_foo2236=== PAUSE TestGlobMatch/*/*_foo2237=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2238=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2239=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02240=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02241=== RUN TestGlobMatch/refs/*/main_refs/heads/main2242=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2243=== RUN TestGlobMatch/fo?_foo2244=== PAUSE TestGlobMatch/fo?_foo2245=== RUN TestGlobMatch/fo?_fo2246=== PAUSE TestGlobMatch/fo?_fo2247=== RUN TestGlobMatch/fo?_fooo2248=== PAUSE TestGlobMatch/fo?_fooo2249=== RUN TestGlobMatch/?oo_foo2250=== PAUSE TestGlobMatch/?oo_foo2251=== RUN TestGlobMatch/?oo_boo2252=== PAUSE TestGlobMatch/?oo_boo2253=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2254=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2255=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2256=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2257=== CONT TestGlobMatch/foo_foo2258=== CONT TestPins_TopLevelShorthand2259=== CONT TestValidateToken_WrongAudience2260=== CONT TestScopes_ConfigValidation2261--- PASS: TestScopes_ConfigValidation (0.00s)2262=== CONT TestPins_ReservedForMatchingRule2263=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2264=== CONT TestValidateToken_MultipleProviders2265=== CONT TestNewValidator_KubernetesRequiresCA2266=== CONT TestValidateToken_BoundSubjectMismatch2267=== CONT TestValidateToken_BoundClaimsMismatch2268=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2269=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2270=== CONT TestGlobMatch/*/*_foo/bar2271=== CONT TestGlobMatch/foo*bar_foobarbaz2272=== CONT TestGlobMatch/?oo_boo2273=== CONT TestGlobMatch/foo*bar_foobar2274=== CONT TestGlobMatch/*bar_foo2275=== CONT TestGlobMatch/*bar_foobar2276=== CONT TestGlobMatch/*bar_bar2277=== CONT TestGlobMatch/foo*_bar2278=== CONT TestGlobMatch/?oo_foo2279=== CONT TestGlobMatch/foo*_foo2280=== CONT TestGlobMatch/fo?_fooo2281=== CONT TestGlobMatch/*_2282=== CONT TestGlobMatch/fo?_fo2283=== CONT TestGlobMatch/fo?_foo2284=== CONT TestGlobMatch/refs/*/main_refs/heads/main2285=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02286=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2287=== CONT TestGlobMatch/*/*_foo2288=== CONT TestGlobMatch/foo*bar_foo123bar2289=== CONT TestGlobMatch/foo_bar2290=== CONT TestGlobMatch/foo*_foobar2291=== CONT TestGlobMatch/*_anything2292--- PASS: TestGlobMatch (0.00s)2293 --- PASS: TestGlobMatch/foo_foo (0.00s)2294 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2295 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2296 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2297 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2298 --- PASS: TestGlobMatch/?oo_boo (0.00s)2299 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2300 --- PASS: TestGlobMatch/*bar_foo (0.00s)2301 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2302 --- PASS: TestGlobMatch/*bar_bar (0.00s)2303 --- PASS: TestGlobMatch/foo*_bar (0.00s)2304 --- PASS: TestGlobMatch/?oo_foo (0.00s)2305 --- PASS: TestGlobMatch/foo*_foo (0.00s)2306 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2307 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2308 --- PASS: TestGlobMatch/foo_bar (0.00s)2309 --- PASS: TestGlobMatch/fo?_fo (0.00s)2310 --- PASS: TestGlobMatch/fo?_foo (0.00s)2311 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2312 --- PASS: TestGlobMatch/*/*_foo (0.00s)2313 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2314 --- PASS: TestGlobMatch/*_anything (0.00s)2315 --- PASS: TestGlobMatch/*_ (0.00s)2316 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2317 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)23182026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40135/oidc2319--- PASS: TestValidateToken_ValidToken (1.38s)23202026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37875/oidc2321--- PASS: TestScopes_Rules (1.64s)23222026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42477/oidc23232026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40031/oidc2324--- PASS: TestValidateToken_WrongAudience (1.66s)2325--- PASS: TestPins_TopLevelShorthand (1.67s)23262026/10/20 08:18:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38443/oidc2327--- PASS: TestValidateToken_NoMatchingProvider (1.70s)23282026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38625/oidc2329--- PASS: TestValidateToken_Expired (1.70s)23302026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44199/oidc2331--- PASS: TestValidateToken_BoundClaimsMismatch (0.39s)23322026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38189/oidc23332026/10/20 08:18:03 http: TLS handshake error from 127.0.0.1:44590: remote error: tls: bad certificate2334--- PASS: TestNewValidator_KubernetesRequiresCA (1.68s)2335--- PASS: TestPins_ReservedForMatchingRule (1.70s)23362026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43299/oidc23372026/10/20 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33789/oidc2338--- PASS: TestScopes_LegacyProviderDefaultsToWrite (1.75s)2339--- PASS: TestValidateToken_BoundSubjectMismatch (0.42s)23402026/10/20 08:18:04 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232341--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (1.88s)23422026/10/20 08:18:04 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:366012343--- PASS: TestValidateToken_KubernetesServiceAccount (1.95s)23442026/10/20 08:18:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36189/oidc23452026/10/20 08:18:04 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:33723/oidc2346--- PASS: TestValidateToken_MultipleProviders (1.90s)2347PASS2348Running hook tests...2349=== RUN TestSendPathsEmpty2350=== PAUSE TestSendPathsEmpty2351=== RUN TestQueueEnqueueAndFetch2352=== PAUSE TestQueueEnqueueAndFetch2353=== RUN TestQueueDeduplication2354=== PAUSE TestQueueDeduplication2355=== RUN TestQueueRemove2356=== PAUSE TestQueueRemove2357=== RUN TestQueueFetchBatchLimit2358=== PAUSE TestQueueFetchBatchLimit2359=== RUN TestQueueRetryMovesToBack2360=== PAUSE TestQueueRetryMovesToBack2361=== RUN TestQueueFetchRemoveLifecycle2362=== PAUSE TestQueueFetchRemoveLifecycle2363=== RUN TestQueueConcurrentWriters2364=== PAUSE TestQueueConcurrentWriters2365=== RUN TestQueueRemoveLargeClosure2366=== PAUSE TestQueueRemoveLargeClosure2367=== RUN TestServerClientIntegration2368--- PASS: TestServerClientIntegration (0.00s)2369=== RUN TestServerQueueError23702026/10/20 08:18:04 ERROR Failed to queue paths error="permission denied" count=12371--- PASS: TestServerQueueError (0.00s)2372=== RUN TestGetListenerSocketActivation2373 server_test.go:219: === RUN TestGetListenerSocketActivation2374 --- PASS: TestGetListenerSocketActivation (0.00s)2375 PASS2376 2377--- PASS: TestGetListenerSocketActivation (0.04s)2378=== RUN TestDrainIsolatesPoisonPath2379=== PAUSE TestDrainIsolatesPoisonPath2380=== RUN TestRunNotBlockedByPoisonHead2381=== PAUSE TestRunNotBlockedByPoisonHead2382=== RUN TestDrainGivesUpWhenServerDown2383=== PAUSE TestDrainGivesUpWhenServerDown2384=== RUN TestFailedPathPrunedByLaterClosure2385=== PAUSE TestFailedPathPrunedByLaterClosure2386=== RUN TestWorkerUploadsAndRemoves2387=== PAUSE TestWorkerUploadsAndRemoves2388=== RUN TestWorkerSkipsGCdPaths2389=== PAUSE TestWorkerSkipsGCdPaths2390=== RUN TestWorkerPrunesClosureDeps2391=== PAUSE TestWorkerPrunesClosureDeps2392=== RUN TestDrainTimeout2393=== PAUSE TestDrainTimeout2394=== CONT TestSendPathsEmpty2395--- PASS: TestSendPathsEmpty (0.00s)2396=== CONT TestDrainTimeout2397=== CONT TestQueueRemoveLargeClosure2398=== CONT TestFailedPathPrunedByLaterClosure2399=== CONT TestRunNotBlockedByPoisonHead2400=== CONT TestDrainIsolatesPoisonPath2401=== CONT TestWorkerSkipsGCdPaths2402=== CONT TestWorkerPrunesClosureDeps2403=== CONT TestWorkerUploadsAndRemoves2404=== CONT TestQueueConcurrentWriters2405=== CONT TestQueueFetchRemoveLifecycle2406=== CONT TestDrainGivesUpWhenServerDown24072026/10/20 08:18:04 INFO Upload queue status pending=224082026/10/20 08:18:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3498932776/002/nonexistent24092026/10/20 08:18:04 INFO Uploading batch count=12410--- PASS: TestQueueFetchRemoveLifecycle (0.00s)24112026/10/20 08:18:04 INFO Upload queue status pending=224122026/10/20 08:18:04 INFO Uploading batch count=22413=== CONT TestQueueRetryMovesToBack24142026/10/20 08:18:04 INFO Uploading batch count=22415=== CONT TestQueueFetchBatchLimit2416=== CONT TestQueueRemove2417=== CONT TestQueueDeduplication24182026/10/20 08:18:04 INFO Upload queue status pending=324192026/10/20 08:18:04 INFO Uploading batch count=124202026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=124212026/10/20 08:18:04 INFO Uploading batch count=124222026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=12423=== CONT TestQueueEnqueueAndFetch2424--- PASS: TestQueueDeduplication (0.01s)24252026/10/20 08:18:04 INFO Uploading batch count=124262026/10/20 08:18:04 INFO Uploading batch count=12427--- PASS: TestQueueRetryMovesToBack (0.01s)2428--- PASS: TestQueueFetchBatchLimit (0.02s)2429--- PASS: TestWorkerUploadsAndRemoves (0.03s)2430--- PASS: TestWorkerSkipsGCdPaths (0.03s)2431--- PASS: TestFailedPathPrunedByLaterClosure (0.04s)24322026/10/20 08:18:04 INFO Uploading batch count=424332026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=424342026/10/20 08:18:04 INFO Upload queue status pending=224352026/10/20 08:18:04 INFO Uploading batch count=12436--- PASS: TestQueueEnqueueAndFetch (0.03s)24372026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3606965324/002/bbb2438--- PASS: TestQueueRemove (0.03s)24392026/10/20 08:18:04 INFO Uploading batch count=224402026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=224412026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2662842826/002/a24422026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2662842826/002/b24432026/10/20 08:18:04 INFO Uploading batch count=124442026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=124452026/10/20 08:18:04 INFO Uploading batch count=124462026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=124472026/10/20 08:18:04 INFO Uploading batch count=224482026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=224492026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2662842826/002/c24502026/10/20 08:18:04 INFO Uploading batch count=124512026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=124522026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2662842826/002/d24532026/10/20 08:18:04 ERROR Drain finished with paths left in queue remaining=124542026/10/20 08:18:04 INFO Uploading batch count=224552026/10/20 08:18:04 ERROR Upload failed error="upload failed" count=224562026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2662842826/002/e24572026/10/20 08:18:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2662842826/002/f24582026/10/20 08:18:04 ERROR Drain finished with paths left in queue remaining=102459--- PASS: TestDrainIsolatesPoisonPath (0.04s)2460--- PASS: TestDrainGivesUpWhenServerDown (0.04s)2461--- PASS: TestWorkerPrunesClosureDeps (0.06s)2462--- PASS: TestQueueRemoveLargeClosure (0.11s)24632026/10/20 08:18:04 ERROR Upload failed error="context deadline exceeded" count=224642026/10/20 08:18:04 ERROR Drain finished with paths left in queue remaining=42465--- PASS: TestDrainTimeout (0.22s)2466--- PASS: TestQueueConcurrentWriters (0.23s)24672026/10/20 08:18:05 INFO Uploading batch count=124682026/10/20 08:18:05 INFO Uploading batch count=124692026/10/20 08:18:05 INFO Uploading batch count=124702026/10/20 08:18:05 ERROR Upload failed error="upload failed" count=124712026/10/20 08:18:05 INFO Uploading batch count=124722026/10/20 08:18:05 ERROR Upload failed error="upload failed" count=124732026/10/20 08:18:05 INFO Uploading batch count=124742026/10/20 08:18:05 ERROR Upload failed error="upload failed" count=124752026/10/20 08:18:05 INFO Uploading batch count=124762026/10/20 08:18:05 ERROR Upload failed error="upload failed" count=124772026/10/20 08:18:05 ERROR Drain finished with paths left in queue remaining=12478--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2479PASS2480Running signing tests...2481=== RUN TestExternalSigner2482=== PAUSE TestExternalSigner2483=== RUN TestExternalSignerWrongPublicKey2484=== PAUSE TestExternalSignerWrongPublicKey2485=== RUN TestExternalSignerErrors2486=== PAUSE TestExternalSignerErrors2487=== RUN TestExternalSignerRestartsAfterCrash2488=== PAUSE TestExternalSignerRestartsAfterCrash2489=== RUN TestExternalSignerProgramErrorKeepsProcess2490=== PAUSE TestExternalSignerProgramErrorKeepsProcess2491=== RUN TestExternalSignerClose2492=== PAUSE TestExternalSignerClose2493=== RUN TestExternalSignerRejectsInvalidPublicKey2494=== PAUSE TestExternalSignerRejectsInvalidPublicKey2495=== RUN TestExternalSignerCancellation2496=== PAUSE TestExternalSignerCancellation2497=== RUN TestGenerateFingerprint2498=== PAUSE TestGenerateFingerprint2499=== RUN TestParseSigningKey2500=== PAUSE TestParseSigningKey2501=== RUN TestSign2502=== PAUSE TestSign2503=== RUN TestSignBatch2504=== PAUSE TestSignBatch2505=== RUN TestNilKeyPublicKey2506=== PAUSE TestNilKeyPublicKey2507=== RUN TestSignErrors2508=== PAUSE TestSignErrors2509=== CONT TestExternalSigner2510=== CONT TestExternalSignerCancellation2511=== CONT TestGenerateFingerprint2512=== RUN TestGenerateFingerprint/basic_with_references2513=== PAUSE TestGenerateFingerprint/basic_with_references2514=== CONT TestSignBatch2515=== CONT TestParseSigningKey2516=== RUN TestGenerateFingerprint/no_references2517=== PAUSE TestGenerateFingerprint/no_references2518=== CONT TestSignErrors2519=== CONT TestSign2520=== CONT TestNilKeyPublicKey2521--- PASS: TestNilKeyPublicKey (0.00s)2522=== CONT TestExternalSignerProgramErrorKeepsProcess2523=== CONT TestExternalSignerRejectsInvalidPublicKey2524=== CONT TestExternalSignerClose2525=== CONT TestExternalSignerErrors2526=== RUN TestExternalSignerErrors/exit_at_startup2527=== PAUSE TestExternalSignerErrors/exit_at_startup2528=== RUN TestExternalSignerErrors/wrong_shape2529=== CONT TestExternalSignerRestartsAfterCrash2530=== CONT TestExternalSignerWrongPublicKey2531=== RUN TestParseSigningKey/valid_32-byte_key2532=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2533=== PAUSE TestParseSigningKey/valid_32-byte_key2534=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2535=== PAUSE TestExternalSignerErrors/wrong_shape2536=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2537=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2538=== RUN TestGenerateFingerprint/invalid_nar_hash_length2539=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2540=== RUN TestGenerateFingerprint/invalid_store_path_prefix2541=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2542=== RUN TestGenerateFingerprint/invalid_reference_prefix2543=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2544=== CONT TestGenerateFingerprint/basic_with_references2545=== CONT TestGenerateFingerprint/invalid_nar_hash_length2546=== CONT TestGenerateFingerprint/invalid_reference_prefix2547=== CONT TestGenerateFingerprint/invalid_store_path_prefix2548=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2549=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2550=== RUN TestExternalSignerErrors/missing_signatures2551=== PAUSE TestExternalSignerErrors/missing_signatures2552=== RUN TestExternalSignerErrors/null_signatures2553=== PAUSE TestExternalSignerErrors/null_signatures2554=== RUN TestExternalSignerErrors/wrong_signatures_shape2555=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2556=== RUN TestExternalSignerErrors/too_few_signatures2557=== PAUSE TestExternalSignerErrors/too_few_signatures2558=== RUN TestExternalSignerErrors/invalid_JSON2559=== PAUSE TestExternalSignerErrors/invalid_JSON2560=== RUN TestExternalSignerErrors/unrequested_key2561=== PAUSE TestExternalSignerErrors/unrequested_key2562=== RUN TestExternalSignerErrors/invalid_signature_base642563=== PAUSE TestExternalSignerErrors/invalid_signature_base642564=== RUN TestExternalSignerErrors/exit_on_request2565=== PAUSE TestExternalSignerErrors/exit_on_request2566=== RUN TestExternalSignerErrors/null2567=== PAUSE TestExternalSignerErrors/null2568=== RUN TestExternalSignerErrors/wrong_id2569=== PAUSE TestExternalSignerErrors/wrong_id2570=== RUN TestExternalSignerErrors/missing_signature_name2571=== PAUSE TestExternalSignerErrors/missing_signature_name2572=== RUN TestExternalSignerErrors/wrong_signature_name2573=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2574=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2575=== RUN TestParseSigningKey/no_colon2576=== RUN TestSignErrors/nil_key2577=== PAUSE TestParseSigningKey/no_colon2578=== CONT TestGenerateFingerprint/no_references2579=== PAUSE TestExternalSignerErrors/wrong_signature_name2580=== RUN TestExternalSignerRejectsInvalidPublicKey/#002581=== RUN TestExternalSignerErrors/wrong_signature_length2582=== PAUSE TestExternalSignerErrors/wrong_signature_length2583=== PAUSE TestSignErrors/nil_key2584=== RUN TestSignErrors/nil_narinfo2585=== PAUSE TestSignErrors/nil_narinfo2586=== RUN TestSignErrors/invalid_narinfo2587=== RUN TestParseSigningKey/empty_name2588--- PASS: TestSign (0.00s)2589--- PASS: TestGenerateFingerprint (0.00s)2590 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2591 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2592 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2593 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2594 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2595 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2596 --- PASS: TestGenerateFingerprint/no_references (0.00s)2597=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002598=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2599=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2600=== RUN TestExternalSignerErrors/program_error2601--- PASS: TestSignBatch (0.00s)2602=== PAUSE TestSignErrors/invalid_narinfo2603=== PAUSE TestParseSigningKey/empty_name2604=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2605=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2606=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2607=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2608=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2609=== PAUSE TestExternalSignerErrors/program_error2610=== RUN TestParseSigningKey/invalid_base642611=== CONT TestExternalSignerErrors/missing_signatures2612=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2613=== CONT TestExternalSignerErrors/exit_at_startup2614=== CONT TestExternalSignerErrors/program_error2615=== CONT TestExternalSignerErrors/wrong_signature_length2616=== CONT TestExternalSignerErrors/wrong_signature_name2617=== CONT TestExternalSignerErrors/missing_signature_name2618=== CONT TestExternalSignerErrors/too_few_signatures2619=== CONT TestExternalSignerErrors/wrong_signatures_shape2620=== CONT TestExternalSignerErrors/null_signatures2621=== CONT TestExternalSignerErrors/invalid_JSON2622=== CONT TestExternalSignerErrors/wrong_id2623=== CONT TestExternalSignerErrors/null2624=== CONT TestExternalSignerErrors/exit_on_request2625=== CONT TestExternalSignerErrors/invalid_signature_base642626=== PAUSE TestParseSigningKey/invalid_base642627=== RUN TestParseSigningKey/wrong_length2628=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2629=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2630=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2631=== PAUSE TestParseSigningKey/wrong_length2632=== CONT TestParseSigningKey/wrong_length2633=== CONT TestParseSigningKey/invalid_base642634=== CONT TestParseSigningKey/valid_32-byte_key2635=== CONT TestExternalSignerErrors/wrong_shape2636--- PASS: TestExternalSignerWrongPublicKey (0.00s)2637--- PASS: TestExternalSignerClose (0.01s)2638--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2639=== CONT TestExternalSignerRejectsInvalidPublicKey/#002640=== CONT TestExternalSignerErrors/unrequested_key2641=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2642--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2643 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2644 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2645 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2646 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2647 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2648=== RUN TestSignErrors/canceled2649=== CONT TestParseSigningKey/empty_name2650=== PAUSE TestSignErrors/canceled2651=== CONT TestSignErrors/nil_key2652=== CONT TestParseSigningKey/no_colon2653=== CONT TestSignErrors/invalid_narinfo2654=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2655--- PASS: TestParseSigningKey (0.01s)2656 --- PASS: TestParseSigningKey/wrong_length (0.00s)2657 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2658 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2659 --- PASS: TestParseSigningKey/empty_name (0.00s)2660 --- PASS: TestParseSigningKey/no_colon (0.00s)2661 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2662=== CONT TestSignErrors/canceled2663=== CONT TestSignErrors/nil_narinfo2664--- PASS: TestSignErrors (0.01s)2665 --- PASS: TestSignErrors/nil_key (0.00s)2666 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2667 --- PASS: TestSignErrors/canceled (0.00s)2668 --- PASS: TestSignErrors/nil_narinfo (0.00s)2669--- PASS: TestExternalSigner (0.01s)2670--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2671--- PASS: TestExternalSignerErrors (0.00s)2672 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2673 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2674 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2675 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2676 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2677 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2678 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2679 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2680 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2681 --- PASS: TestExternalSignerErrors/program_error (0.01s)2682 --- PASS: TestExternalSignerErrors/null (0.01s)2683 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2684 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2685 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2686 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2687 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2688--- PASS: TestExternalSignerCancellation (0.02s)2689PASS2690Running OpenBao signer tests...2691=== RUN TestSign2692=== PAUSE TestSign2693=== RUN TestSignErrors2694=== PAUSE TestSignErrors2695=== RUN TestServe2696=== PAUSE TestServe2697=== RUN TestServeRejectsGarbage2698=== PAUSE TestServeRejectsGarbage2699=== CONT TestSign2700=== CONT TestServe2701=== CONT TestServeRejectsGarbage2702=== CONT TestSignErrors2703=== RUN TestSignErrors/invalid_base642704=== PAUSE TestSignErrors/invalid_base642705=== RUN TestSignErrors/http_error2706=== PAUSE TestSignErrors/http_error2707=== RUN TestSignErrors/invalid_json2708=== PAUSE TestSignErrors/invalid_json2709=== RUN TestSignErrors/no_prefix2710=== PAUSE TestSignErrors/no_prefix2711=== CONT TestSignErrors/invalid_base642712--- PASS: TestServeRejectsGarbage (0.00s)2713=== CONT TestSignErrors/no_prefix2714=== CONT TestSignErrors/invalid_json2715=== CONT TestSignErrors/http_error2716--- PASS: TestServe (0.00s)2717--- PASS: TestSign (0.01s)2718--- PASS: TestSignErrors (0.00s)2719 --- PASS: TestSignErrors/no_prefix (0.01s)2720 --- PASS: TestSignErrors/invalid_json (0.01s)2721 --- PASS: TestSignErrors/invalid_base64 (0.01s)2722 --- PASS: TestSignErrors/http_error (0.01s)2723PASS