niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #418
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestPartSizeForNAR20=== PAUSE TestPartSizeForNAR21=== RUN TestUploadMultipart_SupersededByPeer22=== PAUSE TestUploadMultipart_SupersededByPeer23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)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 TestSetClientTLSDoesNotMutateDefaultTransport115=== CONT TestStreamPushGivesUpOnDeadServer116=== CONT TestDoWithRetry_FinalResponseBodyReadable117=== CONT TestStreamPushIsolatesFailures118=== CONT TestRetryTimeoutOutlastsMaxRetries119=== CONT TestScriptTokenNoExpiryRerunsEveryCall120=== CONT TestStreamPushBatchesUnderLoad121=== CONT TestStreamPushReportsEveryPath122=== CONT TestShellSplitErrors123--- PASS: TestShellSplitErrors (0.00s)124=== CONT TestShellSplit125=== CONT TestFileTokenReadsAndCaches126=== CONT TestDoWithRetry_BodyReplayedViaGetBody1272026/10/20 08:16:05 ERROR Upload failed error="bad path" count=31282026/10/20 08:16:05 ERROR Upload failed error="connection refused" count=201292026/10/20 08:16:05 ERROR Server seems unavailable, giving up on batch untried=17130=== CONT TestFileTokenEmpty131=== CONT TestSupersededNARStillUploadsListing132=== CONT TestSetClientTLS133=== CONT TestStreamPushStopsWhenCanceled134=== CONT TestClientSignaturesByStorePath135=== CONT TestStreamPushReportsSkippedPaths136=== CONT TestStreamPushReportsSignatures137=== CONT TestStreamPushRequestLine138=== CONT TestResolveStorePath139=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer140=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess141=== CONT TestRateLimiterFeedback142--- PASS: TestShellSplit (0.00s)143=== CONT TestFileTokenMissing144=== CONT TestPathInfoCACompatibility145=== RUN TestSupersededNARStillUploadsListing/small_NAR146=== CONT TestParsePathInfoJSON147=== RUN TestParsePathInfoJSON/Nix_format148=== PAUSE TestParsePathInfoJSON/Nix_format149=== RUN TestParsePathInfoJSON/Lix_format150=== PAUSE TestParsePathInfoJSON/Lix_format151=== RUN TestParsePathInfoJSON/empty_input152=== PAUSE TestParsePathInfoJSON/empty_input153=== RUN TestParsePathInfoJSON/whitespace_only154=== PAUSE TestParsePathInfoJSON/whitespace_only1552026/10/20 08:16:05 WARN Rate limiter enabled after throttle name=server-test rate=5156=== CONT TestPathInfoHashCompatibility157=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)159=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon160=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon161=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI162=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI163=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512164=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512165=== CONT TestGetStorePathHash166=== RUN TestGetStorePathHash/valid_store_path167=== PAUSE TestGetStorePathHash/valid_store_path168=== RUN TestGetStorePathHash/basename_without_hyphen_should_error169=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error170=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error171=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error172=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error173=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error174=== CONT TestConvertHashToNix32175=== RUN TestConvertHashToNix32/SRI_format_to_Nix32176=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32177=== RUN TestConvertHashToNix32/already_Nix32_format178=== PAUSE TestConvertHashToNix32/already_Nix32_format179=== RUN TestConvertHashToNix32/invalid_format180=== PAUSE TestConvertHashToNix32/invalid_format181=== CONT TestEncodeNixBase32WithRealHash182=== CONT TestEncodeNixBase32183=== RUN TestEncodeNixBase32/test_string_hash184=== PAUSE TestEncodeNixBase32/test_string_hash185=== RUN TestEncodeNixBase32/empty_input186=== PAUSE TestEncodeNixBase32/empty_input187=== CONT TestDumpPathWriterError188=== RUN TestParsePathInfoJSON/invalid_JSON189=== PAUSE TestParsePathInfoJSON/invalid_JSON190=== CONT TestParsePathInfoJSONMultiplePaths191=== PAUSE TestSupersededNARStillUploadsListing/small_NAR192--- PASS: TestFileTokenReadsAndCaches (0.00s)193--- PASS: TestClientSignaturesByStorePath (0.00s)194--- PASS: TestStreamPushStopsWhenCanceled (0.00s)195--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)196--- PASS: TestEncodeNixBase32WithRealHash (0.00s)197=== CONT TestDumpPathSingleFile198--- PASS: TestStreamPushReportsEveryPath (0.01s)199--- PASS: TestStreamPushIsolatesFailures (0.01s)200--- PASS: TestFileTokenEmpty (0.01s)201=== CONT TestDumpPathMatchesNix202=== CONT TestScriptTokenBadJSON2032026/10/20 08:16:05 ERROR Upload failed error=boom count=1204--- PASS: TestStreamPushReportsSignatures (0.01s)205=== CONT TestScriptTokenEmptyCommand206=== CONT TestSetClientTLSErrors207--- PASS: TestStreamPushReportsSkippedPaths (0.00s)208--- PASS: TestScriptTokenEmptyCommand (0.00s)209=== CONT TestScriptTokenScriptFails210=== RUN TestRateLimiterFeedback/429_enables_limiter211=== CONT TestStaticToken212--- PASS: TestStaticToken (0.00s)213=== CONT TestScriptTokenEmptyToken214=== PAUSE TestRateLimiterFeedback/429_enables_limiter215--- PASS: TestResolveStorePath (0.01s)216--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)2172026/10/20 08:16:05 WARN Rate limiter enabled after throttle name=server-test rate=52182026/10/20 08:16:05 WARN Rate limiter enabled after throttle name=server-test rate=5219=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2202026/10/20 08:16:05 ERROR Upload failed error=boom count=1221=== RUN TestSupersededNARStillUploadsListing/dump_cut_short2222026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:390272232026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35039224=== RUN TestRateLimiterFeedback/503_enables_limiter225=== PAUSE TestRateLimiterFeedback/503_enables_limiter226--- PASS: TestScriptTokenBadJSON (0.00s)227=== CONT TestPartSizeForNAR228--- PASS: TestFileTokenMissing (0.01s)229=== RUN TestSetClientTLSErrors/missing_cert_file230=== PAUSE TestSetClientTLSErrors/missing_cert_file231=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths232=== RUN TestSetClientTLSErrors/missing_key_file233=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths234=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths235=== CONT TestFilterOversizedClosures236=== RUN TestFilterOversizedClosures/no_limit_keeps_everything237=== PAUSE TestSetClientTLSErrors/missing_key_file238--- PASS: TestScriptTokenScriptFails (0.00s)239--- PASS: TestScriptTokenEmptyToken (0.00s)240=== CONT TestUploadMultipart_PartsInParallel241=== CONT TestCaseHackSuffix242=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter243=== CONT TestUploadMultipart_SupersededByPeer244=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter245=== CONT TestRegisterUploadedObjectReusesConnections246=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun247=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything248=== RUN TestSetClientTLSErrors/missing_ca_file249=== RUN TestPartSizeForNAR/zero_stays_at_minimum250=== RUN TestUploadMultipart_SupersededByPeer/exists251=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter252=== RUN TestPathInfoCACompatibility/null_ca_field2532026/10/20 08:16:05 WARN Rate limiter backed off name=server-test rate=5254--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)2552026/10/20 08:16:05 WARN Rate limiter backed off name=server-test rate=5256=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2572026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:39027258=== PAUSE TestPathInfoCACompatibility/null_ca_field259=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short260=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped261=== PAUSE TestSetClientTLSErrors/missing_ca_file262=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum263=== RUN TestPartSizeForNAR/small_stays_at_minimum264=== PAUSE TestPartSizeForNAR/small_stays_at_minimum265=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum266=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum267=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts268=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts2692026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33083270=== PAUSE TestUploadMultipart_SupersededByPeer/exists271=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter272=== RUN TestPathInfoCACompatibility/old_string_format_-_text273=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails274=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped275--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)276=== RUN TestPartSizeForNAR/1_TiB277=== RUN TestFilterOversizedClosures/all_closures_skipped278=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails279=== PAUSE TestPartSizeForNAR/1_TiB280=== RUN TestPartSizeForNAR/5_TiB_S3_max_object281=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object282=== RUN TestPartSizeForNAR/capped_at_5_GiB283=== PAUSE TestPartSizeForNAR/capped_at_5_GiB284=== PAUSE TestFilterOversizedClosures/all_closures_skipped285=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry286=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512287--- PASS: TestDoServerRequestAttachesToken (0.05s)288=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI289=== RUN TestSetClientTLS/rejects_connection_without_client_cert290=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon291=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error292=== CONT TestConvertHashToNix32/SRI_format_to_Nix32293=== CONT TestEncodeNixBase32/test_string_hash294=== CONT TestConvertHashToNix32/invalid_format295=== RUN TestUploadMultipart_SupersededByPeer/missing296=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)297=== RUN TestSetClientTLSErrors/invalid_ca_file298=== PAUSE TestSetClientTLSErrors/invalid_ca_file299=== CONT TestGetStorePathHash/valid_store_path300=== CONT TestParsePathInfoJSON/invalid_JSON301=== CONT TestParsePathInfoJSON/whitespace_only302=== CONT TestParsePathInfoJSON/Lix_format303=== CONT TestParsePathInfoJSON/empty_input304=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths305=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error306=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths307=== CONT TestRateLimiterFeedback/429_enables_limiter308=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter309=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert310=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA311=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA312=== RUN TestSetClientTLS/preserves_debug_logging_transport313=== PAUSE TestSetClientTLS/preserves_debug_logging_transport314=== CONT TestGetStorePathHash/basename_without_hyphen_should_error315=== CONT TestRateLimiterFeedback/503_enables_limiter3162026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33083317=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter318=== CONT TestConvertHashToNix32/already_Nix32_format319=== CONT TestScriptTokenCachesUntilRefresh3202026/10/20 08:16:05 INFO Garbage collection started321=== PAUSE TestUploadMultipart_SupersededByPeer/missing322=== CONT TestParsePathInfoJSON/Nix_format3232026/10/20 08:16:05 WARN Rate limiter enabled after throttle name=server-test rate=53242026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:369313252026/10/20 08:16:05 INFO Garbage collection started326=== CONT TestSupersededNARStillUploadsListing/dump_cut_short327=== CONT TestPartSizeForNAR/zero_stays_at_minimum328=== CONT TestPartSizeForNAR/capped_at_5_GiB329=== CONT TestPartSizeForNAR/5_TiB_S3_max_object330=== CONT TestPartSizeForNAR/1_TiB3312026/10/20 08:16:05 WARN Rate limiter enabled after throttle name=server-test rate=5332=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts3332026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:36025334=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum335=== CONT TestPartSizeForNAR/small_stays_at_minimum336=== CONT TestFilterOversizedClosures/no_limit_keeps_everything337=== CONT TestFilterOversizedClosures/all_closures_skipped3382026/10/20 08:16:05 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=50339=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text3402026/10/20 08:16:05 WARN Rate limiter backed off name=server-test rate=5341=== CONT TestSupersededNARStillUploadsListing/small_NAR3422026/10/20 08:16:05 WARN Rate limiter backed off name=server-test rate=5343=== CONT TestEncodeNixBase32/empty_input344=== CONT TestSetClientTLSErrors/invalid_ca_file345=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails346--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)347=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped348--- PASS: TestPathInfoHashCompatibility (0.00s)349 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)350 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)351 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)352 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)3532026/10/20 08:16:05 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=2000354=== CONT TestSetClientTLSErrors/missing_cert_file3552026/10/20 08:16:05 INFO Uploading abc-hello (1.0GB)356=== CONT TestSetClientTLSErrors/missing_ca_file3572026/10/20 08:16:05 INFO Uploading abc-hello (1.0GB)358--- PASS: TestEncodeNixBase32 (0.00s)359 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)360 --- PASS: TestEncodeNixBase32/empty_input (0.00s)361--- PASS: TestConvertHashToNix32 (0.00s)362 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)363 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)364 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)365=== CONT TestSetClientTLSErrors/missing_key_file366=== CONT TestSetClientTLS/rejects_connection_without_client_cert367--- PASS: TestGetStorePathHash (0.00s)368 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)369 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)370 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)371 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)372--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)373 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)374 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)375--- PASS: TestPartSizeForNAR (0.03s)376 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)377 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)378 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)379 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)380 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)381 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)382 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)383--- PASS: TestParsePathInfoJSON (0.00s)384 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)385 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)386 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)387 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)388 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)389=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA390=== CONT TestSetClientTLS/preserves_debug_logging_transport391--- PASS: TestSetClientTLSErrors (0.03s)392 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)393 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)394 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)395 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)396--- PASS: TestFilterOversizedClosures (0.03s)397 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)398 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)399 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.13s)4002026/10/20 08:16:05 WARN Rate limiter enabled after throttle name=s3-test rate=5401--- PASS: TestDumpPathSingleFile (0.17s)4022026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:45323403=== CONT TestUploadMultipart_SupersededByPeer/exists404=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive405=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive406=== RUN TestPathInfoCACompatibility/new_structured_format_-_text407=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text408=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method409=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method410=== CONT TestPathInfoCACompatibility/null_ca_field411=== CONT TestUploadMultipart_SupersededByPeer/missing412--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.13s)413=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive414=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method415=== CONT TestPathInfoCACompatibility/new_structured_format_-_text416--- PASS: TestRateLimiterFeedback (0.04s)417 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)419 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.13s)420 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)421=== CONT TestPathInfoCACompatibility/old_string_format_-_text422--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.16s)423--- PASS: TestPathInfoCACompatibility (0.17s)424 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)425 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)426 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)427 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)428 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)4292026/10/20 08:16:05 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=04302026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33083431--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)432 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)433 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)4342026/10/20 08:16:05 WARN Garbage collection finished on another replica. Its statistics are not available here4352026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33083436--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.16s)437--- PASS: TestScriptTokenCachesUntilRefresh (0.14s)4382026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:33083439--- PASS: TestCaseHackSuffix (0.17s)4402026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:330834412026/10/20 08:16:05 http: TLS handshake error from 127.0.0.1:38446: remote error: tls: bad certificate4422026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:33083443--- PASS: TestSetClientTLS (0.04s)444 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.13s)445 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.13s)446 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.13s)4472026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:330834482026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:330834492026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:33083450--- PASS: TestStreamPushRequestLine (0.19s)4512026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:330834522026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:330834532026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:330834542026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:330834552026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:330834562026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:330834572026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:33083458--- PASS: TestRegisterUploadedObjectReusesConnections (0.19s)4592026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:330834602026/10/20 08:16:05 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:33083461--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.21s)4622026/10/20 08:16:05 INFO Uploading abc-hello (1.0GB)463--- PASS: TestDumpPathWriterError (0.21s)464--- PASS: TestStreamPushBatchesUnderLoad (0.23s)465--- PASS: TestDumpPathMatchesNix (0.23s)4662026/10/20 08:16:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:45395/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:45395/part/24672026/10/20 08:16:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:45395/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:45395/part/34682026/10/20 08:16:05 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"469--- PASS: TestSupersededNARStillUploadsListing (0.04s)470 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.13s)471 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.13s)472 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.69s)473--- PASS: TestUploadMultipart_PartsInParallel (0.77s)474--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4752026/10/20 08:16:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:40793/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:40793/api/uploads/complete4762026/10/20 08:16:06 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4772026/10/20 08:16:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:40793/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:40793/api/uploads/complete4782026/10/20 08:16:06 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4792026/10/20 08:16:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:40793/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:40793/api/uploads/complete4802026/10/20 08:16:06 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"481--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)482PASS483Running server tests...484The files belonging to this database system will be owned by user "nixbld".485This user must also own the server process.486487The database cluster will be initialized with locale "C".488The default database encoding has accordingly been set to "SQL_ASCII".489The default text search configuration will be set to "english".490491Data page checksums are enabled.492493creating directory /build/postgres943969298/data ... ok494creating subdirectories ... ok495selecting dynamic shared memory implementation ... posix496selecting default "max_connections" ... 100497selecting default "shared_buffers" ... 128MB498selecting default time zone ... UTC499creating configuration files ... ok500running bootstrap script ... ok501performing post-bootstrap initialization ... ok502syncing data to disk ... ok503504initdb: warning: enabling "trust" authentication for local connections505initdb: 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.506507Success. You can now start the database server using:508509 pg_ctl -D /build/postgres943969298/data -l logfile start510511/build/postgres943969298:5432 - no response5122026-10-20 08:16:07.144 UTC [130] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5132026-10-20 08:16:07.144 UTC [130] LOG: listening on Unix socket "/build/postgres943969298/.s.PGSQL.5432"5142026-10-20 08:16:07.149 UTC [137] LOG: database system was shut down at 2026-10-20 08:16:06 UTC5152026-10-20 08:16:07.153 UTC [130] LOG: database system is ready to accept connections516/build/postgres943969298:5432 - accepting connections517=== RUN TestService_AuthMiddleware518=== PAUSE TestService_AuthMiddleware519=== RUN TestService_AuthMiddleware_MTLSProxyHeader520=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader521=== RUN TestService_AuthMiddleware_MTLSBoundSubjects522=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects523=== RUN TestService_ReadAuthMiddleware524=== PAUSE TestService_ReadAuthMiddleware525=== RUN TestService_AuthMiddleware_OIDC526=== PAUSE TestService_AuthMiddleware_OIDC527=== RUN TestService_RequireScope_OIDC528=== PAUSE TestService_RequireScope_OIDC529=== RUN TestService_ReadScope_PublicByDefault530=== PAUSE TestService_ReadScope_PublicByDefault531=== RUN TestCacheConfigHandler532=== PAUSE TestCacheConfigHandler533=== RUN TestCacheStatsHandler534=== PAUSE TestCacheStatsHandler535=== RUN TestClientCADerivations536=== PAUSE TestClientCADerivations537=== RUN TestClientErrorHandling538=== PAUSE TestClientErrorHandling539=== RUN TestClientIntegration540=== PAUSE TestClientIntegration541=== RUN TestClientMultipleUploads542=== PAUSE TestClientMultipleUploads543=== RUN TestClientWithDependencies544=== PAUSE TestClientWithDependencies545=== RUN TestClientSharedPathCommittedMidPush546=== PAUSE TestClientSharedPathCommittedMidPush547=== RUN TestPinProtectsFromGC548=== PAUSE TestPinProtectsFromGC549=== RUN TestClientPushesUseOnePush550=== PAUSE TestClientPushesUseOnePush551=== RUN TestClientFallsBackToClosures552=== PAUSE TestClientFallsBackToClosures553=== RUN TestDeleteClosuresRacingPins554=== PAUSE TestDeleteClosuresRacingPins555=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock557=== RUN TestResolveDBConnectionString558=== PAUSE TestResolveDBConnectionString559=== RUN TestConnectWaitsForAPeerMigration560=== PAUSE TestConnectWaitsForAPeerMigration561=== RUN TestLeadElectsOneAndHandsOver562=== PAUSE TestLeadElectsOneAndHandsOver563=== RUN TestLeadIncumbentWinsAfterRestart5642026/10/20 08:16:07 INFO lead: acquired remote=192.0.2.1:12345652026/10/20 08:16:08 INFO lead: released remote=192.0.2.1:12345662026/10/20 08:16:08 INFO lead: acquired remote=192.0.2.1:12345672026/10/20 08:16:09 INFO lead: released remote=192.0.2.1:1234568--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)569=== RUN TestLeadIncumbentAnnouncesAtOnce570=== PAUSE TestLeadIncumbentAnnouncesAtOnce571=== RUN TestLeadEndsOnShutdown572=== PAUSE TestLeadEndsOnShutdown573=== RUN TestLeadEndsWhenItsConnectionHangs5742026/10/20 08:16:09 INFO lead: acquired remote=192.0.2.1:12345752026-10-20 08:16:10.953 UTC [578] FATAL: terminating connection due to administrator command5762026/10/20 08:16:11 INFO lead: acquired remote=192.0.2.1:12345772026/10/20 08:16:12 WARN lead: lock connection lost error="timeout: context deadline exceeded"5782026/10/20 08:16:12 INFO lead: released remote=192.0.2.1:12345792026/10/20 08:16:12 INFO lead: released remote=192.0.2.1:1234580--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)581=== RUN TestGCAdvisoryLockBlocksConcurrentRun582=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun583=== RUN TestGCBugBareHashReferences584=== PAUSE TestGCBugBareHashReferences585=== RUN TestGCMetrics586=== PAUSE TestGCMetrics587=== RUN TestPushDedupSurvivesConcurrentGC588=== PAUSE TestPushDedupSurvivesConcurrentGC589=== RUN TestDeduplicatedObjectsRecordedAsPending590=== PAUSE TestDeduplicatedObjectsRecordedAsPending591=== RUN TestGCSweepSkipsPendingObjects592=== PAUSE TestGCSweepSkipsPendingObjects593=== RUN TestTombstonedObjectOfferedWithoutWaiting594=== PAUSE TestTombstonedObjectOfferedWithoutWaiting595=== RUN TestGCSweepDeliversEachKeyOnce596=== PAUSE TestGCSweepDeliversEachKeyOnce597=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection599=== RUN TestForceGCDuringPushOffersSweptObject600=== PAUSE TestForceGCDuringPushOffersSweptObject601=== RUN TestFailedS3DeleteKeepsTombstone602=== PAUSE TestFailedS3DeleteKeepsTombstone603=== RUN TestSweepSkipsRowsLockedByPush604=== PAUSE TestSweepSkipsRowsLockedByPush605=== RUN TestRegisterCompletedObjectNeedsPendingRow606=== PAUSE TestRegisterCompletedObjectNeedsPendingRow607=== RUN TestGetExistingObjectsLocksRows608=== PAUSE TestGetExistingObjectsLocksRows609=== RUN TestSweepRechecksPendingAfterLocking610=== PAUSE TestSweepRechecksPendingAfterLocking611=== RUN TestPushWaitsForSweepHoldingRow612=== PAUSE TestPushWaitsForSweepHoldingRow613=== RUN TestCommitRacingPendingCleanupKeepsObjects614=== PAUSE TestCommitRacingPendingCleanupKeepsObjects615=== RUN TestGCEndsOnShutdown616=== PAUSE TestGCEndsOnShutdown617=== RUN TestGCTaskStore_StartNew618=== PAUSE TestGCTaskStore_StartNew619=== RUN TestGCTaskStore_DeduplicateSameParams620=== PAUSE TestGCTaskStore_DeduplicateSameParams621=== RUN TestGCTaskStore_ConflictDifferentParams622=== PAUSE TestGCTaskStore_ConflictDifferentParams623=== RUN TestGCTaskStore_GetEmpty624=== PAUSE TestGCTaskStore_GetEmpty625=== RUN TestGCTaskStore_GetReturnsLatest626=== PAUSE TestGCTaskStore_GetReturnsLatest627=== RUN TestGCTaskStore_CompletedAllowsNewTask628=== PAUSE TestGCTaskStore_CompletedAllowsNewTask629=== RUN TestGCTaskStore_PhaseUpdates630=== PAUSE TestGCTaskStore_PhaseUpdates631=== RUN TestGCTaskStore_Fail632=== PAUSE TestGCTaskStore_Fail633=== RUN TestGracefulShutdownDrainsInflight634=== PAUSE TestGracefulShutdownDrainsInflight635=== RUN TestService_healthCheckHandler636=== PAUSE TestService_healthCheckHandler637=== RUN TestService_readinessHandler638=== PAUSE TestService_readinessHandler639=== RUN TestGenerateLandingPage640=== PAUSE TestGenerateLandingPage641=== RUN TestCacheConfigHandlerMaxNarSize642=== PAUSE TestCacheConfigHandlerMaxNarSize643=== RUN TestCreatePendingClosureRejectsOversizedNAR644=== PAUSE TestCreatePendingClosureRejectsOversizedNAR645=== RUN TestNARDeduplicationMetadataUploadBug646=== PAUSE TestNARDeduplicationMetadataUploadBug647=== RUN TestMetricsInventory648=== PAUSE TestMetricsInventory649=== RUN TestMetricsCommit650=== PAUSE TestMetricsCommit651=== RUN TestService_NativeMTLS652=== PAUSE TestService_NativeMTLS653=== RUN TestServerTLSConfig654=== PAUSE TestServerTLSConfig655=== RUN TestMultipartCleanup656=== PAUSE TestMultipartCleanup657=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded659=== RUN TestPendingCleanupUsesOneCutoff660=== PAUSE TestPendingCleanupUsesOneCutoff661=== RUN TestObjectStatsTrigger662=== PAUSE TestObjectStatsTrigger663=== RUN TestObjectStatsLargeCommit664=== PAUSE TestObjectStatsLargeCommit665=== RUN TestOrphanedObjectsGC666=== PAUSE TestOrphanedObjectsGC667=== RUN TestOrphanedObjectsGCStressTest668=== PAUSE TestOrphanedObjectsGCStressTest669=== RUN TestCreatePin_ReservedPins670=== PAUSE TestCreatePin_ReservedPins671=== RUN TestPresentReportsOnlyClosureRoots672=== PAUSE TestPresentReportsOnlyClosureRoots673=== RUN TestPresentRefreshesOnlyStaleClosures674=== PAUSE TestPresentRefreshesOnlyStaleClosures675=== RUN TestPresentNotReportedWhileGCDeletesClosure676=== PAUSE TestPresentNotReportedWhileGCDeletesClosure677=== RUN TestParseSingleRange678=== PAUSE TestParseSingleRange679=== RUN TestProxyHeadersOnlyTrustedOnSocket6802026/10/20 08:16:12 INFO Starting HTTP server address=proxy.sock6812026/10/20 08:16:12 INFO Starting HTTP server address=127.0.0.1:429296822026/10/20 08:16:12 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6832026/10/20 08:16:12 INFO Shutdown signal received, draining in-flight requests timeout=10s684--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)685=== RUN TestIsValidCachePath686=== PAUSE TestIsValidCachePath687=== RUN TestReadProxyNarinfo688=== PAUSE TestReadProxyNarinfo689=== RUN TestReadProxyNarinfoAlreadyDecompressed690=== PAUSE TestReadProxyNarinfoAlreadyDecompressed691=== RUN TestReadProxyContentNegotiation692=== PAUSE TestReadProxyContentNegotiation693=== RUN TestReadProxyNarStreaming694=== PAUSE TestReadProxyNarStreaming695=== RUN TestReadProxy404696=== PAUSE TestReadProxy404697=== RUN TestReadProxyInvalidPath698=== PAUSE TestReadProxyInvalidPath699=== RUN TestReadProxyHead700=== PAUSE TestReadProxyHead701=== RUN TestReadProxyOutlastsServerWriteTimeout702=== PAUSE TestReadProxyOutlastsServerWriteTimeout703=== RUN TestReadProxyConditionalGet704=== PAUSE TestReadProxyConditionalGet705=== RUN TestReadProxyRootRedirectsToIndexHTML706=== PAUSE TestReadProxyRootRedirectsToIndexHTML707=== RUN TestReadProxyDisabled708=== PAUSE TestReadProxyDisabled709=== RUN TestReadRedirectNar710=== PAUSE TestReadRedirectNar711=== RUN TestReadRedirectKeepsNarinfoProxied712=== PAUSE TestReadRedirectKeepsNarinfoProxied713=== RUN TestReadProxyRangeRequest714=== PAUSE TestReadProxyRangeRequest715=== RUN TestReadRedirectUsesPublicS3URL716=== PAUSE TestReadRedirectUsesPublicS3URL717=== RUN TestPush_OverlappingRootsStoreOneRowPerKey718=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey719=== RUN TestPush_CompleteCommitsEveryRoot720=== PAUSE TestPush_CompleteCommitsEveryRoot721=== RUN TestPush_RepeatedRootCommitsOnce722=== PAUSE TestPush_RepeatedRootCommitsOnce723=== RUN TestPush_CompleteWaitsForCleanupOfThePush724=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush725=== RUN TestPush_RootsAreLockedInByteOrder726=== PAUSE TestPush_RootsAreLockedInByteOrder727=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit728=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit729=== RUN TestPush_RejectsBadRequests730=== PAUSE TestPush_RejectsBadRequests731=== RUN TestPush_SignsNarinfosOfItsPendingObjects732=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects733=== RUN TestRedundantMultipartUpload734=== PAUSE TestRedundantMultipartUpload735=== RUN TestCompleteMultipartUpload_ErrorButObjectExists736=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists737=== RUN TestCompletedNarNotReofferedAcrossClosures738=== PAUSE TestCompletedNarNotReofferedAcrossClosures739=== RUN TestPresignedUploadRegisteredBeforeCommit740=== PAUSE TestPresignedUploadRegisteredBeforeCommit741=== RUN TestService_Rustfstest742=== PAUSE TestService_Rustfstest743=== RUN TestParseSize744=== PAUSE TestParseSize745=== RUN TestSkippedUploadsHandler746=== PAUSE TestSkippedUploadsHandler747=== RUN TestSystemdListenerNotActivated748--- PASS: TestSystemdListenerNotActivated (0.00s)749=== RUN TestWatchdogBeatsWhenHealthy750--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)751=== RUN TestWatchdogSkipsWhenUnhealthy7522026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/20 08:16:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"762--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)763=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle765=== RUN TestProxyWriteTimeout766=== PAUSE TestProxyWriteTimeout767=== RUN TestPendingClosureWriteTimeout768=== PAUSE TestPendingClosureWriteTimeout769=== RUN TestIsValidUploadKey770=== PAUSE TestIsValidUploadKey771=== RUN TestUploadHandlersRejectInvalidKeys772=== PAUSE TestUploadHandlersRejectInvalidKeys773=== RUN TestUploadHandlersRejectOversizedBody774=== PAUSE TestUploadHandlersRejectOversizedBody775=== RUN TestService_cleanupPendingClosuresHandler776=== PAUSE TestService_cleanupPendingClosuresHandler777=== RUN TestService_createPendingClosureHandler778=== PAUSE TestService_createPendingClosureHandler779=== RUN TestService_verifyS3Integrity780=== PAUSE TestService_verifyS3Integrity781=== RUN TestCompleteMultipartUnregistered782=== PAUSE TestCompleteMultipartUnregistered783=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT784=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT785=== CONT TestService_AuthMiddleware786=== CONT TestPush_RootsAreLockedInByteOrder787=== CONT TestReadProxyDisabled788=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT789=== CONT TestCompleteMultipartUnregistered790=== CONT TestService_verifyS3Integrity791=== CONT TestService_createPendingClosureHandler792=== CONT TestService_cleanupPendingClosuresHandler793=== CONT TestUploadHandlersRejectOversizedBody794=== CONT TestUploadHandlersRejectInvalidKeys795=== CONT TestIsValidUploadKey796=== CONT TestPendingClosureWriteTimeout797=== RUN TestIsValidUploadKey/narinfo798=== RUN TestPendingClosureWriteTimeout/empty799=== PAUSE TestPendingClosureWriteTimeout/empty800=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle801=== CONT TestSkippedUploadsHandler802=== CONT TestParseSize803=== CONT TestService_Rustfstest804=== CONT TestPresignedUploadRegisteredBeforeCommit805--- PASS: TestParseSize (0.00s)806=== CONT TestCompleteMultipartUpload_ErrorButObjectExists807=== CONT TestRedundantMultipartUpload808=== CONT TestPush_SignsNarinfosOfItsPendingObjects809=== CONT TestPush_RejectsBadRequests810=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit8112026/10/20 08:16:12 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000812=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info813=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info814=== CONT TestProxyWriteTimeout815=== RUN TestProxyWriteTimeout/narinfo816=== PAUSE TestIsValidUploadKey/narinfo817=== RUN TestPendingClosureWriteTimeout/400_objects818=== CONT TestCompletedNarNotReofferedAcrossClosures819=== CONT TestGCTaskStore_StartNew820=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal821=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal822=== CONT TestReadProxyRootRedirectsToIndexHTML823=== PAUSE TestPendingClosureWriteTimeout/400_objects824=== RUN TestIsValidUploadKey/nar_zst825--- PASS: TestGCTaskStore_StartNew (0.00s)826=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key827=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key828=== PAUSE TestProxyWriteTimeout/narinfo829=== PAUSE TestIsValidUploadKey/nar_zst830=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key831=== RUN TestProxyWriteTimeout/1_GiB_nar832=== RUN TestIsValidUploadKey/nar_xz833=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key834=== RUN TestPendingClosureWriteTimeout/670k_objects835--- PASS: TestSkippedUploadsHandler (0.01s)836=== CONT TestReadProxyOutlastsServerWriteTimeout837=== PAUSE TestProxyWriteTimeout/1_GiB_nar838=== CONT TestReadProxyConditionalGet839=== RUN TestProxyWriteTimeout/10_GiB_nar840=== PAUSE TestProxyWriteTimeout/10_GiB_nar841=== PAUSE TestPendingClosureWriteTimeout/670k_objects842=== PAUSE TestIsValidUploadKey/nar_xz843=== RUN TestProxyWriteTimeout/unknown_size844=== PAUSE TestProxyWriteTimeout/unknown_size845=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline846=== RUN TestIsValidUploadKey/nar_plain847=== PAUSE TestIsValidUploadKey/nar_plain848=== CONT TestReadProxyHead849=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline850=== CONT TestReadProxyInvalidPath851=== RUN TestIsValidUploadKey/listing852=== PAUSE TestIsValidUploadKey/listing853=== RUN TestIsValidUploadKey/build_log854=== PAUSE TestIsValidUploadKey/build_log855=== RUN TestIsValidUploadKey/build_log_home-manager_file856=== PAUSE TestIsValidUploadKey/build_log_home-manager_file857=== RUN TestIsValidUploadKey/build_log_plus_in_name858=== PAUSE TestIsValidUploadKey/build_log_plus_in_name859=== RUN TestIsValidUploadKey/build_log_question_mark860=== PAUSE TestIsValidUploadKey/build_log_question_mark861=== RUN TestIsValidUploadKey/build_log_equals862=== PAUSE TestIsValidUploadKey/build_log_equals863=== RUN TestIsValidUploadKey/realisation864=== PAUSE TestIsValidUploadKey/realisation865=== RUN TestIsValidUploadKey/realisation_plus_in_output866=== PAUSE TestIsValidUploadKey/realisation_plus_in_output867=== RUN TestIsValidUploadKey/nix-cache-info868=== PAUSE TestIsValidUploadKey/nix-cache-info869=== RUN TestIsValidUploadKey/index.html870=== PAUSE TestIsValidUploadKey/index.html871=== RUN TestIsValidUploadKey/narinfo_key,_nar_type872=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type873=== RUN TestIsValidUploadKey/nar_key,_narinfo_type874=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type875=== RUN TestIsValidUploadKey/listing_key,_narinfo_type876=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type877=== RUN TestIsValidUploadKey/traversal878=== PAUSE TestIsValidUploadKey/traversal879=== RUN TestIsValidUploadKey/traversal_nar880=== PAUSE TestIsValidUploadKey/traversal_nar881=== RUN TestIsValidUploadKey/absolute882=== PAUSE TestIsValidUploadKey/absolute883=== RUN TestIsValidUploadKey/empty_key884=== PAUSE TestIsValidUploadKey/empty_key885=== RUN TestIsValidUploadKey/unknown_type886=== PAUSE TestIsValidUploadKey/unknown_type887=== CONT TestReadProxy404888=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure889=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure890=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart891=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart892=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts893=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts894=== CONT TestReadProxyNarStreaming8952026/10/20 08:16:13 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"896--- PASS: TestService_AuthMiddleware (0.50s)897=== CONT TestReadProxyContentNegotiation898--- PASS: TestService_Rustfstest (0.52s)899=== CONT TestReadProxyNarinfoAlreadyDecompressed9002026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures901--- PASS: TestReadProxyDisabled (0.57s)902=== CONT TestReadProxyNarinfo903--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.57s)904=== CONT TestIsValidCachePath905=== RUN TestIsValidCachePath/narinfo906=== PAUSE TestIsValidCachePath/narinfo907=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars908=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars909=== RUN TestIsValidCachePath/nar_zst910=== PAUSE TestIsValidCachePath/nar_zst911=== RUN TestIsValidCachePath/nar_xz912=== PAUSE TestIsValidCachePath/nar_xz913=== RUN TestIsValidCachePath/nar_bz2914=== PAUSE TestIsValidCachePath/nar_bz2915=== RUN TestIsValidCachePath/nar_uncompressed916=== PAUSE TestIsValidCachePath/nar_uncompressed917=== RUN TestIsValidCachePath/ls918=== PAUSE TestIsValidCachePath/ls919=== RUN TestIsValidCachePath/log920=== PAUSE TestIsValidCachePath/log921=== RUN TestIsValidCachePath/realisation922=== PAUSE TestIsValidCachePath/realisation923=== RUN TestIsValidCachePath/nix-cache-info924=== PAUSE TestIsValidCachePath/nix-cache-info925=== RUN TestIsValidCachePath/index.html926=== PAUSE TestIsValidCachePath/index.html927=== RUN TestIsValidCachePath/traversal_parent928=== PAUSE TestIsValidCachePath/traversal_parent929=== RUN TestIsValidCachePath/traversal_in_middle930=== PAUSE TestIsValidCachePath/traversal_in_middle931=== RUN TestIsValidCachePath/invalid_char_e932=== PAUSE TestIsValidCachePath/invalid_char_e933=== RUN TestIsValidCachePath/invalid_char_u934=== PAUSE TestIsValidCachePath/invalid_char_u935=== RUN TestIsValidCachePath/random_path936=== PAUSE TestIsValidCachePath/random_path937=== RUN TestIsValidCachePath/empty938=== PAUSE TestIsValidCachePath/empty939=== RUN TestIsValidCachePath/leading_slash940=== PAUSE TestIsValidCachePath/leading_slash941=== RUN TestIsValidCachePath/wrong_extension942=== PAUSE TestIsValidCachePath/wrong_extension943=== RUN TestIsValidCachePath/short_hash944=== PAUSE TestIsValidCachePath/short_hash945=== CONT TestParseSingleRange946=== RUN TestParseSingleRange/none947=== PAUSE TestParseSingleRange/none948=== RUN TestParseSingleRange/unknown_unit949=== PAUSE TestParseSingleRange/unknown_unit950=== RUN TestParseSingleRange/multi-range_ignored951=== PAUSE TestParseSingleRange/multi-range_ignored952=== RUN TestParseSingleRange/malformed_no_dash953=== PAUSE TestParseSingleRange/malformed_no_dash954=== RUN TestParseSingleRange/malformed_both_empty955=== PAUSE TestParseSingleRange/malformed_both_empty956=== RUN TestParseSingleRange/malformed_end_before_start957=== PAUSE TestParseSingleRange/malformed_end_before_start958=== RUN TestParseSingleRange/closed959=== PAUSE TestParseSingleRange/closed960=== RUN TestParseSingleRange/open-ended961=== PAUSE TestParseSingleRange/open-ended962=== RUN TestParseSingleRange/end_clamped_to_size963=== PAUSE TestParseSingleRange/end_clamped_to_size964=== RUN TestParseSingleRange/suffix965=== PAUSE TestParseSingleRange/suffix966=== RUN TestParseSingleRange/suffix_exceeds_size967=== PAUSE TestParseSingleRange/suffix_exceeds_size968=== RUN TestParseSingleRange/single_byte969=== PAUSE TestParseSingleRange/single_byte970=== RUN TestParseSingleRange/start_past_EOF971=== PAUSE TestParseSingleRange/start_past_EOF972=== RUN TestParseSingleRange/start_far_past_EOF973=== PAUSE TestParseSingleRange/start_far_past_EOF974=== CONT TestPresentNotReportedWhileGCDeletesClosure975=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh976=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh977=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale978=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale979=== CONT TestPresentRefreshesOnlyStaleClosures9802026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures9812026/10/20 08:16:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9822026/10/20 08:16:13 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst983--- PASS: TestCompleteMultipartUnregistered (0.62s)984=== CONT TestPresentReportsOnlyClosureRoots9852026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures9862026/10/20 08:16:13 INFO Received push request method=POST path=/api/pushes9872026/10/20 08:16:13 INFO Received push request method=POST path=/api/pushes9882026/10/20 08:16:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9892026/10/20 08:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9902026/10/20 08:16:13 INFO Signed narinfos id=1 count=19912026/10/20 08:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9922026/10/20 08:16:13 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLjMwZjA4NWZmLTY2MzgtNGNkYS05NGM1LWUzYmRlY2ZkM2U2YngxNzkyNDg0MTczNTQyMTYxNDQ19932026/10/20 08:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9942026/10/20 08:16:13 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9952026/10/20 08:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9962026/10/20 08:16:13 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9972026/10/20 08:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9982026/10/20 08:16:13 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19992026/10/20 08:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10002026/10/20 08:16:13 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1001--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.69s)1002=== CONT TestCreatePin_ReservedPins10032026-10-20 08:16:13.600 UTC [695] ERROR: could not obtain lock on row in relation "closures"10042026-10-20 08:16:13.600 UTC [695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10052026-10-20 08:16:13.600 UTC [695] ERROR: could not obtain lock on row in relation "closures"10062026-10-20 08:16:13.600 UTC [695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10072026-10-20 08:16:13.601 UTC [695] ERROR: could not obtain lock on row in relation "closures"10082026-10-20 08:16:13.601 UTC [695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10092026-10-20 08:16:13.601 UTC [695] ERROR: could not obtain lock on row in relation "closures"10102026-10-20 08:16:13.601 UTC [695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10112026-10-20 08:16:13.601 UTC [695] ERROR: could not obtain lock on row in relation "closures"10122026-10-20 08:16:13.601 UTC [695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10132026/10/20 08:16:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLjMwZjA4NWZmLTY2MzgtNGNkYS05NGM1LWUzYmRlY2ZkM2U2YngxNzkyNDg0MTczNTQyMTYxNDQ1 parts=11014--- PASS: TestPush_RootsAreLockedInByteOrder (0.71s)10152026/10/20 08:16:13 INFO Received push request method=POST path=/api/pushes1016=== CONT TestOrphanedObjectsGCStressTest1017--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.70s)1018=== CONT TestOrphanedObjectsGC10192026/10/20 08:16:13 INFO Received complete push request method=POST path=/api/pushes/1/complete10202026/10/20 08:16:13 INFO Received cleanup request method=DELETE path=/api/pending_closures10212026/10/20 08:16:13 INFO Aborted multipart uploads count=0 kept=010222026/10/20 08:16:13 INFO Completed push id=1 objects=4 duration=8.16193ms10232026/10/20 08:16:13 INFO Received push request method=POST path=/api/pushes10242026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10252026/10/20 08:16:13 INFO Received cleanup request method=DELETE path=/api/pending_closures10262026/10/20 08:16:13 INFO Aborted multipart uploads count=1 kept=010272026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10302026/10/20 08:16:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10312026-10-20 08:16:13.654 UTC [656] ERROR: Closure does not exist: id=110322026-10-20 08:16:13.654 UTC [656] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10332026-10-20 08:16:13.654 UTC [656] STATEMENT: -- name: CommitPendingClosure :one1034 SELECT commit_pending_closure($1::bigint)::bigint1035 1036--- PASS: TestService_cleanupPendingClosuresHandler (0.76s)1037=== CONT TestObjectStatsLargeCommit10382026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10392026/10/20 08:16:13 INFO Aborted multipart uploads count=0 kept=010402026/10/20 08:16:13 WARN Force mode enabled - objects will be deleted immediately without grace period10412026/10/20 08:16:13 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10422026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures1043--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.81s)1044=== CONT TestObjectStatsTrigger1045--- PASS: TestReadProxyHead (0.74s)1046=== CONT TestService_readinessHandler10472026/10/20 08:16:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36547/oidc10482026/10/20 08:16:13 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=010492026/10/20 08:16:13 INFO Vacuumed table table=pending_closures10502026/10/20 08:16:13 INFO Vacuumed table table=pending_objects10512026/10/20 08:16:13 INFO Vacuumed table table=multipart_uploads1052--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.84s)1053=== CONT TestService_healthCheckHandler10542026/10/20 08:16:13 INFO Vacuumed table table=closures10552026/10/20 08:16:13 INFO Vacuumed table table=objects10562026/10/20 08:16:13 INFO Received complete push request method=POST path=/api/pushes/2/complete10572026/10/20 08:16:13 INFO Completed push id=2 objects=4 duration=5.62631ms1058--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.86s)1059=== CONT TestGracefulShutdownDrainsInflight10602026/10/20 08:16:13 INFO Starting HTTP server address=127.0.0.1:4327310612026/10/20 08:16:13 INFO Shutdown signal received, draining in-flight requests timeout=10s1062=== RUN TestPush_RejectsBadRequests/root_not_in_objects1063=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1064=== RUN TestPush_RejectsBadRequests/no_roots1065=== PAUSE TestPush_RejectsBadRequests/no_roots1066=== RUN TestPush_RejectsBadRequests/no_objects1067=== PAUSE TestPush_RejectsBadRequests/no_objects1068=== RUN TestPush_RejectsBadRequests/bad_root1069=== PAUSE TestPush_RejectsBadRequests/bad_root1070=== CONT TestGCTaskStore_Fail1071--- PASS: TestGCTaskStore_Fail (0.00s)1072=== CONT TestGCTaskStore_PhaseUpdates1073--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1074=== CONT TestGCTaskStore_CompletedAllowsNewTask1075--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1076=== CONT TestGCTaskStore_GetReturnsLatest1077--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1078=== CONT TestGenerateLandingPage1079--- PASS: TestGenerateLandingPage (0.00s)1080=== CONT TestPendingCleanupUsesOneCutoff1081--- PASS: TestReadProxyInvalidPath (0.84s)1082=== CONT TestGCTaskStore_GetEmpty1083--- PASS: TestGCTaskStore_GetEmpty (0.00s)1084=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1085--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1086=== CONT TestGCTaskStore_ConflictDifferentParams1087--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1088=== CONT TestGCTaskStore_DeduplicateSameParams1089--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1090=== CONT TestMultipartCleanup10912026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures1092--- PASS: TestReadProxyNarStreaming (0.84s)1093=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10942026/10/20 08:16:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10952026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10962026/10/20 08:16:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLjAzODdmMjMzLWE2OWEtNGFlOS05Y2M4LTk4NDYxOThkZjBiNngxNzkyNDg0MTczNTAyOTc1ODY5 parts=1010972026/10/20 08:16:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10982026/10/20 08:16:13 INFO Completed upload id=1 objects=2 duration=2.97746ms10992026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures11002026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures11012026/10/20 08:16:13 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11022026/10/20 08:16:13 WARN Found objects in DB but missing from S3, will re-upload count=11103--- PASS: TestService_verifyS3Integrity (1.07s)1104=== CONT TestServerTLSConfig1105=== RUN TestServerTLSConfig/no_client_CA1106=== PAUSE TestServerTLSConfig/no_client_CA1107=== RUN TestServerTLSConfig/missing_CA_file1108=== PAUSE TestServerTLSConfig/missing_CA_file1109=== RUN TestServerTLSConfig/not_a_PEM_file1110=== PAUSE TestServerTLSConfig/not_a_PEM_file1111=== CONT TestPush_CompleteWaitsForCleanupOfThePush11122026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures11132026/10/20 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures1114--- PASS: TestReadProxy404 (1.02s)1115=== CONT TestService_NativeMTLS1116--- PASS: TestReadProxyConditionalGet (1.04s)1117=== CONT TestPush_RepeatedRootCommitsOnce1118--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.62s)1119=== CONT TestMetricsCommit11202026/10/20 08:16:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11212026/10/20 08:16:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1122--- PASS: TestReadProxyContentNegotiation (0.73s)1123=== CONT TestPush_CompleteCommitsEveryRoot11242026/10/20 08:16:14 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLjdkNzVhN2NkLTJkNDktNDU0OC1hZDNjLTIxNzFkNDE1NWFiZHgxNzkyNDg0MTczNjYyMDM2MjI0 parts=1011252026/10/20 08:16:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11262026/10/20 08:16:14 INFO Completed upload id=1 objects=2 duration=5.64197ms11272026/10/20 08:16:14 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011282026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures11292026/10/20 08:16:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures1130--- PASS: TestPresentRefreshesOnlyStaleClosures (0.68s)1131=== CONT TestMetricsInventory11322026/10/20 08:16:14 INFO Aborted multipart uploads count=0 kept=011332026/10/20 08:16:14 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=011342026/10/20 08:16:14 INFO Vacuumed table table=pending_closures11352026/10/20 08:16:14 INFO Vacuumed table table=pending_objects11362026/10/20 08:16:14 INFO Vacuumed table table=multipart_uploads11372026/10/20 08:16:14 INFO Vacuumed table table=closures11382026/10/20 08:16:14 INFO Vacuumed table table=objects1139--- PASS: TestPresentReportsOnlyClosureRoots (0.68s)1140=== CONT TestNARDeduplicationMetadataUploadBug11412026/10/20 08:16:14 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001142--- PASS: TestService_createPendingClosureHandler (1.30s)1143=== CONT TestReadProxyRangeRequest11442026/10/20 08:16:14 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1145--- PASS: TestReadProxyNarinfo (0.74s)1146=== CONT TestCreatePendingClosureRejectsOversizedNAR11472026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures1148--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1149=== CONT TestReadRedirectUsesPublicS3URL11502026/10/20 08:16:14 WARN readiness check failed error="closed pool"1151--- PASS: TestService_readinessHandler (0.60s)1152=== CONT TestCacheConfigHandlerMaxNarSize1153--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1154=== CONT TestLeadElectsOneAndHandsOver1155--- PASS: TestObjectStatsTrigger (0.62s)1156=== CONT TestClientIntegration11572026/10/20 08:16:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11582026/10/20 08:16:14 WARN Refused reserved pin name=worker-x86_64-linux11592026/10/20 08:16:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11602026/10/20 08:16:14 INFO Received create pin request method=POST path=/api/pins/my-app11612026/10/20 08:16:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1162--- PASS: TestCreatePin_ReservedPins (0.75s)1163=== CONT TestGCEndsOnShutdown1164=== RUN TestGCEndsOnShutdown/before_the_run1165=== PAUSE TestGCEndsOnShutdown/before_the_run1166=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1167=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1168=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1169=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1170=== CONT TestConnectWaitsForAPeerMigration1171--- PASS: TestService_healthCheckHandler (0.62s)1172=== CONT TestCommitRacingPendingCleanupKeepsObjects11732026/10/20 08:16:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11742026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures11752026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures11762026/10/20 08:16:14 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLjBmYjZjMWMyLWVmOGItNDU1Mi1iYjQxLWUxMWQwNjhkZGZkNngxNzkyNDg0MTczODYzODU3MDg1 parts=1211772026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures11782026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures1179--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.53s)1180=== CONT TestPushWaitsForSweepHoldingRow11812026/10/20 08:16:14 INFO Received cleanup request method=DELETE path=/api/pending_closures11822026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures1183--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.66s)1184=== CONT TestResolveDBConnectionString1185=== RUN TestResolveDBConnectionString/flag_wins1186=== PAUSE TestResolveDBConnectionString/flag_wins1187=== RUN TestResolveDBConnectionString/file_when_flag_empty1188=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1189=== RUN TestResolveDBConnectionString/missing_file_is_an_error1190=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1191=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1192=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1193=== RUN TestResolveDBConnectionString/nothing_configured1194=== PAUSE TestResolveDBConnectionString/nothing_configured1195=== CONT TestSweepRechecksPendingAfterLocking11962026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes11972026/10/20 08:16:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11982026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes1199--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.62s)12002026/10/20 08:16:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLjFlYzYxZmZjLTQ4YWItNGY2NS04NjZlLTJhNjc2NzYwMjhmYngxNzkyNDg0MTczOTg2MzY2MDMz parts=121201=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12022026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures12032026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures12042026/10/20 08:16:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12052026/10/20 08:16:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1206--- PASS: TestService_NativeMTLS (0.54s)1207=== CONT TestGetExistingObjectsLocksRows12082026/10/20 08:16:14 INFO Received cleanup request method=DELETE path=/api/pending_closures12092026/10/20 08:16:14 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket41/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12102026/10/20 08:16:14 INFO Aborted multipart uploads count=0 kept=112112026/10/20 08:16:14 INFO Received cleanup request method=DELETE path=/api/pending_closures12122026/10/20 08:16:14 INFO Aborted multipart uploads count=1 kept=01213--- PASS: TestMultipartCleanup (0.73s)1214=== CONT TestDeleteClosuresRacingPins12152026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes12162026/10/20 08:16:14 INFO Received complete push request method=POST path=/api/pushes/1/complete12172026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes12182026/10/20 08:16:14 INFO Completed push id=1 objects=4 duration=11.880259ms1219--- PASS: TestPush_RepeatedRootCommitsOnce (0.59s)1220=== CONT TestRegisterCompletedObjectNeedsPendingRow12212026/10/20 08:16:14 INFO Received complete push request method=POST path=/api/pushes/1/complete12222026/10/20 08:16:14 INFO Completed push id=1 objects=4 duration=9.395479ms12232026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes12242026/10/20 08:16:14 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12252026/10/20 08:16:14 INFO Completed upload id=2 objects=2 duration=2.06188ms1226--- PASS: TestMetricsCommit (0.60s)1227=== CONT TestClientFallsBackToClosures1228=== NAME TestOrphanedObjectsGC12292026/10/20 08:16:14 INFO Received complete push request method=POST path=/api/pushes/1/complete1230 orphaned_objects_gc_test.go:287: GC Test Summary:1231 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1232 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1233 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1234 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1235 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1236--- PASS: TestOrphanedObjectsGC (1.05s)1237=== CONT TestClientPushesUseOnePush12382026/10/20 08:16:14 INFO Completed push id=1 objects=6 duration=8.952119ms1239--- PASS: TestPush_CompleteCommitsEveryRoot (0.54s)1240=== CONT TestSweepSkipsRowsLockedByPush1241--- PASS: TestMetricsInventory (0.53s)1242=== CONT TestPinProtectsFromGC1243--- PASS: TestReadProxyRangeRequest (0.51s)1244=== CONT TestFailedS3DeleteKeepsTombstone1245=== NAME TestNARDeduplicationMetadataUploadBug1246 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3451588573/001/store/57v4bb5gk9g4anp5rmcpnind5sfx2gdg-file1.txt1247--- PASS: TestReadRedirectUsesPublicS3URL (0.58s)1248=== CONT TestClientSharedPathCommittedMidPush12492026/10/20 08:16:14 INFO lead: acquired remote=192.0.2.1:123412502026-10-20 08:16:14.833 UTC [806] ERROR: Push does not exist: id=112512026-10-20 08:16:14.833 UTC [806] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE12522026-10-20 08:16:14.833 UTC [806] STATEMENT: SELECT commit_push($1)1253--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.86s)1254=== CONT TestForceGCDuringPushOffersSweptObject1255=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1256=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1257=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1258=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1259=== CONT TestClientWithDependencies12602026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes12612026/10/20 08:16:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12622026/10/20 08:16:14 INFO Uploading 57v4bb5gk9g4anp5rmcpnind5sfx2gdg-file1.txt (160B)1263=== NAME TestClientIntegration1264 client_integration_test.go:286: Created store path: /build/TestClientIntegration2681049536/002/store/3yp5zs4gdx7ilsbvldj7gg9xn8cv8vzd-test-file.txt12652026/10/20 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures12662026/10/20 08:16:14 WARN Failed to register uploaded object key=57v4bb5gk9g4anp5rmcpnind5sfx2gdg.ls error="server returned 404: 404 page not found\n"12672026/10/20 08:16:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12682026/10/20 08:16:14 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12692026/10/20 08:16:14 INFO Signed narinfos id=1 count=112702026/10/20 08:16:14 INFO Uploading 1 narinfos12712026/10/20 08:16:14 INFO Received complete push request method=POST path=/api/pushes/1/complete12722026/10/20 08:16:14 WARN Failed to register uploaded object key=57v4bb5gk9g4anp5rmcpnind5sfx2gdg.narinfo error="server returned 404: 404 page not found\n"12732026/10/20 08:16:14 INFO Aborted multipart uploads count=0 kept=012742026/10/20 08:16:14 WARN Force mode enabled - objects will be deleted immediately without grace period12752026/10/20 08:16:14 INFO Completed push id=1 objects=3 duration=12.762789ms12762026/10/20 08:16:14 INFO Upload complete. (81ms)1277=== NAME TestNARDeduplicationMetadataUploadBug1278 metadata_upload_test.go:54: Retrieved narinfo from S3:12792026/10/20 08:16:14 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=01280 StorePath: /build/TestNARDeduplicationMetadataUploadBug3451588573/001/store/57v4bb5gk9g4anp5rmcpnind5sfx2gdg-file1.txt1281 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1282 Compression: zstd1283 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1284 NarSize: 1601285 References: 1286 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1287 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1288 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):12892026/10/20 08:16:14 INFO Vacuumed table table=pending_closures1290 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12912026/10/20 08:16:14 INFO Vacuumed table table=pending_objects12922026/10/20 08:16:14 INFO Vacuumed table table=multipart_uploads12932026/10/20 08:16:14 INFO Vacuumed table table=closures12942026/10/20 08:16:14 INFO Vacuumed table table=objects12952026/10/20 08:16:14 INFO Aborted multipart uploads count=0 kept=01296--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.56s)1297=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12982026/10/20 08:16:14 WARN Force mode enabled - objects will be deleted immediately without grace period12992026/10/20 08:16:14 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=01300=== NAME TestNARDeduplicationMetadataUploadBug1301 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3451588573/001/store/vj51v1kxnnmw0ddknwpg2qmp5i2r3vmp-file2.txt13022026/10/20 08:16:14 INFO Received push request method=POST path=/api/pushes13032026/10/20 08:16:14 INFO Vacuumed table table=pending_closures13042026/10/20 08:16:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13052026/10/20 08:16:14 INFO Uploading 3yp5zs4gdx7ilsbvldj7gg9xn8cv8vzd-test-file.txt (152B)13062026/10/20 08:16:14 INFO Vacuumed table table=pending_objects13072026/10/20 08:16:14 INFO Vacuumed table table=multipart_uploads13082026/10/20 08:16:14 INFO Vacuumed table table=closures13092026/10/20 08:16:14 INFO Vacuumed table table=objects13102026/10/20 08:16:14 WARN Failed to register uploaded object key=3yp5zs4gdx7ilsbvldj7gg9xn8cv8vzd.ls error="server returned 404: 404 page not found\n"1311--- PASS: TestSweepRechecksPendingAfterLocking (0.52s)1312=== CONT TestClientMultipleUploads13132026/10/20 08:16:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13142026/10/20 08:16:14 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13152026/10/20 08:16:14 INFO Signed narinfos id=1 count=113162026/10/20 08:16:14 INFO Uploading 1 narinfos13172026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete13182026/10/20 08:16:15 WARN Failed to register uploaded object key=3yp5zs4gdx7ilsbvldj7gg9xn8cv8vzd.narinfo error="server returned 404: 404 page not found\n"13192026/10/20 08:16:15 INFO Completed push id=1 objects=3 duration=5.9855ms13202026/10/20 08:16:15 INFO Upload complete. (97ms)1321--- PASS: TestGetExistingObjectsLocksRows (0.48s)1322=== CONT TestGCSweepDeliversEachKeyOnce13232026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes13242026/10/20 08:16:15 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13252026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13262026/10/20 08:16:15 INFO Signed narinfos id=2 count=113272026/10/20 08:16:15 WARN Failed to register uploaded object key=vj51v1kxnnmw0ddknwpg2qmp5i2r3vmp.ls error="server returned 404: 404 page not found\n"13282026/10/20 08:16:15 INFO Uploading 1 narinfos13292026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/2/complete13302026/10/20 08:16:15 WARN Failed to register uploaded object key=vj51v1kxnnmw0ddknwpg2qmp5i2r3vmp.narinfo error="server returned 404: 404 page not found\n"13312026/10/20 08:16:15 INFO Completed push id=2 objects=3 duration=3.45903ms13322026/10/20 08:16:15 INFO Upload complete. (62ms)13332026/10/20 08:16:15 INFO All 1 paths already cached1334=== NAME TestNARDeduplicationMetadataUploadBug1335 metadata_upload_test.go:76: Retrieved narinfo from S3:1336 StorePath: /build/TestNARDeduplicationMetadataUploadBug3451588573/001/store/vj51v1kxnnmw0ddknwpg2qmp5i2r3vmp-file2.txt1337 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1338 Compression: zstd1339 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1340 NarSize: 1601341 References: 1342 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1343=== NAME TestClientIntegration1344 client_integration_test.go:312: Retrieved narinfo from S3:1345 StorePath: /build/TestClientIntegration2681049536/002/store/3yp5zs4gdx7ilsbvldj7gg9xn8cv8vzd-test-file.txt1346 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1347 Compression: zstd1348 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11349 NarSize: 1521350 References: 1351 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11352=== NAME TestNARDeduplicationMetadataUploadBug1353 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1354 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1355 {"version":1,"root":{"type":"regular","size":44}}1356=== NAME TestClientIntegration1357 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1358 client_integration_test.go:313: Decompressed .ls content (64 bytes):1359 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1360 client_integration_test.go:316: Testing garbage collection...1361--- PASS: TestNARDeduplicationMetadataUploadBug (0.86s)1362=== CONT TestGCMetrics1363--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.45s)1364=== CONT TestGCBugBareHashReferences13652026/10/20 08:16:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13662026/10/20 08:16:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures13672026/10/20 08:16:15 INFO Garbage collection started13682026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=013692026/10/20 08:16:15 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLmE1M2IwZWFiLTJjNzEtNDU3Zi05YTA2LWI2Y2M0MThhYTA2Y3gxNzkyNDg0MTc0NTM0MjcxNzQx error="Get \"http://127.0.0.1:1/bucket26/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13702026/10/20 08:16:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWJlM2I3MTAtZmE3OC00YjBmLTkwNTQtNDNkMWNhNWZmN2NlLmMwZGQ4Njc5LTM2MmMtNGEzOS05YTYzLTkyMTA5ZTMwYTY4ZXgxNzkyNDg0MTc0NTI3Mjk1NzMy parts=1213712026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period13722026/10/20 08:16:15 INFO Received cleanup request method=DELETE path=/api/pending_closures13732026/10/20 08:16:15 INFO Aborted multipart uploads count=1 kept=01374--- PASS: TestRedundantMultipartUpload (2.23s)1375=== CONT TestTombstonedObjectOfferedWithoutWaiting13762026/10/20 08:16:15 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=013772026/10/20 08:16:15 INFO Vacuumed table table=pending_closures13782026/10/20 08:16:15 INFO Vacuumed table table=pending_objects13792026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads13802026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=013812026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period13822026/10/20 08:16:15 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=013832026/10/20 08:16:15 INFO Vacuumed table table=pending_closures13842026/10/20 08:16:15 INFO Vacuumed table table=pending_objects13852026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads13862026/10/20 08:16:15 INFO Vacuumed table table=closures13872026/10/20 08:16:15 INFO Vacuumed table table=closures1388--- PASS: TestObjectStatsLargeCommit (1.53s)1389=== CONT TestGCSweepSkipsPendingObjects13902026/10/20 08:16:15 INFO Vacuumed table table=objects13912026/10/20 08:16:15 INFO Vacuumed table table=objects13922026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures13932026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=01394--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.68s)1395=== CONT TestGCAdvisoryLockBlocksConcurrentRun13962026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period13972026/10/20 08:16:15 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=013982026/10/20 08:16:15 INFO Vacuumed table table=pending_closures13992026/10/20 08:16:15 INFO Vacuumed table table=pending_objects14002026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads14012026/10/20 08:16:15 INFO Vacuumed table table=closures14022026/10/20 08:16:15 INFO Vacuumed table table=objects1403--- PASS: TestSweepSkipsRowsLockedByPush (0.58s)1404=== CONT TestDeduplicatedObjectsRecordedAsPending1405=== NAME TestPinProtectsFromGC1406 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3839828102/001/store/gs78sy666jnvqiwhrkygqm7c1cjfwsys-pinned-file.txt1407 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3839828102/001/store/iawpr23minqaqmfmy5lhyvc6scpmmxnm-unpinned-file.txt14082026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures14092026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=014102026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period14112026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures14122026/10/20 08:16:15 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14132026/10/20 08:16:15 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."14142026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures1415--- PASS: TestFailedS3DeleteKeepsTombstone (0.60s)1416=== CONT TestPushDedupSurvivesConcurrentGC14172026/10/20 08:16:15 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14182026/10/20 08:16:15 INFO Uploading d30ss3k2sjxb2lj7zk3wrczzbmfssk7c-shared-dep (136B)14192026/10/20 08:16:15 INFO Uploading 1cncmiwz7q6m337ybcy0v576gapsbkhd-a (216B)14202026/10/20 08:16:15 WARN Failed to register uploaded object key=00x3caram4zrzwyr4mhcvivybiaazvcd.ls error="server returned 404: 404 page not found\n"14212026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/0sj37cyh5lz5grz3yia544dwb5y5071qbcxbb42xdjbnymcxlf6p.nar.zst error="server returned 404: 404 page not found\n"14222026/10/20 08:16:15 WARN Failed to register uploaded object key=d30ss3k2sjxb2lj7zk3wrczzbmfssk7c.ls error="server returned 404: 404 page not found\n"14232026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14242026/10/20 08:16:15 WARN Failed to register uploaded object key=1cncmiwz7q6m337ybcy0v576gapsbkhd.ls error="server returned 404: 404 page not found\n"14252026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14262026/10/20 08:16:15 INFO Signed narinfos id=1 count=214272026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14282026/10/20 08:16:15 INFO Signed narinfos id=2 count=214292026/10/20 08:16:15 INFO Uploading 4 narinfos14302026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes14312026/10/20 08:16:15 WARN Failed to register uploaded object key=d30ss3k2sjxb2lj7zk3wrczzbmfssk7c.narinfo error="server returned 404: 404 page not found\n"14322026/10/20 08:16:15 WARN Failed to register uploaded object key=1cncmiwz7q6m337ybcy0v576gapsbkhd.narinfo error="server returned 404: 404 page not found\n"14332026/10/20 08:16:15 WARN Failed to register uploaded object key=00x3caram4zrzwyr4mhcvivybiaazvcd.narinfo error="server returned 404: 404 page not found\n"14342026/10/20 08:16:15 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14352026/10/20 08:16:15 INFO Uploading zg19baf9d31jczv1dd9zp04s7x3m3idh-b (216B)14362026/10/20 08:16:15 INFO Uploading 4f0giz98nsb3yly65sdfhrgkgazij9i0-shared-dep (136B)14372026/10/20 08:16:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14382026/10/20 08:16:15 WARN Failed to register uploaded object key=d30ss3k2sjxb2lj7zk3wrczzbmfssk7c.narinfo error="server returned 404: 404 page not found\n"14392026/10/20 08:16:15 WARN Failed to register uploaded object key=a1fclnbv92d7gzj6x6y9hip951slxbpr.ls error="server returned 404: 404 page not found\n"14402026/10/20 08:16:15 WARN Failed to register uploaded object key=4f0giz98nsb3yly65sdfhrgkgazij9i0.ls error="server returned 404: 404 page not found\n"14412026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/11iw4cp5xxh6f963fx77mv2phij0k4x2f0ir54h7w9mdci28aiaf.nar.zst error="server returned 404: 404 page not found\n"14422026/10/20 08:16:15 WARN Failed to register uploaded object key=zg19baf9d31jczv1dd9zp04s7x3m3idh.ls error="server returned 404: 404 page not found\n"14432026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14442026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14452026/10/20 08:16:15 INFO Completed upload id=1 objects=6 duration=6.173059ms14462026/10/20 08:16:15 INFO Signed narinfos id=1 count=314472026/10/20 08:16:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14482026/10/20 08:16:15 INFO Uploading 3 narinfos14492026/10/20 08:16:15 INFO Completed upload id=2 objects=6 duration=881.26µs14502026/10/20 08:16:15 INFO Upload complete. (83ms)1451=== NAME TestClientFallsBackToClosures1452 client_pushes_test.go:112: Retrieved narinfo from S3:1453 StorePath: /build/TestClientFallsBackToClosures1764603497/001/store/d30ss3k2sjxb2lj7zk3wrczzbmfssk7c-shared-dep1454 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1455 Compression: zstd1456 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821457 NarSize: 1361458 References: 1459 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n14602026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes1461 client_pushes_test.go:112: Retrieved narinfo from S3:14622026/10/20 08:16:15 WARN Failed to register uploaded object key=zg19baf9d31jczv1dd9zp04s7x3m3idh.narinfo error="server returned 404: 404 page not found\n"1463 StorePath: /build/TestClientFallsBackToClosures1764603497/001/store/1cncmiwz7q6m337ybcy0v576gapsbkhd-a1464 URL: nar/0sj37cyh5lz5grz3yia544dwb5y5071qbcxbb42xdjbnymcxlf6p.nar.zst1465 Compression: zstd1466 NarHash: sha256:0sj37cyh5lz5grz3yia544dwb5y5071qbcxbb42xdjbnymcxlf6p1467 NarSize: 2161468 References: /build/TestClientFallsBackToClosures1764603497/001/store/d30ss3k2sjxb2lj7zk3wrczzbmfssk7c-shared-dep1469 CA: text:sha256:0zxmyyhraf8jc2w9m1gbq25n45g0ic3r3cdl4m4l23rwsrba06kw14702026/10/20 08:16:15 WARN Failed to register uploaded object key=4f0giz98nsb3yly65sdfhrgkgazij9i0.narinfo error="server returned 404: 404 page not found\n"14712026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete14722026/10/20 08:16:15 WARN Failed to register uploaded object key=a1fclnbv92d7gzj6x6y9hip951slxbpr.narinfo error="server returned 404: 404 page not found\n"1473 client_pushes_test.go:112: Retrieved narinfo from S3:1474 StorePath: /build/TestClientFallsBackToClosures1764603497/001/store/00x3caram4zrzwyr4mhcvivybiaazvcd-b1475 URL: nar/0sj37cyh5lz5grz3yia544dwb5y5071qbcxbb42xdjbnymcxlf6p.nar.zst1476 Compression: zstd1477 NarHash: sha256:0sj37cyh5lz5grz3yia544dwb5y5071qbcxbb42xdjbnymcxlf6p1478 NarSize: 2161479 References: /build/TestClientFallsBackToClosures1764603497/001/store/d30ss3k2sjxb2lj7zk3wrczzbmfssk7c-shared-dep1480 CA: text:sha256:0zxmyyhraf8jc2w9m1gbq25n45g0ic3r3cdl4m4l23rwsrba06kw14812026/10/20 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14822026/10/20 08:16:15 INFO Uploading gs78sy666jnvqiwhrkygqm7c1cjfwsys-pinned-file.txt (128B)1483--- PASS: TestClientFallsBackToClosures (0.70s)1484=== CONT TestLeadEndsOnShutdown14852026/10/20 08:16:15 INFO Completed push id=1 objects=8 duration=5.68438ms14862026/10/20 08:16:15 INFO Upload complete. (72ms)1487=== NAME TestClientMultipleUploads1488 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2740425799/001/store/hrzni12g5rwyz0pw9irqnr3gsn26wsv0-test-file-0.txt1489=== NAME TestClientWithDependencies1490 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3735491837/001/store/546sy9ldz7gi28w7qgvyak0nbzjhwkgq-test-script1491=== NAME TestClientPushesUseOnePush1492 client_pushes_test.go:97: Retrieved narinfo from S3:1493 StorePath: /build/TestClientPushesUseOnePush2302158099/001/store/4f0giz98nsb3yly65sdfhrgkgazij9i0-shared-dep1494 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1495 Compression: zstd1496 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821497 NarSize: 1361498 References: 1499 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15002026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15012026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15022026/10/20 08:16:15 WARN Failed to register uploaded object key=gs78sy666jnvqiwhrkygqm7c1cjfwsys.ls error="server returned 404: 404 page not found\n"15032026/10/20 08:16:15 INFO Signed narinfos id=1 count=11504 client_pushes_test.go:97: Retrieved narinfo from S3:1505 StorePath: /build/TestClientPushesUseOnePush2302158099/001/store/a1fclnbv92d7gzj6x6y9hip951slxbpr-a15062026/10/20 08:16:15 INFO Uploading 1 narinfos1507 URL: nar/11iw4cp5xxh6f963fx77mv2phij0k4x2f0ir54h7w9mdci28aiaf.nar.zst1508 Compression: zstd1509 NarHash: sha256:11iw4cp5xxh6f963fx77mv2phij0k4x2f0ir54h7w9mdci28aiaf1510 NarSize: 2161511 References: /build/TestClientPushesUseOnePush2302158099/001/store/4f0giz98nsb3yly65sdfhrgkgazij9i0-shared-dep1512 CA: text:sha256:0zb1kvji0fnswj292r3fbyc3qwxadmqwim236m1wwvpgmc27hjm915132026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=01514 client_pushes_test.go:97: Retrieved narinfo from S3:1515 StorePath: /build/TestClientPushesUseOnePush2302158099/001/store/zg19baf9d31jczv1dd9zp04s7x3m3idh-b1516 URL: nar/11iw4cp5xxh6f963fx77mv2phij0k4x2f0ir54h7w9mdci28aiaf.nar.zst1517 Compression: zstd1518 NarHash: sha256:11iw4cp5xxh6f963fx77mv2phij0k4x2f0ir54h7w9mdci28aiaf1519 NarSize: 2161520 References: /build/TestClientPushesUseOnePush2302158099/001/store/4f0giz98nsb3yly65sdfhrgkgazij9i0-shared-dep1521 CA: text:sha256:0zb1kvji0fnswj292r3fbyc3qwxadmqwim236m1wwvpgmc27hjm915222026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete15232026/10/20 08:16:15 WARN Failed to register uploaded object key=gs78sy666jnvqiwhrkygqm7c1cjfwsys.narinfo error="server returned 404: 404 page not found\n"15242026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period1525--- PASS: TestClientPushesUseOnePush (0.70s)1526=== CONT TestService_ReadScope_PublicByDefault15272026/10/20 08:16:15 INFO Completed push id=1 objects=3 duration=8.31027ms15282026/10/20 08:16:15 INFO Upload complete. (71ms)1529=== NAME TestClientWithDependencies1530 client_integration_test.go:615: Found 1 dependencies (including self)15312026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes15322026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=01533=== NAME TestClientMultipleUploads1534 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2740425799/001/store/qzy1xvhk6p4vr7937nzs6p54x1jr8kpa-test-file-1.txt1535--- PASS: TestPushWaitsForSweepHoldingRow (0.96s)1536=== CONT TestLeadIncumbentAnnouncesAtOnce15372026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period15382026/10/20 08:16:15 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15392026/10/20 08:16:15 INFO Uploading r8a4mzsgrhnlaqm7qzgrdb7hsybm4yzx-top (224B)15402026/10/20 08:16:15 INFO Uploading q96kfdbkcz9llxff6zad8m35mi9zlzd8-shared-dep (136B)15412026/10/20 08:16:15 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=015422026/10/20 08:16:15 INFO Vacuumed table table=pending_closures15432026/10/20 08:16:15 INFO Vacuumed table table=pending_objects15442026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads15452026/10/20 08:16:15 INFO Vacuumed table table=closures15462026/10/20 08:16:15 INFO Vacuumed table table=objects15472026/10/20 08:16:15 WARN Failed to register uploaded object key=r8a4mzsgrhnlaqm7qzgrdb7hsybm4yzx.ls error="server returned 404: 404 page not found\n"15482026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15492026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/1ljhc5j3wlx5k2zhdn9bs6f0ww647vyhxj0885idbnq33bz9mrb5.nar.zst error="server returned 404: 404 page not found\n"15502026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15512026/10/20 08:16:15 WARN Failed to register uploaded object key=q96kfdbkcz9llxff6zad8m35mi9zlzd8.ls error="server returned 404: 404 page not found\n"1552--- PASS: TestGCMetrics (0.34s)1553=== CONT TestClientErrorHandling15542026/10/20 08:16:15 INFO Signed narinfos id=1 count=21555=== RUN TestClientErrorHandling/InvalidStorePath15562026/10/20 08:16:15 INFO Uploading 2 narinfos1557=== PAUSE TestClientErrorHandling/InvalidStorePath1558=== RUN TestClientErrorHandling/InvalidAuthToken1559=== PAUSE TestClientErrorHandling/InvalidAuthToken1560=== RUN TestClientErrorHandling/ServerNotAvailable1561=== PAUSE TestClientErrorHandling/ServerNotAvailable1562=== CONT TestClientCADerivations15632026/10/20 08:16:15 WARN Failed to register uploaded object key=q96kfdbkcz9llxff6zad8m35mi9zlzd8.narinfo error="server returned 404: 404 page not found\n"15642026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete15652026/10/20 08:16:15 WARN Failed to register uploaded object key=r8a4mzsgrhnlaqm7qzgrdb7hsybm4yzx.narinfo error="server returned 404: 404 page not found\n"15662026/10/20 08:16:15 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=015672026/10/20 08:16:15 INFO Vacuumed table table=pending_closures15682026/10/20 08:16:15 INFO Vacuumed table table=pending_objects15692026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures15702026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads15712026/10/20 08:16:15 INFO Vacuumed table table=closures15722026/10/20 08:16:15 INFO Vacuumed table table=objects1573--- PASS: TestGCSweepDeliversEachKeyOnce (0.39s)1574=== CONT TestCacheConfigHandler1575=== RUN TestCacheConfigHandler/full_config,_no_issuer1576=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1577=== RUN TestCacheConfigHandler/no_cache_url_configured1578=== PAUSE TestCacheConfigHandler/no_cache_url_configured1579=== RUN TestCacheConfigHandler/no_signing_keys1580=== PAUSE TestCacheConfigHandler/no_signing_keys1581=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator15822026/10/20 08:16:15 INFO Completed push id=1 objects=6 duration=11.597969ms1583=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1584=== CONT TestCacheStatsHandler15852026/10/20 08:16:15 INFO Upload complete. (74ms)1586--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.29s)1587=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1588=== NAME TestClientSharedPathCommittedMidPush1589 client_integration_test.go:680: Retrieved narinfo from S3:1590 StorePath: /build/TestClientSharedPathCommittedMidPush309183447/001/store/q96kfdbkcz9llxff6zad8m35mi9zlzd8-shared-dep1591 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1592 Compression: zstd1593 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821594 NarSize: 1361595 References: 1596 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1597=== NAME TestClientMultipleUploads1598 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2740425799/001/store/rirr7khwpk10774wmpwrdprd7sw30lrm-test-file-2.txt1599=== NAME TestClientSharedPathCommittedMidPush1600 client_integration_test.go:680: Retrieved narinfo from S3:1601 StorePath: /build/TestClientSharedPathCommittedMidPush309183447/001/store/r8a4mzsgrhnlaqm7qzgrdb7hsybm4yzx-top1602 URL: nar/1ljhc5j3wlx5k2zhdn9bs6f0ww647vyhxj0885idbnq33bz9mrb5.nar.zst1603 Compression: zstd1604 NarHash: sha256:1ljhc5j3wlx5k2zhdn9bs6f0ww647vyhxj0885idbnq33bz9mrb51605 NarSize: 2241606 References: /build/TestClientSharedPathCommittedMidPush309183447/001/store/q96kfdbkcz9llxff6zad8m35mi9zlzd8-shared-dep1607 CA: text:sha256:0881xy3lhhcfz2ngvvdqdhwwjdfa65agygpv4501p1rjd698v91b1608--- PASS: TestClientSharedPathCommittedMidPush (0.65s)1609=== CONT TestService_AuthMiddleware_MTLSProxyHeader16102026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures16112026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes16122026/10/20 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16132026/10/20 08:16:15 INFO Uploading iawpr23minqaqmfmy5lhyvc6scpmmxnm-unpinned-file.txt (128B)16142026/10/20 08:16:15 WARN Failed to register uploaded object key=iawpr23minqaqmfmy5lhyvc6scpmmxnm.ls error="server returned 404: 404 page not found\n"16152026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16162026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16172026/10/20 08:16:15 INFO Signed narinfos id=2 count=116182026/10/20 08:16:15 INFO Uploading 1 narinfos16192026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=016202026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/2/complete16212026/10/20 08:16:15 WARN Failed to register uploaded object key=iawpr23minqaqmfmy5lhyvc6scpmmxnm.narinfo error="server returned 404: 404 page not found\n"16222026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period16232026/10/20 08:16:15 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"1624--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.26s)1625=== CONT TestService_RequireScope_OIDC16262026/10/20 08:16:15 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=016272026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes16282026/10/20 08:16:15 INFO Completed push id=2 objects=3 duration=17.473989ms16292026/10/20 08:16:15 INFO Upload complete. (70ms)16302026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures16312026/10/20 08:16:15 INFO Vacuumed table table=pending_closures16322026/10/20 08:16:15 INFO Vacuumed table table=pending_objects16332026/10/20 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16342026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads16352026/10/20 08:16:15 INFO Uploading 546sy9ldz7gi28w7qgvyak0nbzjhwkgq-test-script (136B)16362026/10/20 08:16:15 INFO Vacuumed table table=closures1637--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.24s)1638=== CONT TestService_AuthMiddleware_OIDC16392026/10/20 08:16:15 INFO Vacuumed table table=objects16402026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16412026/10/20 08:16:15 WARN Failed to register uploaded object key=546sy9ldz7gi28w7qgvyak0nbzjhwkgq.ls error="server returned 404: 404 page not found\n"16422026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16432026/10/20 08:16:15 WARN Failed to register uploaded object key=log/j62x1yzpf69akg286qv1fc44mg9x7lb0-test-script.drv error="server returned 404: 404 page not found\n"16442026/10/20 08:16:15 INFO Signed narinfos id=1 count=116452026/10/20 08:16:15 INFO Uploading 1 narinfos1646--- PASS: TestGCSweepSkipsPendingObjects (0.31s)1647=== CONT TestReadRedirectKeepsNarinfoProxied1648--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.58s)1649=== CONT TestReadRedirectNar16502026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete16512026/10/20 08:16:15 WARN Failed to register uploaded object key=546sy9ldz7gi28w7qgvyak0nbzjhwkgq.narinfo error="server returned 404: 404 page not found\n"16522026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes16532026/10/20 08:16:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures16542026/10/20 08:16:15 INFO Garbage collection started16552026/10/20 08:16:15 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16562026/10/20 08:16:15 INFO Uploading rirr7khwpk10774wmpwrdprd7sw30lrm-test-file-2.txt (160B)16572026/10/20 08:16:15 INFO Uploading hrzni12g5rwyz0pw9irqnr3gsn26wsv0-test-file-0.txt (160B)16582026/10/20 08:16:15 INFO Uploading qzy1xvhk6p4vr7937nzs6p54x1jr8kpa-test-file-1.txt (160B)16592026/10/20 08:16:15 INFO Completed push id=1 objects=4 duration=13.840319ms16602026/10/20 08:16:15 INFO Upload complete. (94ms)1661=== NAME TestClientWithDependencies1662 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3735491837/001/store) requires matching store prefix16632026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16642026/10/20 08:16:15 WARN Failed to register uploaded object key=qzy1xvhk6p4vr7937nzs6p54x1jr8kpa.ls error="server returned 404: 404 page not found\n"16652026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16662026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16672026/10/20 08:16:15 WARN Failed to register uploaded object key=hrzni12g5rwyz0pw9irqnr3gsn26wsv0.ls error="server returned 404: 404 page not found\n"16682026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16692026/10/20 08:16:15 WARN Failed to register uploaded object key=rirr7khwpk10774wmpwrdprd7sw30lrm.ls error="server returned 404: 404 page not found\n"16702026/10/20 08:16:15 INFO Signed narinfos id=1 count=316712026/10/20 08:16:15 INFO Uploading 3 narinfos1672--- PASS: TestClientWithDependencies (0.69s)1673=== CONT TestService_ReadAuthMiddleware16742026/10/20 08:16:15 WARN Failed to register uploaded object key=qzy1xvhk6p4vr7937nzs6p54x1jr8kpa.narinfo error="server returned 404: 404 page not found\n"16752026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete16762026/10/20 08:16:15 WARN Failed to register uploaded object key=hrzni12g5rwyz0pw9irqnr3gsn26wsv0.narinfo error="server returned 404: 404 page not found\n"16772026/10/20 08:16:15 WARN Failed to register uploaded object key=rirr7khwpk10774wmpwrdprd7sw30lrm.narinfo error="server returned 404: 404 page not found\n"16782026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=016792026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures16802026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period16812026/10/20 08:16:15 INFO Completed push id=1 objects=9 duration=15.833708ms16822026/10/20 08:16:15 INFO Upload complete. (88ms)1683=== NAME TestClientMultipleUploads1684 client_integration_test.go:369: Uploaded 3 paths in 124.391558ms1685--- PASS: TestService_ReadScope_PublicByDefault (0.19s)1686--- PASS: TestClientMultipleUploads (0.56s)1687=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1688=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16892026/10/20 08:16:15 INFO Received uploads request method=POST path=/16902026/10/20 08:16:15 INFO Received complete multipart upload request method=POST path=/1691=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1692=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16932026/10/20 08:16:15 INFO Received request for more parts method=POST path=/1694=== CONT TestProxyWriteTimeout/narinfo16952026/10/20 08:16:15 INFO Received uploads request method=POST path=/1696=== CONT TestProxyWriteTimeout/unknown_size1697--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1698 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1699 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1700 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1701 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1702=== CONT TestProxyWriteTimeout/10_GiB_nar1703=== CONT TestPendingClosureWriteTimeout/empty1704=== CONT TestProxyWriteTimeout/1_GiB_nar1705--- PASS: TestProxyWriteTimeout (0.08s)1706 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1707 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1708 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1709 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1710=== CONT TestPendingClosureWriteTimeout/670k_objects1711=== CONT TestPendingClosureWriteTimeout/400_objects1712=== CONT TestIsValidUploadKey/narinfo1713=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1714=== CONT TestIsValidUploadKey/realisation_plus_in_output1715=== CONT TestIsValidUploadKey/realisation1716=== CONT TestIsValidUploadKey/build_log_equals1717=== CONT TestIsValidUploadKey/build_log_question_mark1718=== CONT TestIsValidUploadKey/build_log_plus_in_name1719=== CONT TestIsValidUploadKey/build_log_home-manager_file1720=== CONT TestIsValidUploadKey/build_log1721=== CONT TestIsValidUploadKey/listing1722=== CONT TestIsValidUploadKey/nar_plain1723=== CONT TestIsValidUploadKey/nar_xz1724=== CONT TestIsValidUploadKey/nar_zst1725=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1726=== CONT TestIsValidUploadKey/traversal1727=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1728=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1729=== CONT TestIsValidUploadKey/index.html1730=== CONT TestIsValidUploadKey/unknown_type1731=== CONT TestIsValidUploadKey/nix-cache-info1732=== CONT TestIsValidUploadKey/empty_key1733=== CONT TestIsValidUploadKey/absolute1734=== CONT TestIsValidUploadKey/traversal_nar1735--- PASS: TestIsValidUploadKey (0.08s)1736 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1737 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1738 --- PASS: TestIsValidUploadKey/realisation (0.00s)1739 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1740 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1741 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1742 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1743 --- PASS: TestIsValidUploadKey/build_log (0.00s)1744 --- PASS: TestIsValidUploadKey/listing (0.00s)1745 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1746 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1747 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1748 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1749 --- PASS: TestIsValidUploadKey/traversal (0.00s)1750 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1751 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1752 --- PASS: TestIsValidUploadKey/index.html (0.00s)1753 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1754 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1755 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1756 --- PASS: TestIsValidUploadKey/absolute (0.00s)1757 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1758=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17592026/10/20 08:16:15 INFO Received uploads request method=POST path=/17602026/10/20 08:16:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36497/oidc17612026/10/20 08:16:15 INFO lead: acquired remote=192.0.2.1:123417622026/10/20 08:16:15 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=01763--- PASS: TestGCBugBareHashReferences (0.53s)1764=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17652026/10/20 08:16:15 INFO Received request for more parts method=POST path=/17662026/10/20 08:16:15 INFO Vacuumed table table=pending_closures17672026/10/20 08:16:15 INFO Vacuumed table table=pending_objects17682026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads17692026/10/20 08:16:15 INFO Vacuumed table table=closures17702026/10/20 08:16:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43819/oidc17712026/10/20 08:16:15 INFO lead: acquired remote=192.0.2.1:123417722026/10/20 08:16:15 INFO lead: released remote=192.0.2.1:12341773--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.22s)1774=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17752026/10/20 08:16:15 INFO Received complete multipart upload request method=POST path=/17762026/10/20 08:16:15 INFO Vacuumed table table=objects17772026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=01778=== CONT TestIsValidCachePath/narinfo1779=== CONT TestIsValidCachePath/index.html1780=== CONT TestIsValidCachePath/short_hash1781=== CONT TestIsValidCachePath/wrong_extension1782=== CONT TestIsValidCachePath/invalid_char_e1783=== CONT TestIsValidCachePath/invalid_char_u1784=== CONT TestIsValidCachePath/traversal_in_middle1785=== CONT TestIsValidCachePath/leading_slash1786=== CONT TestIsValidCachePath/traversal_parent1787=== CONT TestIsValidCachePath/empty1788=== CONT TestIsValidCachePath/random_path1789=== CONT TestIsValidCachePath/nar_xz1790=== CONT TestIsValidCachePath/nar_bz21791=== CONT TestIsValidCachePath/nar_uncompressed1792=== CONT TestIsValidCachePath/nix-cache-info1793=== CONT TestIsValidCachePath/nar_zst1794=== CONT TestIsValidCachePath/realisation1795=== CONT TestIsValidCachePath/log1796=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1797=== CONT TestIsValidCachePath/ls1798--- PASS: TestIsValidCachePath (0.00s)1799 --- PASS: TestIsValidCachePath/narinfo (0.00s)1800 --- PASS: TestIsValidCachePath/index.html (0.00s)1801 --- PASS: TestIsValidCachePath/short_hash (0.00s)1802 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1803 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1804 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1805 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1806 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1807 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1808 --- PASS: TestIsValidCachePath/empty (0.00s)1809 --- PASS: TestIsValidCachePath/random_path (0.00s)1810 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1811 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1812 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1813 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1814 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1815 --- PASS: TestIsValidCachePath/realisation (0.00s)1816 --- PASS: TestIsValidCachePath/log (0.00s)1817 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1818 --- PASS: TestIsValidCachePath/ls (0.00s)1819=== CONT TestParseSingleRange/none1820=== CONT TestParseSingleRange/open-ended1821=== CONT TestParseSingleRange/start_far_past_EOF1822=== CONT TestParseSingleRange/start_past_EOF1823=== CONT TestParseSingleRange/single_byte1824=== CONT TestParseSingleRange/suffix_exceeds_size1825=== CONT TestParseSingleRange/suffix1826=== CONT TestParseSingleRange/end_clamped_to_size1827=== CONT TestParseSingleRange/malformed_both_empty1828=== CONT TestParseSingleRange/closed1829=== CONT TestParseSingleRange/multi-range_ignored1830=== CONT TestParseSingleRange/malformed_no_dash1831=== CONT TestParseSingleRange/malformed_end_before_start1832=== CONT TestParseSingleRange/unknown_unit1833--- PASS: TestParseSingleRange (0.00s)1834 --- PASS: TestParseSingleRange/none (0.00s)1835 --- PASS: TestParseSingleRange/open-ended (0.00s)1836 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1837 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1838 --- PASS: TestParseSingleRange/single_byte (0.00s)1839 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1840 --- PASS: TestParseSingleRange/suffix (0.00s)1841 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1842 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1843 --- PASS: TestParseSingleRange/closed (0.00s)1844 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1845 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1846 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1847 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1848=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18492026/10/20 08:16:15 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=018502026/10/20 08:16:15 INFO Vacuumed table table=pending_closures18512026/10/20 08:16:15 INFO Vacuumed table table=pending_objects18522026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads1853=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18542026/10/20 08:16:15 INFO Vacuumed table table=closures18552026/10/20 08:16:15 INFO Vacuumed table table=objects18562026/10/20 08:16:15 INFO Aborted multipart uploads count=0 kept=018572026/10/20 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period18582026/10/20 08:16:15 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=018592026/10/20 08:16:15 INFO Vacuumed table table=pending_closures18602026/10/20 08:16:15 INFO Vacuumed table table=pending_objects18612026/10/20 08:16:15 INFO Vacuumed table table=multipart_uploads18622026/10/20 08:16:15 INFO Vacuumed table table=closures18632026/10/20 08:16:15 INFO Vacuumed table table=objects1864--- PASS: TestPushDedupSurvivesConcurrentGC (0.36s)1865=== CONT TestPush_RejectsBadRequests/root_not_in_objects18662026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes1867=== CONT TestPush_RejectsBadRequests/no_objects18682026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes1869=== CONT TestPush_RejectsBadRequests/no_roots18702026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes1871=== CONT TestPush_RejectsBadRequests/bad_root18722026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes1873=== CONT TestServerTLSConfig/no_client_CA1874=== CONT TestServerTLSConfig/not_a_PEM_file1875--- PASS: TestPush_RejectsBadRequests (0.86s)1876 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1877 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1878 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1879 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1880=== CONT TestServerTLSConfig/missing_CA_file1881--- PASS: TestServerTLSConfig (0.00s)1882 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1883 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1884 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1885=== CONT TestGCEndsOnShutdown/before_the_run1886--- PASS: TestCacheStatsHandler (0.26s)1887=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18882026/10/20 08:16:15 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18892026/10/20 08:16:15 WARN mTLS auth: bound subjects configured but subject DN unavailable18902026/10/20 08:16:15 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1891--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.28s)1892=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1893=== NAME TestClientCADerivations1894 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1272849240/001/store/nvp8jny7abhc4pdlalx0ybqw2d7rabyj-ca-test1895--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.33s)1896=== CONT TestResolveDBConnectionString/flag_wins1897=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1898=== CONT TestResolveDBConnectionString/nothing_configured1899=== CONT TestResolveDBConnectionString/file_when_flag_empty1900=== CONT TestResolveDBConnectionString/missing_file_is_an_error1901=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1902--- PASS: TestResolveDBConnectionString (0.00s)1903 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1904 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1905 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1906 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1907 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1908=== NAME TestClientCADerivations1909 client_ca_test.go:139: Found 1 dependencies (including self)1910--- PASS: TestReadRedirectKeepsNarinfoProxied (0.30s)1911=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1912--- PASS: TestReadRedirectNar (0.33s)1913=== CONT TestClientErrorHandling/InvalidStorePath1914--- PASS: TestService_ReadAuthMiddleware (0.33s)1915=== CONT TestClientErrorHandling/ServerNotAvailable19162026/10/20 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures19172026/10/20 08:16:15 INFO Received push request method=POST path=/api/pushes19182026/10/20 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19192026/10/20 08:16:15 INFO Uploading nvp8jny7abhc4pdlalx0ybqw2d7rabyj-ca-test (144B)19202026/10/20 08:16:15 WARN Failed to register uploaded object key=nvp8jny7abhc4pdlalx0ybqw2d7rabyj.ls error="server returned 404: 404 page not found\n"19212026/10/20 08:16:15 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/present19222026/10/20 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19232026/10/20 08:16:15 WARN Failed to register uploaded object key=log/40b187ilrnpz2sb28bb0h9mar6q9sf8c-ca-test.drv error="server returned 404: 404 page not found\n"19242026/10/20 08:16:15 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19252026/10/20 08:16:15 INFO Signed narinfos id=1 count=119262026/10/20 08:16:15 INFO Uploading 1 narinfos19272026/10/20 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete19282026/10/20 08:16:15 WARN Failed to register uploaded object key=nvp8jny7abhc4pdlalx0ybqw2d7rabyj.narinfo error="server returned 404: 404 page not found\n"1929=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1930=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1931=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1932=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1933=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1934=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1935=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1936=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1937=== CONT TestClientErrorHandling/InvalidAuthToken19382026/10/20 08:16:15 INFO Completed push id=1 objects=4 duration=9.502569ms19392026/10/20 08:16:15 INFO Upload complete. (115ms)1940=== NAME TestClientCADerivations1941 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1272849240/001/store/nvp8jny7abhc4pdlalx0ybqw2d7rabyj-ca-test1942 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1943 Compression: zstd1944 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1945 NarSize: 1441946 References: 1947 Deriver: /build/TestClientCADerivations1272849240/001/store/40b187ilrnpz2sb28bb0h9mar6q9sf8c-ca-test.drv1948 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1949 client_ca_test.go:185: Checking for realisation files in S3...1950 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1951 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1952=== CONT TestCacheConfigHandler/full_config,_no_issuer1953=== CONT TestCacheConfigHandler/no_signing_keys1954=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1955=== CONT TestCacheConfigHandler/no_cache_url_configured1956--- PASS: TestCacheConfigHandler (0.00s)1957 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1958 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1959 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1960 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1961=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1962=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19632026/10/20 08:16:15 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]1964=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1965=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19662026/10/20 08:16:15 WARN Authentication failed token_preview=eyJhbGciOi...__qhVRRiIg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1967--- PASS: TestService_AuthMiddleware_OIDC (0.45s)1968 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1969 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1970 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1971 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1972=== RUN TestService_RequireScope_OIDC/builder_may_write1973=== PAUSE TestService_RequireScope_OIDC/builder_may_write19742026/10/20 08:16:16 WARN Request failed, retrying attempt=2 backoff=192.894687ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1975=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1976=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1977=== RUN TestService_RequireScope_OIDC/ops_may_admin1978=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1979=== RUN TestService_RequireScope_OIDC/ops_may_not_write1980=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1981=== RUN TestService_RequireScope_OIDC/reader_may_not_write1982=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1983=== RUN TestService_RequireScope_OIDC/static_token_may_admin1984=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1985=== RUN TestService_RequireScope_OIDC/static_token_may_write1986=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1987=== RUN TestService_RequireScope_OIDC/reader_may_read1988=== PAUSE TestService_RequireScope_OIDC/reader_may_read1989=== RUN TestService_RequireScope_OIDC/writer_implies_read1990=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1991=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1992=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1993=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1994=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1995=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1996=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1997=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1998=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1999=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2000=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2001=== CONT TestService_RequireScope_OIDC/builder_may_write2002=== CONT TestService_RequireScope_OIDC/reader_may_read2003=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2004=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2005=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc20062026/10/20 08:16:16 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]2007=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2008=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2009=== CONT TestService_RequireScope_OIDC/writer_implies_read2010=== CONT TestService_RequireScope_OIDC/reader_may_not_write2011=== CONT TestService_RequireScope_OIDC/static_token_may_write2012=== CONT TestService_RequireScope_OIDC/static_token_may_admin2013=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2014=== CONT TestService_RequireScope_OIDC/ops_may_not_write2015=== CONT TestService_RequireScope_OIDC/ops_may_admin2016--- PASS: TestService_RequireScope_OIDC (0.57s)2017 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2018 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2026 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2027 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2028 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2029 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2030 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)20312026/10/20 08:16:16 INFO lead: released remote=192.0.2.1:123420322026/10/20 08:16:16 INFO Aborted multipart uploads count=0 kept=020332026/10/20 08:16:16 WARN Force mode enabled - objects will be deleted immediately without grace period2034=== NAME TestClientCADerivations2035 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2036 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2037 error: binary cache 's3://bucket82?endpoint=http://localhost:44917®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1272849240/001/store'2038 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12039--- PASS: TestClientCADerivations (0.67s)20402026/10/20 08:16:16 INFO Aborted multipart uploads count=0 kept=020412026/10/20 08:16:16 WARN Force mode enabled - objects will be deleted immediately without grace period20422026/10/20 08:16:16 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:44917/bucket96/?delete=\": context canceled"20432026/10/20 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures2044--- PASS: TestGCEndsOnShutdown (0.00s)2045 --- PASS: TestGCEndsOnShutdown/before_the_run (0.33s)2046 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.38s)2047 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.40s)20482026/10/20 08:16:16 INFO Aborted multipart uploads count=0 kept=020492026/10/20 08:16:16 INFO lead: acquired remote=192.0.2.1:12342050--- PASS: TestDeleteClosuresRacingPins (1.53s)20512026/10/20 08:16:16 WARN Force mode enabled - objects will be deleted immediately without grace period20522026/10/20 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures20532026/10/20 08:16:16 INFO Aborted multipart uploads count=0 kept=020542026/10/20 08:16:16 WARN Force mode enabled - objects will be deleted immediately without grace period20552026/10/20 08:16:16 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=020562026/10/20 08:16:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020572026/10/20 08:16:16 INFO Vacuumed table table=pending_closures20582026/10/20 08:16:16 INFO Vacuumed table table=pending_objects20592026/10/20 08:16:16 INFO Vacuumed table table=multipart_uploads20602026/10/20 08:16:16 INFO Vacuumed table table=closures20612026/10/20 08:16:16 INFO Vacuumed table table=pending_closures20622026/10/20 08:16:16 INFO Vacuumed table table=pending_objects20632026/10/20 08:16:16 INFO Vacuumed table table=multipart_uploads20642026/10/20 08:16:16 INFO Vacuumed table table=objects20652026/10/20 08:16:16 INFO Vacuumed table table=closures20662026/10/20 08:16:16 INFO Vacuumed table table=objects2067--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2068 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.32s)2069 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.37s)20702026/10/20 08:16:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20712026/10/20 08:16:16 WARN Request failed, retrying attempt=3 backoff=374.276398ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2072=== NAME TestOrphanedObjectsGCStressTest2073 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains20742026/10/20 08:16:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2075 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2076--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2077 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)2078 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)2079 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.69s)2080--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2081 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.79s)2082 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.83s)20832026/10/20 08:16:16 WARN Request failed, retrying attempt=4 backoff=840.727698ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20842026/10/20 08:16:16 INFO lead: released remote=192.0.2.1:12342085--- PASS: TestLeadEndsOnShutdown (1.29s)2086--- PASS: TestPendingClosureWriteTimeout (0.08s)2087 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2088 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2089 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2090 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.13s)20912026/10/20 08:16:17 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02092=== NAME TestClientIntegration2093 client_integration_test.go:323: Objects in database after GC:2094 client_integration_test.go:323: Successfully deleted all objects with GC --force2095--- PASS: TestClientIntegration (2.78s)20962026/10/20 08:16:17 INFO lead: released remote=192.0.2.1:12342097--- PASS: TestLeadElectsOneAndHandsOver (2.88s)2098=== NAME TestOrphanedObjectsGCStressTest2099 orphaned_objects_gc_test.go:503: Stress test completed successfully:2100 orphaned_objects_gc_test.go:504: - Active objects preserved: 202101 orphaned_objects_gc_test.go:505: - Objects deleted: 2102102 orphaned_objects_gc_test.go:506: - Total GC'd: 2102103--- PASS: TestOrphanedObjectsGCStressTest (3.69s)21042026/10/20 08:16:17 WARN Request failed, retrying attempt=5 backoff=1.468890208s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21052026/10/20 08:16:17 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021062026/10/20 08:16:17 INFO Received create pin request method=POST path=/api/pins/myapp21072026/10/20 08:16:17 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3839828102/001/store/gs78sy666jnvqiwhrkygqm7c1cjfwsys-pinned-file.txt narinfo_key=gs78sy666jnvqiwhrkygqm7c1cjfwsys.narinfo21082026/10/20 08:16:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures21092026/10/20 08:16:17 INFO Garbage collection started21102026/10/20 08:16:17 INFO Aborted multipart uploads count=0 kept=021112026/10/20 08:16:17 WARN Force mode enabled - objects will be deleted immediately without grace period21122026/10/20 08:16:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021132026/10/20 08:16:17 INFO Vacuumed table table=pending_closures21142026/10/20 08:16:17 INFO Vacuumed table table=pending_objects21152026/10/20 08:16:17 INFO Vacuumed table table=multipart_uploads21162026/10/20 08:16:17 INFO Vacuumed table table=closures21172026/10/20 08:16:17 INFO Vacuumed table table=objects2118--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.10s)21192026/10/20 08:16:18 WARN Rate limiter enabled after throttle name=s3-test rate=521202026/10/20 08:16:18 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2121=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2122 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102123 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002124--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.21s)21252026/10/20 08:16:18 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-config21262026/10/20 08:16:19 WARN Request failed, retrying attempt=2 backoff=207.412411ms 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:16:19 WARN Request failed, retrying attempt=3 backoff=391.661674ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2128--- PASS: TestConnectWaitsForAPeerMigration (5.16s)2129=== NAME TestPinProtectsFromGC2130 client_integration_test.go:840: Pin successfully protected closure from garbage collection2131--- PASS: TestPinProtectsFromGC (4.85s)21322026/10/20 08:16:19 WARN Request failed, retrying attempt=4 backoff=837.278489ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21332026/10/20 08:16:20 INFO Aborted multipart uploads count=1 kept=021342026/10/20 08:16:20 INFO Received cleanup request method=DELETE path=/api/pending_closures21352026/10/20 08:16:20 INFO Aborted multipart uploads count=1 kept=02136--- PASS: TestPendingCleanupUsesOneCutoff (6.68s)21372026/10/20 08:16:20 WARN Request failed, retrying attempt=5 backoff=1.713022591s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21382026/10/20 08:16:22 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"21392026/10/20 08:16:22 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-config21402026/10/20 08:16:22 WARN Request failed, retrying attempt=2 backoff=194.705553ms 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:16:22 WARN Request failed, retrying attempt=3 backoff=392.047147ms 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:16:22 WARN Request failed, retrying attempt=4 backoff=797.776046ms 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:16:23 WARN Request failed, retrying attempt=5 backoff=1.684791036s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21442026/10/20 08:16:25 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_closures21452026/10/20 08:16:25 WARN Request failed, retrying attempt=2 backoff=206.70997ms 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:16:25 WARN Request failed, retrying attempt=3 backoff=439.165141ms 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:16:26 WARN Request failed, retrying attempt=4 backoff=737.721209ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21482026/10/20 08:16:26 WARN Request failed, retrying attempt=5 backoff=1.498470796s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2149--- PASS: TestClientErrorHandling (0.00s)2150 --- PASS: TestClientErrorHandling/InvalidStorePath (0.31s)2151 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.30s)2152 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.53s)2153PASS21542026-10-20 08:16:28.671 UTC [130] LOG: received smart shutdown request21552026-10-20 08:16:28.676 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 121562026-10-20 08:16:28.688 UTC [135] LOG: shutting down21572026-10-20 08:16:28.689 UTC [135] LOG: checkpoint starting: shutdown immediate21582026-10-20 08:16:30.281 UTC [135] LOG: checkpoint complete: wrote 10903 buffers (66.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.428 s, sync=1.125 s, total=1.594 s; sync files=34045, longest=0.135 s, average=0.001 s; distance=531514 kB, estimate=531514 kB; lsn=0/21E748B8, redo lsn=0/21E748B821592026-10-20 08:16:30.342 UTC [130] LOG: database system is shut down2160Running OIDC tests...2161=== RUN TestAudienceForIssuer2162=== PAUSE TestAudienceForIssuer2163=== RUN TestGlobMatch2164=== PAUSE TestGlobMatch2165=== RUN TestValidateToken_ValidToken2166=== PAUSE TestValidateToken_ValidToken2167=== RUN TestValidateToken_WrongAudience2168=== PAUSE TestValidateToken_WrongAudience2169=== RUN TestValidateToken_Expired2170=== PAUSE TestValidateToken_Expired2171=== RUN TestValidateToken_BoundClaimsMismatch2172=== PAUSE TestValidateToken_BoundClaimsMismatch2173=== RUN TestValidateToken_BoundSubjectMismatch2174=== PAUSE TestValidateToken_BoundSubjectMismatch2175=== RUN TestValidateToken_MultipleProviders2176=== PAUSE TestValidateToken_MultipleProviders2177=== RUN TestValidateToken_NoMatchingProvider2178=== PAUSE TestValidateToken_NoMatchingProvider2179=== RUN TestValidateToken_KubernetesServiceAccount2180=== PAUSE TestValidateToken_KubernetesServiceAccount2181=== RUN TestNewValidator_KubernetesRequiresCA2182=== PAUSE TestNewValidator_KubernetesRequiresCA2183=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2184=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2185=== RUN TestPins_ReservedForMatchingRule2186=== PAUSE TestPins_ReservedForMatchingRule2187=== RUN TestPins_TopLevelShorthand2188=== PAUSE TestPins_TopLevelShorthand2189=== RUN TestPins_ConfigValidation2190=== PAUSE TestPins_ConfigValidation2191=== RUN TestScopes_LegacyProviderDefaultsToWrite2192=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2193=== RUN TestScopes_Rules2194=== PAUSE TestScopes_Rules2195=== RUN TestScopes_ConfigValidation2196=== PAUSE TestScopes_ConfigValidation2197=== CONT TestAudienceForIssuer2198=== CONT TestValidateToken_KubernetesServiceAccount2199=== CONT TestPins_ReservedForMatchingRule2200--- PASS: TestAudienceForIssuer (0.00s)2201=== CONT TestValidateToken_NoMatchingProvider2202=== CONT TestPins_ConfigValidation2203=== CONT TestValidateToken_MultipleProviders2204=== CONT TestValidateToken_BoundSubjectMismatch2205=== CONT TestValidateToken_BoundClaimsMismatch2206=== CONT TestValidateToken_Expired2207=== CONT TestScopes_ConfigValidation2208=== CONT TestValidateToken_WrongAudience2209=== CONT TestValidateToken_ValidToken2210=== CONT TestScopes_Rules2211=== CONT TestGlobMatch2212=== RUN TestGlobMatch/foo_foo2213=== CONT TestScopes_LegacyProviderDefaultsToWrite2214=== PAUSE TestGlobMatch/foo_foo2215=== RUN TestGlobMatch/foo_bar2216=== PAUSE TestGlobMatch/foo_bar2217=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2218=== CONT TestNewValidator_KubernetesRequiresCA2219--- PASS: TestPins_ConfigValidation (0.00s)2220--- PASS: TestScopes_ConfigValidation (0.00s)2221=== CONT TestPins_TopLevelShorthand2222=== RUN TestGlobMatch/*_2223=== PAUSE TestGlobMatch/*_2224=== RUN TestGlobMatch/*_anything2225=== PAUSE TestGlobMatch/*_anything2226=== RUN TestGlobMatch/foo*_foo2227=== PAUSE TestGlobMatch/foo*_foo2228=== RUN TestGlobMatch/foo*_foobar2229=== PAUSE TestGlobMatch/foo*_foobar2230=== RUN TestGlobMatch/foo*_bar2231=== PAUSE TestGlobMatch/foo*_bar2232=== RUN TestGlobMatch/*bar_bar2233=== PAUSE TestGlobMatch/*bar_bar2234=== RUN TestGlobMatch/*bar_foobar2235=== PAUSE TestGlobMatch/*bar_foobar2236=== RUN TestGlobMatch/*bar_foo2237=== PAUSE TestGlobMatch/*bar_foo2238=== RUN TestGlobMatch/foo*bar_foobar2239=== PAUSE TestGlobMatch/foo*bar_foobar2240=== RUN TestGlobMatch/foo*bar_foo123bar2241=== PAUSE TestGlobMatch/foo*bar_foo123bar2242=== RUN TestGlobMatch/foo*bar_foobarbaz2243=== PAUSE TestGlobMatch/foo*bar_foobarbaz2244=== RUN TestGlobMatch/*/*_foo/bar2245=== PAUSE TestGlobMatch/*/*_foo/bar2246=== RUN TestGlobMatch/*/*_foo2247=== PAUSE TestGlobMatch/*/*_foo2248=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2249=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2250=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02251=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02252=== RUN TestGlobMatch/refs/*/main_refs/heads/main2253=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2254=== RUN TestGlobMatch/fo?_foo2255=== PAUSE TestGlobMatch/fo?_foo2256=== RUN TestGlobMatch/fo?_fo2257=== PAUSE TestGlobMatch/fo?_fo2258=== RUN TestGlobMatch/fo?_fooo2259=== PAUSE TestGlobMatch/fo?_fooo2260=== RUN TestGlobMatch/?oo_foo2261=== PAUSE TestGlobMatch/?oo_foo2262=== RUN TestGlobMatch/?oo_boo2263=== PAUSE TestGlobMatch/?oo_boo2264=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2265=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2266=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2267=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2268=== CONT TestGlobMatch/foo_foo2269=== CONT TestGlobMatch/fo?_foo2270=== CONT TestGlobMatch/refs/*/main_refs/heads/main2271=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02272=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2273=== CONT TestGlobMatch/*/*_foo2274=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2275=== CONT TestGlobMatch/foo*_foobar2276=== CONT TestGlobMatch/fo?_fo2277=== CONT TestGlobMatch/*_anything2278=== CONT TestGlobMatch/*/*_foo/bar2279=== CONT TestGlobMatch/foo_bar2280=== CONT TestGlobMatch/foo*bar_foobarbaz2281=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2282=== CONT TestGlobMatch/?oo_foo2283=== CONT TestGlobMatch/fo?_fooo2284=== CONT TestGlobMatch/?oo_boo2285=== CONT TestGlobMatch/foo*bar_foobar2286=== CONT TestGlobMatch/*bar_foo2287=== CONT TestGlobMatch/*bar_foobar2288=== CONT TestGlobMatch/*bar_bar2289=== CONT TestGlobMatch/foo*_bar2290=== CONT TestGlobMatch/foo*_foo2291=== CONT TestGlobMatch/*_2292=== CONT TestGlobMatch/foo*bar_foo123bar2293--- PASS: TestGlobMatch (0.00s)2294 --- PASS: TestGlobMatch/foo_foo (0.00s)2295 --- PASS: TestGlobMatch/fo?_foo (0.00s)2296 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2297 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2298 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2299 --- PASS: TestGlobMatch/*/*_foo (0.00s)2300 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2301 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2302 --- PASS: TestGlobMatch/fo?_fo (0.00s)2303 --- PASS: TestGlobMatch/*_anything (0.00s)2304 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2305 --- PASS: TestGlobMatch/foo_bar (0.00s)2306 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2307 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2308 --- PASS: TestGlobMatch/?oo_foo (0.00s)2309 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2310 --- PASS: TestGlobMatch/?oo_boo (0.00s)2311 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2312 --- PASS: TestGlobMatch/*bar_foo (0.00s)2313 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2314 --- PASS: TestGlobMatch/*bar_bar (0.00s)2315 --- PASS: TestGlobMatch/foo*_bar (0.00s)2316 --- PASS: TestGlobMatch/foo*_foo (0.00s)2317 --- PASS: TestGlobMatch/*_ (0.00s)2318 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)23192026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40867/oidc23202026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40211/oidc2321--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)23222026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38769/oidc2323--- PASS: TestScopes_Rules (0.04s)2324--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.04s)23252026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43961/oidc2326--- PASS: TestValidateToken_WrongAudience (0.05s)23272026/10/20 08:16:32 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232328--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)23292026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32925/oidc23302026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46043/oidc2331--- PASS: TestValidateToken_Expired (0.07s)2332--- PASS: TestValidateToken_ValidToken (0.07s)23332026/10/20 08:16:32 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:337632334--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)23352026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42029/oidc2336--- PASS: TestPins_TopLevelShorthand (0.09s)23372026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43989/oidc2338--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)23392026/10/20 08:16:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45211/oidc2340--- PASS: TestPins_ReservedForMatchingRule (0.12s)23412026/10/20 08:16:32 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33419/oidc2342--- PASS: TestValidateToken_NoMatchingProvider (0.14s)23432026/10/20 08:16:32 http: TLS handshake error from 127.0.0.1:47522: remote error: tls: bad certificate2344--- PASS: TestNewValidator_KubernetesRequiresCA (0.18s)23452026/10/20 08:16:32 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:34175/oidc23462026/10/20 08:16:32 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:41359/oidc2347--- PASS: TestValidateToken_MultipleProviders (0.22s)2348PASS2349Running hook tests...2350=== RUN TestSendPathsEmpty2351=== PAUSE TestSendPathsEmpty2352=== RUN TestQueueEnqueueAndFetch2353=== PAUSE TestQueueEnqueueAndFetch2354=== RUN TestQueueDeduplication2355=== PAUSE TestQueueDeduplication2356=== RUN TestQueueRemove2357=== PAUSE TestQueueRemove2358=== RUN TestQueueFetchBatchLimit2359=== PAUSE TestQueueFetchBatchLimit2360=== RUN TestQueueRetryMovesToBack2361=== PAUSE TestQueueRetryMovesToBack2362=== RUN TestQueueFetchRemoveLifecycle2363=== PAUSE TestQueueFetchRemoveLifecycle2364=== RUN TestQueueConcurrentWriters2365=== PAUSE TestQueueConcurrentWriters2366=== RUN TestQueueRemoveLargeClosure2367=== PAUSE TestQueueRemoveLargeClosure2368=== RUN TestServerClientIntegration2369--- PASS: TestServerClientIntegration (0.00s)2370=== RUN TestServerQueueError23712026/10/20 08:16:32 ERROR Failed to queue paths error="permission denied" count=12372--- PASS: TestServerQueueError (0.00s)2373=== RUN TestGetListenerSocketActivation2374 server_test.go:219: === RUN TestGetListenerSocketActivation2375 --- PASS: TestGetListenerSocketActivation (0.00s)2376 PASS2377 2378--- PASS: TestGetListenerSocketActivation (0.01s)2379=== RUN TestDrainIsolatesPoisonPath2380=== PAUSE TestDrainIsolatesPoisonPath2381=== RUN TestRunNotBlockedByPoisonHead2382=== PAUSE TestRunNotBlockedByPoisonHead2383=== RUN TestDrainGivesUpWhenServerDown2384=== PAUSE TestDrainGivesUpWhenServerDown2385=== RUN TestFailedPathPrunedByLaterClosure2386=== PAUSE TestFailedPathPrunedByLaterClosure2387=== RUN TestWorkerUploadsAndRemoves2388=== PAUSE TestWorkerUploadsAndRemoves2389=== RUN TestWorkerSkipsGCdPaths2390=== PAUSE TestWorkerSkipsGCdPaths2391=== RUN TestWorkerPrunesClosureDeps2392=== PAUSE TestWorkerPrunesClosureDeps2393=== RUN TestDrainTimeout2394=== PAUSE TestDrainTimeout2395=== CONT TestSendPathsEmpty2396=== CONT TestRunNotBlockedByPoisonHead2397=== CONT TestDrainIsolatesPoisonPath2398=== CONT TestDrainTimeout2399=== CONT TestWorkerPrunesClosureDeps2400=== CONT TestDrainGivesUpWhenServerDown2401--- PASS: TestSendPathsEmpty (0.00s)2402=== CONT TestFailedPathPrunedByLaterClosure2403=== CONT TestQueueRemoveLargeClosure2404=== CONT TestQueueConcurrentWriters2405=== CONT TestWorkerSkipsGCdPaths2406=== CONT TestQueueFetchRemoveLifecycle2407=== CONT TestQueueRetryMovesToBack2408=== CONT TestQueueFetchBatchLimit2409=== CONT TestQueueRemove2410=== CONT TestQueueDeduplication2411=== CONT TestWorkerUploadsAndRemoves2412=== CONT TestQueueEnqueueAndFetch24132026/10/20 08:16:32 INFO Uploading batch count=424142026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=424152026/10/20 08:16:32 INFO Uploading batch count=124162026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=124172026/10/20 08:16:32 INFO Uploading batch count=224182026/10/20 08:16:32 INFO Upload queue status pending=224192026/10/20 08:16:32 INFO Uploading batch count=124202026/10/20 08:16:32 INFO Upload queue status pending=224212026/10/20 08:16:32 INFO Uploading batch count=224222026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=224232026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4093387971/002/a24242026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3029035016/002/bbb24252026/10/20 08:16:32 INFO Uploading batch count=12426--- PASS: TestQueueFetchBatchLimit (0.02s)2427--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24282026/10/20 08:16:32 INFO Upload queue status pending=32429--- PASS: TestQueueEnqueueAndFetch (0.02s)24302026/10/20 08:16:32 INFO Uploading batch count=124312026/10/20 08:16:32 INFO Uploading batch count=224322026/10/20 08:16:32 INFO Uploading batch count=124332026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=124342026/10/20 08:16:32 INFO Upload queue status pending=224352026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4093387971/002/b24362026/10/20 08:16:32 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2293386628/002/nonexistent2437--- PASS: TestQueueDeduplication (0.02s)2438--- PASS: TestQueueRetryMovesToBack (0.02s)2439--- PASS: TestQueueRemove (0.02s)24402026/10/20 08:16:32 INFO Uploading batch count=124412026/10/20 08:16:32 INFO Uploading batch count=224422026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=224432026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4093387971/002/c24442026/10/20 08:16:32 INFO Uploading batch count=124452026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=12446--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24472026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4093387971/002/d24482026/10/20 08:16:32 INFO Uploading batch count=124492026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=124502026/10/20 08:16:32 INFO Uploading batch count=224512026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=224522026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4093387971/002/e24532026/10/20 08:16:32 INFO Uploading batch count=124542026/10/20 08:16:32 ERROR Upload failed error="upload failed" count=124552026/10/20 08:16:32 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4093387971/002/f24562026/10/20 08:16:32 ERROR Drain finished with paths left in queue remaining=124572026/10/20 08:16:32 ERROR Drain finished with paths left in queue remaining=102458--- PASS: TestDrainIsolatesPoisonPath (0.03s)2459--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2460--- PASS: TestWorkerUploadsAndRemoves (0.03s)2461--- PASS: TestWorkerPrunesClosureDeps (0.04s)2462--- PASS: TestWorkerSkipsGCdPaths (0.04s)2463--- PASS: TestQueueRemoveLargeClosure (0.06s)24642026/10/20 08:16:32 ERROR Upload failed error="context deadline exceeded" count=224652026/10/20 08:16:32 ERROR Drain finished with paths left in queue remaining=42466--- PASS: TestDrainTimeout (0.22s)2467--- PASS: TestQueueConcurrentWriters (0.47s)24682026/10/20 08:16:33 INFO Uploading batch count=124692026/10/20 08:16:33 INFO Uploading batch count=124702026/10/20 08:16:33 INFO Uploading batch count=124712026/10/20 08:16:33 ERROR Upload failed error="upload failed" count=124722026/10/20 08:16:33 INFO Uploading batch count=124732026/10/20 08:16:33 ERROR Upload failed error="upload failed" count=124742026/10/20 08:16:34 INFO Uploading batch count=124752026/10/20 08:16:34 ERROR Upload failed error="upload failed" count=124762026/10/20 08:16:34 INFO Uploading batch count=124772026/10/20 08:16:34 ERROR Upload failed error="upload failed" count=124782026/10/20 08:16:34 ERROR Drain finished with paths left in queue remaining=12479--- PASS: TestRunNotBlockedByPoisonHead (1.59s)2480PASS2481Running signing tests...2482=== RUN TestExternalSigner2483=== PAUSE TestExternalSigner2484=== RUN TestExternalSignerWrongPublicKey2485=== PAUSE TestExternalSignerWrongPublicKey2486=== RUN TestExternalSignerErrors2487=== PAUSE TestExternalSignerErrors2488=== RUN TestExternalSignerRestartsAfterCrash2489=== PAUSE TestExternalSignerRestartsAfterCrash2490=== RUN TestExternalSignerProgramErrorKeepsProcess2491=== PAUSE TestExternalSignerProgramErrorKeepsProcess2492=== RUN TestExternalSignerClose2493=== PAUSE TestExternalSignerClose2494=== RUN TestExternalSignerRejectsInvalidPublicKey2495=== PAUSE TestExternalSignerRejectsInvalidPublicKey2496=== RUN TestExternalSignerCancellation2497=== PAUSE TestExternalSignerCancellation2498=== RUN TestGenerateFingerprint2499=== PAUSE TestGenerateFingerprint2500=== RUN TestParseSigningKey2501=== PAUSE TestParseSigningKey2502=== RUN TestSign2503=== PAUSE TestSign2504=== RUN TestSignBatch2505=== PAUSE TestSignBatch2506=== RUN TestNilKeyPublicKey2507=== PAUSE TestNilKeyPublicKey2508=== RUN TestSignErrors2509=== PAUSE TestSignErrors2510=== CONT TestExternalSigner2511=== CONT TestSignErrors2512=== CONT TestExternalSignerCancellation2513=== CONT TestSign2514=== CONT TestParseSigningKey2515=== CONT TestSignBatch2516=== CONT TestGenerateFingerprint2517=== RUN TestGenerateFingerprint/basic_with_references2518=== CONT TestNilKeyPublicKey2519=== CONT TestExternalSignerErrors2520=== CONT TestExternalSignerRestartsAfterCrash2521=== CONT TestExternalSignerWrongPublicKey2522=== CONT TestExternalSignerRejectsInvalidPublicKey2523=== CONT TestExternalSignerClose2524=== CONT TestExternalSignerProgramErrorKeepsProcess2525=== RUN TestParseSigningKey/valid_32-byte_key2526=== RUN TestExternalSignerErrors/unrequested_key2527=== PAUSE TestExternalSignerErrors/unrequested_key2528=== RUN TestExternalSignerErrors/program_error2529=== PAUSE TestExternalSignerErrors/program_error2530=== RUN TestExternalSignerErrors/exit_on_request2531=== PAUSE TestExternalSignerErrors/exit_on_request2532=== RUN TestExternalSignerErrors/missing_signatures2533=== PAUSE TestExternalSignerErrors/missing_signatures2534=== RUN TestExternalSignerRejectsInvalidPublicKey/#002535=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002536--- PASS: TestSign (0.00s)2537=== PAUSE TestGenerateFingerprint/basic_with_references2538=== PAUSE TestParseSigningKey/valid_32-byte_key2539=== RUN TestSignErrors/nil_key2540=== RUN TestExternalSignerErrors/null_signatures2541=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2542--- PASS: TestSignBatch (0.00s)2543--- PASS: TestNilKeyPublicKey (0.00s)2544=== RUN TestGenerateFingerprint/no_references2545=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2546=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2547=== RUN TestParseSigningKey/no_colon2548=== PAUSE TestParseSigningKey/no_colon2549=== RUN TestParseSigningKey/empty_name2550=== PAUSE TestParseSigningKey/empty_name2551=== PAUSE TestExternalSignerErrors/null_signatures2552=== PAUSE TestSignErrors/nil_key2553=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2554=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2555=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2556=== PAUSE TestGenerateFingerprint/no_references2557=== RUN TestParseSigningKey/invalid_base642558=== PAUSE TestParseSigningKey/invalid_base642559=== RUN TestExternalSignerErrors/exit_at_startup2560=== PAUSE TestExternalSignerErrors/exit_at_startup2561=== RUN TestSignErrors/nil_narinfo2562=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2563=== PAUSE TestSignErrors/nil_narinfo2564=== RUN TestSignErrors/invalid_narinfo2565=== PAUSE TestSignErrors/invalid_narinfo2566=== RUN TestSignErrors/canceled2567=== PAUSE TestSignErrors/canceled2568=== CONT TestSignErrors/nil_key2569--- PASS: TestExternalSignerWrongPublicKey (0.00s)2570=== RUN TestExternalSignerErrors/wrong_shape2571=== PAUSE TestExternalSignerErrors/wrong_shape2572=== RUN TestExternalSignerErrors/wrong_id2573=== PAUSE TestExternalSignerErrors/wrong_id2574=== RUN TestExternalSignerErrors/null2575=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2576=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2577=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2578=== RUN TestParseSigningKey/wrong_length2579=== CONT TestSignErrors/canceled2580=== CONT TestSignErrors/nil_narinfo2581=== CONT TestSignErrors/invalid_narinfo2582--- PASS: TestExternalSignerClose (0.00s)2583--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2584=== PAUSE TestExternalSignerErrors/null2585=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2586=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2587=== CONT TestExternalSignerRejectsInvalidPublicKey/#002588=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2589=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2590=== PAUSE TestParseSigningKey/wrong_length2591--- PASS: TestSignErrors (0.01s)2592 --- PASS: TestSignErrors/nil_key (0.00s)2593 --- PASS: TestSignErrors/canceled (0.00s)2594 --- PASS: TestSignErrors/nil_narinfo (0.00s)2595 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2596=== RUN TestExternalSignerErrors/too_few_signatures2597=== PAUSE TestExternalSignerErrors/too_few_signatures2598=== RUN TestExternalSignerErrors/missing_signature_name2599=== PAUSE TestExternalSignerErrors/missing_signature_name2600=== RUN TestExternalSignerErrors/wrong_signature_name2601=== PAUSE TestExternalSignerErrors/wrong_signature_name2602=== RUN TestExternalSignerErrors/invalid_signature_base642603=== PAUSE TestExternalSignerErrors/invalid_signature_base642604=== RUN TestExternalSignerErrors/wrong_signature_length2605=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2606=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2607=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2608=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2609=== RUN TestGenerateFingerprint/invalid_nar_hash_length2610=== CONT TestParseSigningKey/valid_32-byte_key2611=== CONT TestParseSigningKey/wrong_length2612=== CONT TestParseSigningKey/invalid_base642613=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2614=== CONT TestParseSigningKey/no_colon2615=== CONT TestParseSigningKey/empty_name2616--- PASS: TestExternalSigner (0.01s)2617=== PAUSE TestExternalSignerErrors/wrong_signature_length2618=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2619--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.01s)2620 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2621 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2622 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2623 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2624 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2625=== RUN TestExternalSignerErrors/invalid_JSON2626=== RUN TestGenerateFingerprint/invalid_store_path_prefix2627=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2628=== RUN TestGenerateFingerprint/invalid_reference_prefix2629=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2630=== CONT TestGenerateFingerprint/basic_with_references2631--- PASS: TestParseSigningKey (0.01s)2632 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2633 --- PASS: TestParseSigningKey/wrong_length (0.00s)2634 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2635 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2636 --- PASS: TestParseSigningKey/no_colon (0.00s)2637 --- PASS: TestParseSigningKey/empty_name (0.00s)2638=== CONT TestGenerateFingerprint/invalid_nar_hash_length2639=== PAUSE TestExternalSignerErrors/invalid_JSON2640=== RUN TestExternalSignerErrors/wrong_signatures_shape2641=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2642=== CONT TestExternalSignerErrors/unrequested_key2643=== CONT TestGenerateFingerprint/invalid_reference_prefix2644=== CONT TestExternalSignerErrors/too_few_signatures2645=== CONT TestGenerateFingerprint/invalid_store_path_prefix2646=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2647=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2648=== CONT TestGenerateFingerprint/no_references2649--- PASS: TestGenerateFingerprint (0.01s)2650 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2651 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2652 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2653 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2654 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2655 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2656 --- PASS: TestGenerateFingerprint/no_references (0.00s)2657=== CONT TestExternalSignerErrors/wrong_signatures_shape2658=== CONT TestExternalSignerErrors/invalid_JSON2659=== CONT TestExternalSignerErrors/wrong_signature_length2660=== CONT TestExternalSignerErrors/invalid_signature_base642661=== CONT TestExternalSignerErrors/wrong_signature_name2662=== CONT TestExternalSignerErrors/missing_signature_name2663=== CONT TestExternalSignerErrors/exit_at_startup2664=== CONT TestExternalSignerErrors/missing_signatures2665=== CONT TestExternalSignerErrors/null2666=== CONT TestExternalSignerErrors/null_signatures2667=== CONT TestExternalSignerErrors/wrong_id2668=== CONT TestExternalSignerErrors/exit_on_request2669=== CONT TestExternalSignerErrors/wrong_shape2670=== CONT TestExternalSignerErrors/program_error2671--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2672--- PASS: TestExternalSignerCancellation (0.02s)2673--- PASS: TestExternalSignerErrors (0.01s)2674 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2675 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2676 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2677 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2678 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2679 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2680 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2681 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2682 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2683 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2684 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2685 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2686 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2687 --- PASS: TestExternalSignerErrors/null (0.01s)2688 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2689 --- PASS: TestExternalSignerErrors/program_error (0.01s)2690PASS2691Running OpenBao signer tests...2692=== RUN TestSign2693=== PAUSE TestSign2694=== RUN TestSignErrors2695=== PAUSE TestSignErrors2696=== RUN TestServe2697=== PAUSE TestServe2698=== RUN TestServeRejectsGarbage2699=== PAUSE TestServeRejectsGarbage2700=== CONT TestSign2701=== CONT TestServeRejectsGarbage2702--- PASS: TestServeRejectsGarbage (0.00s)2703=== CONT TestServe2704=== CONT TestSignErrors2705=== RUN TestSignErrors/http_error2706=== PAUSE TestSignErrors/http_error2707=== RUN TestSignErrors/invalid_json2708=== PAUSE TestSignErrors/invalid_json2709--- PASS: TestServe (0.00s)2710=== RUN TestSignErrors/no_prefix2711=== PAUSE TestSignErrors/no_prefix2712=== RUN TestSignErrors/invalid_base642713=== PAUSE TestSignErrors/invalid_base642714=== CONT TestSignErrors/http_error2715=== CONT TestSignErrors/no_prefix2716=== CONT TestSignErrors/invalid_json2717=== CONT TestSignErrors/invalid_base642718--- PASS: TestSign (0.01s)2719--- PASS: TestSignErrors (0.00s)2720 --- PASS: TestSignErrors/no_prefix (0.01s)2721 --- PASS: TestSignErrors/invalid_base64 (0.01s)2722 --- PASS: TestSignErrors/invalid_json (0.01s)2723 --- PASS: TestSignErrors/http_error (0.01s)2724PASS