niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #311
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestShellSplit97=== CONT TestSetClientTLSErrors98--- PASS: TestShellSplit (0.00s)99=== CONT TestClientSignaturesByStorePath100--- PASS: TestClientSignaturesByStorePath (0.00s)101=== CONT TestPathInfoHashCompatibility102=== CONT TestScriptTokenEmptyCommand103=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)104--- PASS: TestScriptTokenEmptyCommand (0.00s)105=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)106=== CONT TestScriptTokenBadJSON107=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon108=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon109=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI110=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI111=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512112=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512113=== CONT TestGetStorePathHash114=== RUN TestGetStorePathHash/valid_store_path115=== PAUSE TestGetStorePathHash/valid_store_path116=== RUN TestGetStorePathHash/basename_without_hyphen_should_error117=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error118=== CONT TestScriptTokenEmptyToken119=== CONT TestScriptTokenCachesUntilRefresh120=== CONT TestScriptTokenNoExpiryRerunsEveryCall121=== CONT TestFileTokenEmpty122=== CONT TestFileTokenMissing123=== CONT TestFileTokenReadsAndCaches124=== CONT TestStaticToken125--- PASS: TestStaticToken (0.00s)126=== CONT TestEncodeNixBase32WithRealHash127=== CONT TestDoWithRetry_BodyReplayedViaGetBody128=== CONT TestResolveStorePath129=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess130=== CONT TestStreamPushRequestLine131=== CONT TestRateLimiterFeedback132=== CONT TestPathInfoCACompatibility133=== CONT TestSetClientTLSDoesNotMutateDefaultTransport134=== CONT TestParsePathInfoJSONMultiplePaths135=== CONT TestStreamPushReportsEveryPath136=== CONT TestParsePathInfoJSON137=== CONT TestUploadMultipart_SupersededByPeer138=== RUN TestParsePathInfoJSON/Nix_format139=== RUN TestRateLimiterFeedback/429_enables_limiter140=== CONT TestStreamPushGivesUpOnDeadServer141=== RUN TestUploadMultipart_SupersededByPeer/exists142=== PAUSE TestParsePathInfoJSON/Nix_format143=== CONT TestStreamPushReportsSignatures144=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error1452026/10/01 09:39:08 WARN Rate limiter enabled after throttle name=server-test rate=5146=== CONT TestConvertHashToNix32147=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error148--- PASS: TestEncodeNixBase32WithRealHash (0.00s)149--- PASS: TestFileTokenEmpty (0.00s)1502026/10/01 09:39:08 ERROR Upload failed error="connection refused" count=201512026/10/01 09:39:08 ERROR Server seems unavailable, giving up on batch untried=17152=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths153=== CONT TestSetClientTLS1542026/10/01 09:39:08 WARN Rate limiter enabled after throttle name=server-test rate=5155=== CONT TestScriptTokenScriptFails156=== CONT TestDumpPathWriterError1572026/10/01 09:39:08 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:457471582026/10/01 09:39:08 ERROR Upload failed error=boom count=1159=== RUN TestPathInfoCACompatibility/null_ca_field160=== PAUSE TestRateLimiterFeedback/429_enables_limiter161=== CONT TestEncodeNixBase32162=== RUN TestParsePathInfoJSON/Lix_format163=== PAUSE TestParsePathInfoJSON/Lix_format164=== PAUSE TestUploadMultipart_SupersededByPeer/exists165=== CONT TestDumpPathMatchesNix166=== RUN TestConvertHashToNix32/SRI_format_to_Nix321672026/10/01 09:39:08 ERROR Upload failed error=boom count=1168--- PASS: TestScriptTokenBadJSON (0.00s)169=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error170=== CONT TestDumpPathSingleFile171=== RUN TestSetClientTLSErrors/missing_cert_file172=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths173=== CONT TestFilterOversizedClosures174=== PAUSE TestPathInfoCACompatibility/null_ca_field175=== CONT TestPartSizeForNAR176--- PASS: TestFileTokenMissing (0.00s)177=== RUN TestEncodeNixBase32/test_string_hash178=== RUN TestRateLimiterFeedback/503_enables_limiter179=== PAUSE TestRateLimiterFeedback/503_enables_limiter180=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32181=== RUN TestParsePathInfoJSON/empty_input182=== RUN TestConvertHashToNix32/already_Nix32_format183=== RUN TestUploadMultipart_SupersededByPeer/missing184=== CONT TestStreamPushIsolatesFailures185=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error186--- PASS: TestFileTokenReadsAndCaches (0.00s)187--- PASS: TestScriptTokenEmptyToken (0.01s)188=== CONT TestShellSplitErrors189=== CONT TestRegisterUploadedObjectReusesConnections190=== PAUSE TestEncodeNixBase32/test_string_hash191=== RUN TestEncodeNixBase32/empty_input192=== PAUSE TestEncodeNixBase32/empty_input193=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter194=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter195=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter1962026/10/01 09:39:08 WARN Rate limiter backed off name=server-test rate=5197=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter1982026/10/01 09:39:08 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:45747199=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)200=== RUN TestPartSizeForNAR/zero_stays_at_minimum201=== CONT TestUploadMultipart_PartsInParallel202=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths203=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths204=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI205=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512206=== CONT TestCaseHackSuffix207=== RUN TestPathInfoCACompatibility/old_string_format_-_text208--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)209=== PAUSE TestSetClientTLSErrors/missing_cert_file210=== RUN TestFilterOversizedClosures/no_limit_keeps_everything211=== CONT TestStreamPushBatchesUnderLoad212--- PASS: TestStreamPushReportsEveryPath (0.00s)213--- PASS: TestDoServerRequestAttachesToken (0.01s)214--- PASS: TestStreamPushReportsSignatures (0.00s)215--- PASS: TestResolveStorePath (0.00s)2162026/10/01 09:39:08 ERROR Upload failed error="bad path" count=3217--- PASS: TestScriptTokenScriptFails (0.00s)218=== PAUSE TestConvertHashToNix32/already_Nix32_format219=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon220=== CONT TestRateLimiterFeedback/429_enables_limiter221=== CONT TestEncodeNixBase32/test_string_hash222=== CONT TestEncodeNixBase32/empty_input223=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter224=== CONT TestGetStorePathHash/valid_store_path225=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter226=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error227=== CONT TestRateLimiterFeedback/503_enables_limiter228=== RUN TestSetClientTLS/rejects_connection_without_client_cert2292026/10/01 09:39:09 WARN Rate limiter enabled after throttle name=server-test rate=5230=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert2312026/10/01 09:39:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:41685232=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA233=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA234=== RUN TestSetClientTLS/preserves_debug_logging_transport235=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths236=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2372026/10/01 09:39:09 WARN Rate limiter backed off name=server-test rate=5238=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text2392026/10/01 09:39:09 WARN Rate limiter enabled after throttle name=server-test rate=5240=== PAUSE TestSetClientTLS/preserves_debug_logging_transport241=== CONT TestSetClientTLS/rejects_connection_without_client_cert2422026/10/01 09:39:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:35095243=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error244=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything2452026/10/01 09:39:09 WARN Rate limiter backed off name=server-test rate=5246=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped247=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped248=== RUN TestFilterOversizedClosures/all_closures_skipped249=== PAUSE TestFilterOversizedClosures/all_closures_skipped250=== CONT TestFilterOversizedClosures/no_limit_keeps_everything251=== CONT TestSetClientTLS/preserves_debug_logging_transport252=== PAUSE TestUploadMultipart_SupersededByPeer/missing253=== CONT TestUploadMultipart_SupersededByPeer/exists254=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum255=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA256=== CONT TestGetStorePathHash/basename_without_hyphen_should_error257--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)258=== RUN TestConvertHashToNix32/invalid_format259=== PAUSE TestParsePathInfoJSON/empty_input260=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive261=== RUN TestSetClientTLSErrors/missing_key_file262=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2632026/10/01 09:39:09 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=2000264=== PAUSE TestConvertHashToNix32/invalid_format265=== CONT TestConvertHashToNix32/SRI_format_to_Nix32266=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive267=== RUN TestPathInfoCACompatibility/new_structured_format_-_text268=== CONT TestConvertHashToNix32/invalid_format269=== CONT TestFilterOversizedClosures/all_closures_skipped270=== CONT TestConvertHashToNix32/already_Nix32_format2712026/10/01 09:39:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50272=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text273=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method274=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method275=== CONT TestPathInfoCACompatibility/null_ca_field276=== CONT TestPathInfoCACompatibility/new_structured_format_-_text277=== CONT TestPathInfoCACompatibility/old_string_format_-_text278=== RUN TestParsePathInfoJSON/whitespace_only279=== PAUSE TestParsePathInfoJSON/whitespace_only280=== RUN TestParsePathInfoJSON/invalid_JSON281=== PAUSE TestParsePathInfoJSON/invalid_JSON282=== CONT TestParsePathInfoJSON/Nix_format283=== CONT TestParsePathInfoJSON/whitespace_only284=== CONT TestParsePathInfoJSON/empty_input285=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive286=== CONT TestUploadMultipart_SupersededByPeer/missing287=== RUN TestPartSizeForNAR/small_stays_at_minimum288=== PAUSE TestPartSizeForNAR/small_stays_at_minimum289=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum290=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum291=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts292=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts293--- PASS: TestShellSplitErrors (0.00s)294--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)295=== PAUSE TestSetClientTLSErrors/missing_key_file296=== RUN TestSetClientTLSErrors/missing_ca_file297=== PAUSE TestSetClientTLSErrors/missing_ca_file298=== RUN TestSetClientTLSErrors/invalid_ca_file299=== PAUSE TestSetClientTLSErrors/invalid_ca_file300=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method301=== CONT TestParsePathInfoJSON/invalid_JSON302=== CONT TestParsePathInfoJSON/Lix_format303=== RUN TestPartSizeForNAR/1_TiB304=== PAUSE TestPartSizeForNAR/1_TiB305--- PASS: TestStreamPushIsolatesFailures (0.00s)306--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)307--- PASS: TestPathInfoHashCompatibility (0.00s)308 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)309 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)310 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)311 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)312=== CONT TestSetClientTLSErrors/missing_cert_file313=== CONT TestSetClientTLSErrors/invalid_ca_file314--- PASS: TestEncodeNixBase32 (0.00s)315 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)316 --- PASS: TestEncodeNixBase32/empty_input (0.00s)317=== CONT TestSetClientTLSErrors/missing_ca_file318=== CONT TestSetClientTLSErrors/missing_key_file319=== RUN TestPartSizeForNAR/5_TiB_S3_max_object320--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.09s)321=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object322=== RUN TestPartSizeForNAR/capped_at_5_GiB323--- PASS: TestUploadMultipart_SupersededByPeer (0.10s)324 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)325 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)326--- PASS: TestGetStorePathHash (0.01s)327 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)328 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)329 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)330 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)331=== PAUSE TestPartSizeForNAR/capped_at_5_GiB332=== CONT TestPartSizeForNAR/zero_stays_at_minimum333=== CONT TestPartSizeForNAR/5_TiB_S3_max_object334=== CONT TestPartSizeForNAR/1_TiB335--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)336 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)337 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)338--- PASS: TestPathInfoCACompatibility (0.10s)339 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)340 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)341 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)342 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)343 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)344--- PASS: TestRateLimiterFeedback (0.01s)345 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)346 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)347 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)348 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)349=== CONT TestPartSizeForNAR/capped_at_5_GiB350=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum351=== CONT TestPartSizeForNAR/small_stays_at_minimum352=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts353--- PASS: TestParsePathInfoJSON (0.10s)354 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)355 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)356 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)357 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)358 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)359--- PASS: TestConvertHashToNix32 (0.09s)360 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)361 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)362 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)363--- PASS: TestFilterOversizedClosures (0.09s)364 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)365 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)366 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)367--- PASS: TestSetClientTLSErrors (0.11s)368 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)369 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)370 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)371 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)372--- PASS: TestPartSizeForNAR (0.10s)373 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)375 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)376 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)377 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)378 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)379 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)3802026/10/01 09:39:09 http: TLS handshake error from 127.0.0.1:42172: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.09s)382 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestStreamPushRequestLine (0.12s)386--- PASS: TestDumpPathSingleFile (0.12s)387--- PASS: TestRegisterUploadedObjectReusesConnections (0.12s)388--- PASS: TestCaseHackSuffix (0.12s)389--- PASS: TestDumpPathWriterError (0.13s)390--- PASS: TestDumpPathMatchesNix (0.17s)391--- PASS: TestStreamPushBatchesUnderLoad (0.19s)392--- PASS: TestUploadMultipart_PartsInParallel (0.70s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)394PASS395Running server tests...396The files belonging to this database system will be owned by user "nixbld".397This user must also own the server process.398399The database cluster will be initialized with locale "C".400The default database encoding has accordingly been set to "SQL_ASCII".401The default text search configuration will be set to "english".402403Data page checksums are enabled.404405creating directory /build/postgres1655669434/data ... ok406creating subdirectories ... ok407selecting dynamic shared memory implementation ... posix408selecting default "max_connections" ... 100409selecting default "shared_buffers" ... 128MB410selecting default time zone ... UTC411creating configuration files ... ok412running bootstrap script ... ok413performing post-bootstrap initialization ... ok414syncing data to disk ... ok415416initdb: warning: enabling "trust" authentication for local connections417initdb: 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.418419Success. You can now start the database server using:420421 pg_ctl -D /build/postgres1655669434/data -l logfile start422423/build/postgres1655669434:5432 - no response4242026-10-01 09:39:10.862 UTC [130] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:39:10.863 UTC [130] LOG: listening on Unix socket "/build/postgres1655669434/.s.PGSQL.5432"4262026-10-01 09:39:10.869 UTC [137] LOG: database system was shut down at 2026-10-01 09:39:10 UTC4272026-10-01 09:39:10.874 UTC [130] LOG: database system is ready to accept connections428/build/postgres1655669434:5432 - accepting connections429{"timestamp":"2026-10-01T09:39:11.16469459Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"cd2068ca-1631-43ea-90fe-7cbe0f32dc18","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(398)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:39:11.361 UTC [567] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:39:11.361 UTC [567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:39:11 OK 20241026095416_initial_model.sql (6.73ms)4762026/10/01 09:39:11 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)4772026/10/01 09:39:11 OK 20251218171726_add_pins.sql (1.9ms)4782026/10/01 09:39:11 OK 20260628120000_add_object_size_and_stats.sql (2.02ms)4792026/10/01 09:39:11 OK 20260905000000_add_claims.sql (2.57ms)4802026/10/01 09:39:11 OK 20260920000000_drop_claims.sql (1.34ms)4812026/10/01 09:39:11 OK 20260923120000_add_pushes.sql (952.94µs)4822026/10/01 09:39:11 goose: successfully migrated database to version: 202609231200004832026/10/01 09:39:11 OK 1_commit_pending_closure.sql (1.58ms)4842026/10/01 09:39:11 OK 2_object_stats_trigger.sql (573.8µs)4852026/10/01 09:39:11 OK 3_commit_push.sql (573.26µs)4862026/10/01 09:39:11 goose: up to current file version: 34872026/10/01 09:39:11 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:39:12 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:39:12 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:39:12 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:39:12.130 UTC [577] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:39:12.130 UTC [577] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:39:12 OK 20241026095416_initial_model.sql (6.52ms)4982026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)4992026/10/01 09:39:12 OK 20251218171726_add_pins.sql (2.14ms)5002026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (2.67ms)5012026/10/01 09:39:12 OK 20260905000000_add_claims.sql (2.32ms)5022026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (1.42ms)5032026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (923.5µs)5042026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200005052026/10/01 09:39:12 OK 1_commit_pending_closure.sql (1.34ms)5062026/10/01 09:39:12 OK 2_object_stats_trigger.sql (507.15µs)5072026/10/01 09:39:12 OK 3_commit_push.sql (676.14µs)5082026/10/01 09:39:12 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestObjectStatsTrigger583=== PAUSE TestObjectStatsTrigger584=== RUN TestOrphanedObjectsGC585=== PAUSE TestOrphanedObjectsGC586=== RUN TestOrphanedObjectsGCStressTest587=== PAUSE TestOrphanedObjectsGCStressTest588=== RUN TestCreatePin_ReservedPins589=== PAUSE TestCreatePin_ReservedPins590=== RUN TestPresentReportsOnlyClosureRoots591=== PAUSE TestPresentReportsOnlyClosureRoots592=== RUN TestPresentNotReportedWhileGCDeletesClosure593=== PAUSE TestPresentNotReportedWhileGCDeletesClosure594=== RUN TestParseSingleRange595=== PAUSE TestParseSingleRange596=== RUN TestProxyHeadersOnlyTrustedOnSocket597=== PAUSE TestProxyHeadersOnlyTrustedOnSocket598=== RUN TestIsValidCachePath599=== PAUSE TestIsValidCachePath600=== RUN TestReadProxyNarinfo601=== PAUSE TestReadProxyNarinfo602=== RUN TestReadProxyNarinfoAlreadyDecompressed603=== PAUSE TestReadProxyNarinfoAlreadyDecompressed604=== RUN TestReadProxyNarStreaming605=== PAUSE TestReadProxyNarStreaming606=== RUN TestReadProxy404607=== PAUSE TestReadProxy404608=== RUN TestReadProxyInvalidPath609=== PAUSE TestReadProxyInvalidPath610=== RUN TestReadProxyHead611=== PAUSE TestReadProxyHead612=== RUN TestReadProxyConditionalGet613=== PAUSE TestReadProxyConditionalGet614=== RUN TestReadProxyRootRedirectsToIndexHTML615=== PAUSE TestReadProxyRootRedirectsToIndexHTML616=== RUN TestReadProxyDisabled617=== PAUSE TestReadProxyDisabled618=== RUN TestReadRedirectNar619=== PAUSE TestReadRedirectNar620=== RUN TestReadRedirectKeepsNarinfoProxied621=== PAUSE TestReadRedirectKeepsNarinfoProxied622=== RUN TestReadProxyRangeRequest623=== PAUSE TestReadProxyRangeRequest624=== RUN TestReadRedirectUsesPublicS3URL625=== PAUSE TestReadRedirectUsesPublicS3URL626=== RUN TestPush_OverlappingRootsStoreOneRowPerKey627=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey628=== RUN TestPush_CompleteCommitsEveryRoot629=== PAUSE TestPush_CompleteCommitsEveryRoot630=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit631=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit632=== RUN TestPush_RejectsBadRequests633=== PAUSE TestPush_RejectsBadRequests634=== RUN TestPush_SignsNarinfosOfItsPendingObjects635=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects636=== RUN TestRedundantMultipartUpload637=== PAUSE TestRedundantMultipartUpload638=== RUN TestCompleteMultipartUpload_ErrorButObjectExists639=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists640=== RUN TestCompletedNarNotReofferedAcrossClosures641=== PAUSE TestCompletedNarNotReofferedAcrossClosures642=== RUN TestPresignedUploadRegisteredBeforeCommit643=== PAUSE TestPresignedUploadRegisteredBeforeCommit644=== RUN TestService_Rustfstest645=== PAUSE TestService_Rustfstest646=== RUN TestParseSize647=== PAUSE TestParseSize648=== RUN TestSkippedUploadsHandler649=== PAUSE TestSkippedUploadsHandler650=== RUN TestSystemdListenerNotActivated651--- PASS: TestSystemdListenerNotActivated (0.00s)652=== RUN TestWatchdogBeatsWhenHealthy653--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)654=== RUN TestWatchdogSkipsWhenUnhealthy6552026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"665--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)666=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle667=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle668=== RUN TestProxyWriteTimeout669=== PAUSE TestProxyWriteTimeout670=== RUN TestIsValidUploadKey671=== PAUSE TestIsValidUploadKey672=== RUN TestUploadHandlersRejectInvalidKeys673=== PAUSE TestUploadHandlersRejectInvalidKeys674=== RUN TestUploadHandlersRejectOversizedBody675=== PAUSE TestUploadHandlersRejectOversizedBody676=== RUN TestService_cleanupPendingClosuresHandler677=== PAUSE TestService_cleanupPendingClosuresHandler678=== RUN TestService_createPendingClosureHandler679=== PAUSE TestService_createPendingClosureHandler680=== RUN TestService_verifyS3Integrity681=== PAUSE TestService_verifyS3Integrity682=== RUN TestCompleteMultipartUnregistered683=== PAUSE TestCompleteMultipartUnregistered684=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT685=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT686=== CONT TestPush_OverlappingRootsStoreOneRowPerKey687=== CONT TestService_AuthMiddleware688=== CONT TestReadRedirectUsesPublicS3URL689=== CONT TestReadProxyRangeRequest690=== CONT TestReadRedirectKeepsNarinfoProxied691=== CONT TestReadRedirectNar692=== CONT TestReadProxyDisabled693=== CONT TestReadProxyRootRedirectsToIndexHTML694=== CONT TestReadProxyConditionalGet695=== CONT TestReadProxyHead696=== CONT TestReadProxyInvalidPath697=== CONT TestReadProxy404698=== CONT TestReadProxyNarStreaming699=== CONT TestReadProxyNarinfoAlreadyDecompressed700=== CONT TestReadProxyNarinfo701=== CONT TestIsValidCachePath702=== CONT TestProxyHeadersOnlyTrustedOnSocket703=== CONT TestParseSingleRange704=== CONT TestPresentNotReportedWhileGCDeletesClosure705=== CONT TestPresentReportsOnlyClosureRoots706=== CONT TestCreatePin_ReservedPins707=== CONT TestOrphanedObjectsGCStressTest708=== CONT TestOrphanedObjectsGC709=== CONT TestObjectStatsTrigger710=== RUN TestIsValidCachePath/narinfo711=== RUN TestParseSingleRange/none712=== PAUSE TestParseSingleRange/none713=== PAUSE TestIsValidCachePath/narinfo714=== RUN TestParseSingleRange/unknown_unit715=== PAUSE TestParseSingleRange/unknown_unit716=== RUN TestParseSingleRange/multi-range_ignored717=== PAUSE TestParseSingleRange/multi-range_ignored718=== RUN TestParseSingleRange/malformed_no_dash719=== PAUSE TestParseSingleRange/malformed_no_dash720=== RUN TestParseSingleRange/malformed_both_empty721=== PAUSE TestParseSingleRange/malformed_both_empty722=== RUN TestParseSingleRange/malformed_end_before_start723=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars724=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars725=== PAUSE TestParseSingleRange/malformed_end_before_start726=== RUN TestIsValidCachePath/nar_zst727=== PAUSE TestIsValidCachePath/nar_zst728=== RUN TestParseSingleRange/closed729=== PAUSE TestParseSingleRange/closed730=== RUN TestParseSingleRange/open-ended731=== PAUSE TestParseSingleRange/open-ended732=== RUN TestParseSingleRange/end_clamped_to_size733=== PAUSE TestParseSingleRange/end_clamped_to_size734=== RUN TestParseSingleRange/suffix735=== PAUSE TestParseSingleRange/suffix736=== RUN TestIsValidCachePath/nar_xz737=== PAUSE TestIsValidCachePath/nar_xz738=== RUN TestIsValidCachePath/nar_bz2739=== PAUSE TestIsValidCachePath/nar_bz2740=== RUN TestIsValidCachePath/nar_uncompressed741=== PAUSE TestIsValidCachePath/nar_uncompressed742=== RUN TestParseSingleRange/suffix_exceeds_size743=== PAUSE TestParseSingleRange/suffix_exceeds_size744=== RUN TestParseSingleRange/single_byte745=== PAUSE TestParseSingleRange/single_byte746=== RUN TestIsValidCachePath/ls747=== RUN TestParseSingleRange/start_past_EOF748=== PAUSE TestParseSingleRange/start_past_EOF749=== PAUSE TestIsValidCachePath/ls750=== RUN TestParseSingleRange/start_far_past_EOF751=== PAUSE TestParseSingleRange/start_far_past_EOF752=== CONT TestMultipartCleanup753=== RUN TestIsValidCachePath/log754=== PAUSE TestIsValidCachePath/log755=== RUN TestIsValidCachePath/realisation756=== PAUSE TestIsValidCachePath/realisation757=== RUN TestIsValidCachePath/nix-cache-info758=== PAUSE TestIsValidCachePath/nix-cache-info759=== RUN TestIsValidCachePath/index.html760=== PAUSE TestIsValidCachePath/index.html761=== RUN TestIsValidCachePath/traversal_parent762=== PAUSE TestIsValidCachePath/traversal_parent763=== RUN TestIsValidCachePath/traversal_in_middle764=== PAUSE TestIsValidCachePath/traversal_in_middle765=== RUN TestIsValidCachePath/invalid_char_e766=== PAUSE TestIsValidCachePath/invalid_char_e767=== RUN TestIsValidCachePath/invalid_char_u768=== PAUSE TestIsValidCachePath/invalid_char_u769=== RUN TestIsValidCachePath/random_path770=== PAUSE TestIsValidCachePath/random_path771=== RUN TestIsValidCachePath/empty772=== PAUSE TestIsValidCachePath/empty773=== RUN TestIsValidCachePath/leading_slash774=== PAUSE TestIsValidCachePath/leading_slash775=== RUN TestIsValidCachePath/wrong_extension776=== PAUSE TestIsValidCachePath/wrong_extension777=== RUN TestIsValidCachePath/short_hash778=== PAUSE TestIsValidCachePath/short_hash779=== CONT TestServerTLSConfig780=== RUN TestServerTLSConfig/no_client_CA781=== PAUSE TestServerTLSConfig/no_client_CA782=== RUN TestServerTLSConfig/missing_CA_file783=== PAUSE TestServerTLSConfig/missing_CA_file784=== RUN TestServerTLSConfig/not_a_PEM_file785=== PAUSE TestServerTLSConfig/not_a_PEM_file786=== CONT TestService_NativeMTLS7872026/10/01 09:39:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34899/oidc7882026-10-01 09:39:12.527 UTC [645] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 09:39:12.527 UTC [645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026-10-01 09:39:12.611 UTC [646] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 09:39:12.611 UTC [646] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 09:39:12.653 UTC [647] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 09:39:12.653 UTC [647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026-10-01 09:39:12.665 UTC [648] ERROR: relation "goose_db_version" does not exist at character 367952026-10-01 09:39:12.665 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/10/01 09:39:12 OK 20241026095416_initial_model.sql (69.05ms)7972026/10/01 09:39:12 OK 20241026095416_initial_model.sql (20.78ms)7982026-10-01 09:39:12.681 UTC [649] ERROR: relation "goose_db_version" does not exist at character 367992026-10-01 09:39:12.681 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8002026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (21.88ms)8012026/10/01 09:39:12 OK 20241026095416_initial_model.sql (36.12ms)8022026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (24.77ms)8032026/10/01 09:39:12 OK 20241026095416_initial_model.sql (34.42ms)8042026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (6.47ms)8052026/10/01 09:39:12 OK 20251218171726_add_pins.sql (7.59ms)8062026/10/01 09:39:12 OK 20251218171726_add_pins.sql (13.86ms)8072026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.04ms)8082026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.19ms)8092026-10-01 09:39:12.717 UTC [650] ERROR: relation "goose_db_version" does not exist at character 368102026-10-01 09:39:12.717 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8112026/10/01 09:39:12 OK 20251218171726_add_pins.sql (8.52ms)8122026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (12.19ms)8132026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (9.75ms)8142026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (20.83ms)8152026/10/01 09:39:12 OK 20260905000000_add_claims.sql (21.01ms)8162026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (23.86ms)8172026/10/01 09:39:12 OK 20260905000000_add_claims.sql (22.53ms)8182026/10/01 09:39:12 OK 20241026095416_initial_model.sql (38ms)8192026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (6.48ms)8202026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (6.78ms)8212026/10/01 09:39:12 OK 20260905000000_add_claims.sql (8.09ms)8222026/10/01 09:39:12 OK 20260905000000_add_claims.sql (20.35ms)8232026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.9ms)8242026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.44ms)8252026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008262026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5.84ms)8272026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008282026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.87ms)8292026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.9ms)8302026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.88ms)8312026-10-01 09:39:12.762 UTC [651] ERROR: relation "goose_db_version" does not exist at character 368322026-10-01 09:39:12.762 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8332026/10/01 09:39:12 OK 1_commit_pending_closure.sql (6.53ms)8342026/10/01 09:39:12 OK 1_commit_pending_closure.sql (6.31ms)8352026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5.48ms)8362026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008372026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5.45ms)8382026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008392026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.68ms)8402026/10/01 09:39:12 OK 2_object_stats_trigger.sql (5.45ms)8412026/10/01 09:39:12 OK 2_object_stats_trigger.sql (10.36ms)8422026/10/01 09:39:12 OK 1_commit_pending_closure.sql (9.91ms)8432026-10-01 09:39:12.779 UTC [652] ERROR: relation "goose_db_version" does not exist at character 368442026-10-01 09:39:12.779 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8452026/10/01 09:39:12 OK 1_commit_pending_closure.sql (16.32ms)8462026/10/01 09:39:12 OK 20241026095416_initial_model.sql (26.69ms)8472026/10/01 09:39:12 OK 3_commit_push.sql (13ms)8482026/10/01 09:39:12 goose: up to current file version: 38492026/10/01 09:39:12 OK 20260905000000_add_claims.sql (15.69ms)8502026/10/01 09:39:12 OK 2_object_stats_trigger.sql (11.74ms)8512026/10/01 09:39:12 OK 3_commit_push.sql (12.5ms)8522026/10/01 09:39:12 goose: up to current file version: 38532026-10-01 09:39:12.794 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368542026-10-01 09:39:12.794 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8552026-10-01 09:39:12.794 UTC [658] ERROR: relation "goose_db_version" does not exist at character 368562026-10-01 09:39:12.794 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8572026-10-01 09:39:12.794 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368582026-10-01 09:39:12.794 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8592026/10/01 09:39:12 OK 2_object_stats_trigger.sql (12.68ms)8602026/10/01 09:39:12 OK 3_commit_push.sql (64.07ms)8612026/10/01 09:39:12 goose: up to current file version: 38622026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (70.03ms)8632026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (70.73ms)8642026/10/01 09:39:12 OK 3_commit_push.sql (59.5ms)8652026/10/01 09:39:12 goose: up to current file version: 38662026/10/01 09:39:12 OK 20241026095416_initial_model.sql (73.72ms)8672026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5.68ms)8682026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008692026/10/01 09:39:12 OK 20251218171726_add_pins.sql (10.03ms)8702026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.14ms)8712026-10-01 09:39:12.865 UTC [659] ERROR: relation "goose_db_version" does not exist at character 368722026-10-01 09:39:12.865 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8732026/10/01 09:39:12 OK 1_commit_pending_closure.sql (5.01ms)8742026-10-01 09:39:12.868 UTC [660] ERROR: relation "goose_db_version" does not exist at character 368752026-10-01 09:39:12.868 UTC [660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8762026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.89ms)8772026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.39ms)8782026/10/01 09:39:12 OK 20241026095416_initial_model.sql (13.23ms)8792026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (8.51ms)8802026/10/01 09:39:12 OK 3_commit_push.sql (1.75ms)8812026/10/01 09:39:12 goose: up to current file version: 38822026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)8832026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.69ms)8842026-10-01 09:39:12.875 UTC [661] ERROR: relation "goose_db_version" does not exist at character 368852026-10-01 09:39:12.875 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8862026-10-01 09:39:12.875 UTC [662] ERROR: relation "goose_db_version" does not exist at character 368872026-10-01 09:39:12.875 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8882026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.2ms)8892026-10-01 09:39:12.877 UTC [663] ERROR: relation "goose_db_version" does not exist at character 368902026-10-01 09:39:12.877 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8912026/10/01 09:39:12 OK 20241026095416_initial_model.sql (16.71ms)8922026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.19ms)8932026/10/01 09:39:12 OK 20241026095416_initial_model.sql (13.85ms)8942026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.05ms)8952026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)8962026-10-01 09:39:12.880 UTC [664] ERROR: relation "goose_db_version" does not exist at character 368972026-10-01 09:39:12.880 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC898--- PASS: TestReadProxyRangeRequest (0.47s)8992026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (4.58ms)900=== CONT TestMetricsInventory9012026/10/01 09:39:12 OK 20241026095416_initial_model.sql (20.31ms)9022026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.85ms)9032026-10-01 09:39:12.883 UTC [668] ERROR: relation "goose_db_version" does not exist at character 369042026-10-01 09:39:12.883 UTC [668] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9052026-10-01 09:39:12.883 UTC [665] ERROR: relation "goose_db_version" does not exist at character 369062026-10-01 09:39:12.883 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9072026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)9082026-10-01 09:39:12.884 UTC [666] ERROR: relation "goose_db_version" does not exist at character 369092026-10-01 09:39:12.884 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9102026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)9112026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4ms)9122026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009132026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.88ms)9142026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.8ms)9152026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.68ms)9162026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009172026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.31ms)9182026/10/01 09:39:12 OK 20241026095416_initial_model.sql (10.7ms)9192026-10-01 09:39:12.889 UTC [669] ERROR: relation "goose_db_version" does not exist at character 369202026-10-01 09:39:12.889 UTC [669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9212026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.05ms)9222026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.35ms)9232026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)9242026/10/01 09:39:12 OK 1_commit_pending_closure.sql (5.36ms)9252026/10/01 09:39:12 OK 20241026095416_initial_model.sql (10.63ms)9262026/10/01 09:39:12 OK 20251218171726_add_pins.sql (6.39ms)9272026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.98ms)9282026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.58ms)9292026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.45ms)9302026/10/01 09:39:12 OK 3_commit_push.sql (1.85ms)9312026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.5ms)9322026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.29ms)9332026/10/01 09:39:12 goose: up to current file version: 39342026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.9ms)9352026/10/01 09:39:12 OK 20241026095416_initial_model.sql (11.81ms)9362026/10/01 09:39:12 OK 2_object_stats_trigger.sql (3.57ms)9372026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.03ms)9382026-10-01 09:39:12.895 UTC [673] ERROR: relation "goose_db_version" does not exist at character 369392026-10-01 09:39:12.895 UTC [673] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9402026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009412026/10/01 09:39:12 OK 3_commit_push.sql (1.87ms)9422026/10/01 09:39:12 goose: up to current file version: 39432026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.63ms)9442026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.77ms)9452026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.91ms)9462026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.7ms)9472026-10-01 09:39:12.899 UTC [675] ERROR: relation "goose_db_version" does not exist at character 369482026-10-01 09:39:12.899 UTC [675] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9492026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.81ms)9502026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (7.99ms)9512026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.22ms)9522026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.09ms)9532026-10-01 09:39:12.900 UTC [674] ERROR: relation "goose_db_version" does not exist at character 369542026-10-01 09:39:12.900 UTC [674] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9552026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.98ms)9562026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.04ms)9572026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)9582026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)9592026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.55ms)9602026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.74ms)9612026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.99ms)9622026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.42ms)9632026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.28ms)9642026/10/01 09:39:12 OK 3_commit_push.sql (1.34ms)9652026/10/01 09:39:12 goose: up to current file version: 39662026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.89ms)9672026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.76ms)9682026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.1ms)9692026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.05ms)9702026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009712026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.67ms)9722026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.95ms)9732026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.8ms)9742026/10/01 09:39:12 OK 20241026095416_initial_model.sql (15.86ms)9752026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.96ms)9762026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009772026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.75ms)9782026/10/01 09:39:12 OK 20241026095416_initial_model.sql (11.76ms)9792026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.34ms)9802026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.96ms)9812026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)9822026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.43ms)9832026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.91ms)9842026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.72ms)9852026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.98ms)9862026/10/01 09:39:12 OK 20241026095416_initial_model.sql (13.08ms)9872026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.58ms)9882026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.63ms)9892026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)9902026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.35ms)9912026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.66ms)9922026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009932026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)9942026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.67ms)9952026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.07ms)9962026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009972026/10/01 09:39:12 OK 3_commit_push.sql (1.53ms)9982026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)9992026/10/01 09:39:12 goose: up to current file version: 310002026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010012026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.54ms)1002--- PASS: TestReadRedirectUsesPublicS3URL (0.50s)1003=== CONT TestNARDeduplicationMetadataUploadBug10042026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.35ms)10052026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.6ms)10062026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.11ms)10072026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.82ms)10082026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.32ms)10092026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.1ms)10102026/10/01 09:39:12 OK 3_commit_push.sql (2.2ms)10112026/10/01 09:39:12 goose: up to current file version: 310122026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.39ms)10132026/10/01 09:39:12 OK 20241026095416_initial_model.sql (11.94ms)10142026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.54ms)10152026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.18ms)10162026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.48ms)10172026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.54ms)10182026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.27ms)10192026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)10202026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010212026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.58ms)10222026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.89ms)10232026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.73ms)10242026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.6ms)10252026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.04ms)10262026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)10272026/10/01 09:39:12 OK 2_object_stats_trigger.sql (3.06ms)10282026/10/01 09:39:12 OK 3_commit_push.sql (1.46ms)10292026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.57ms)10302026/10/01 09:39:12 goose: up to current file version: 310312026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.22ms)10322026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.53ms)10332026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.68ms)10342026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010352026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.79ms)10362026/10/01 09:39:12 OK 3_commit_push.sql (1.53ms)10372026/10/01 09:39:12 goose: up to current file version: 310382026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.65ms)10392026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010402026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)10412026/10/01 09:39:12 OK 3_commit_push.sql (1.88ms)10422026/10/01 09:39:12 goose: up to current file version: 310432026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.73ms)10442026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.05ms)10452026/10/01 09:39:12 OK 20241026095416_initial_model.sql (10.18ms)10462026/10/01 09:39:12 OK 1_commit_pending_closure.sql (1.56ms)10472026/10/01 09:39:12 OK 20260905000000_add_claims.sql (2.42ms)10482026/10/01 09:39:12 OK 20251218171726_add_pins.sql (2.43ms)10492026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (1.73ms)10502026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)10512026/10/01 09:39:12 OK 3_commit_push.sql (995.28µs)10522026/10/01 09:39:12 goose: up to current file version: 310532026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.87ms)10542026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.01ms)10552026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)10562026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.92ms)10572026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010582026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.15ms)10592026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.43ms)10602026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.9ms)10612026/10/01 09:39:12 OK 3_commit_push.sql (2.04ms)10622026/10/01 09:39:12 goose: up to current file version: 310632026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2ms)10642026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.66ms)1065--- PASS: TestReadRedirectKeepsNarinfoProxied (0.51s)1066=== CONT TestCreatePendingClosureRejectsOversizedNAR10672026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.3ms)10682026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.65ms)10692026/10/01 09:39:12 INFO Received uploads request method=POST path=/api/pending_closures10702026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.12ms)10712026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.41ms)1072--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1073=== CONT TestCacheConfigHandlerMaxNarSize1074--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1075=== CONT TestGenerateLandingPage10762026/10/01 09:39:12 OK 3_commit_push.sql (1.66ms)10772026/10/01 09:39:12 goose: up to current file version: 310782026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.94ms)10792026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (1.87ms)10802026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010812026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.25ms)10822026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.31ms)10832026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.39ms)10842026/10/01 09:39:12 OK 3_commit_push.sql (1.46ms)10852026/10/01 09:39:12 goose: up to current file version: 31086--- PASS: TestGenerateLandingPage (0.00s)1087=== CONT TestService_readinessHandler10882026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.47ms)10892026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.47ms)10902026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.39ms)10912026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010922026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.95ms)10932026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.7ms)10942026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010952026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.83ms)10962026/10/01 09:39:12 OK 1_commit_pending_closure.sql (4.12ms)10972026/10/01 09:39:12 OK 1_commit_pending_closure.sql (4.34ms)10982026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.06ms)10992026/10/01 09:39:12 OK 2_object_stats_trigger.sql (4.62ms)11002026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.82ms)11012026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.3ms)11022026/10/01 09:39:12 OK 20260905000000_add_claims.sql (2.95ms)11032026/10/01 09:39:12 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1104--- PASS: TestService_AuthMiddleware (0.53s)1105=== CONT TestService_healthCheckHandler11062026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.32ms)11072026/10/01 09:39:12 OK 3_commit_push.sql (2.19ms)11082026/10/01 09:39:12 goose: up to current file version: 311092026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.44ms)11102026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.4ms)11112026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011122026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.14ms)11132026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.18ms)11142026/10/01 09:39:12 OK 3_commit_push.sql (1.65ms)11152026/10/01 09:39:12 goose: up to current file version: 311162026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.18ms)11172026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011182026/10/01 09:39:12 OK 3_commit_push.sql (2.18ms)11192026/10/01 09:39:12 goose: up to current file version: 311202026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (1.79ms)11212026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011222026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.56ms)11232026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011242026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.26ms)11252026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.88ms)11262026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.74ms)11272026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.08ms)11282026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.86ms)11292026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.24ms)11302026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.57ms)11312026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.79ms)11322026/10/01 09:39:12 OK 3_commit_push.sql (1.74ms)11332026/10/01 09:39:12 goose: up to current file version: 311342026/10/01 09:39:12 OK 3_commit_push.sql (1.18ms)11352026/10/01 09:39:12 goose: up to current file version: 311362026/10/01 09:39:12 OK 3_commit_push.sql (1.14ms)11372026/10/01 09:39:12 goose: up to current file version: 311382026/10/01 09:39:12 OK 3_commit_push.sql (1.89ms)11392026/10/01 09:39:12 goose: up to current file version: 31140--- PASS: TestReadRedirectNar (0.56s)1141=== CONT TestGracefulShutdownDrainsInflight11422026/10/01 09:39:12 INFO Starting HTTP server address=127.0.0.1:3785111432026/10/01 09:39:12 INFO Shutdown signal received, draining in-flight requests timeout=10s1144--- PASS: TestReadProxyDisabled (0.57s)1145=== CONT TestGCTaskStore_Fail1146--- PASS: TestGCTaskStore_Fail (0.00s)1147=== CONT TestGCTaskStore_PhaseUpdates1148--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1149=== CONT TestGCTaskStore_CompletedAllowsNewTask1150--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1151=== CONT TestGCTaskStore_GetReturnsLatest1152--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1153=== CONT TestGCTaskStore_GetEmpty1154--- PASS: TestGCTaskStore_GetEmpty (0.00s)1155=== CONT TestGCTaskStore_ConflictDifferentParams1156--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1157=== CONT TestGCTaskStore_DeduplicateSameParams1158--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1159=== CONT TestGCTaskStore_StartNew1160--- PASS: TestGCTaskStore_StartNew (0.00s)1161=== CONT TestGCEndsOnShutdown1162--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.59s)1163=== CONT TestCommitRacingPendingCleanupKeepsObjects11642026/10/01 09:39:13 INFO Received push request method=POST path=/api/pushes1165--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1166=== CONT TestPushWaitsForSweepHoldingRow1167--- PASS: TestReadProxyConditionalGet (0.64s)1168=== CONT TestSweepRechecksPendingAfterLocking1169--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.64s)1170=== CONT TestGetExistingObjectsLocksRows11712026-10-01 09:39:13.065 UTC [693] ERROR: relation "goose_db_version" does not exist at character 3611722026-10-01 09:39:13.065 UTC [693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11732026-10-01 09:39:13.065 UTC [692] ERROR: relation "goose_db_version" does not exist at character 3611742026-10-01 09:39:13.065 UTC [692] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026-10-01 09:39:13.088 UTC [696] ERROR: relation "goose_db_version" does not exist at character 3611762026-10-01 09:39:13.088 UTC [696] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11772026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.23ms)11782026/10/01 09:39:13 OK 20241026095416_initial_model.sql (13.76ms)11792026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)11802026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (3.77ms)11812026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.28ms)11822026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.46ms)11832026-10-01 09:39:13.104 UTC [698] ERROR: relation "goose_db_version" does not exist at character 3611842026-10-01 09:39:13.104 UTC [698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11852026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.57ms)11862026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.46ms)11872026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.79ms)11882026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.04ms)11892026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.98ms)11902026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)11912026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.12ms)11922026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.79ms)11932026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.03ms)11942026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.01ms)11952026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000011962026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.38ms)11972026-10-01 09:39:13.119 UTC [699] ERROR: relation "goose_db_version" does not exist at character 3611982026-10-01 09:39:13.119 UTC [699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11992026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.67ms)12002026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.97ms)12012026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.69ms)12022026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.2ms)12032026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000012042026/10/01 09:39:13 OK 3_commit_push.sql (1.12ms)12052026/10/01 09:39:13 goose: up to current file version: 312062026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.9ms)12072026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.87ms)12082026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.12ms)12092026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.03ms)12102026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.21ms)12112026/10/01 09:39:13 goose: successfully migrated database to version: 202609231200001212--- PASS: TestObjectStatsTrigger (0.71s)12132026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)1214=== CONT TestRegisterCompletedObjectNeedsPendingRow12152026/10/01 09:39:13 OK 3_commit_push.sql (841.07µs)12162026/10/01 09:39:13 goose: up to current file version: 312172026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.24ms)12182026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.94ms)12192026-10-01 09:39:13.131 UTC [700] ERROR: relation "goose_db_version" does not exist at character 3612202026-10-01 09:39:13.131 UTC [700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12212026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.83ms)12222026/10/01 09:39:13 OK 20241026095416_initial_model.sql (8.4ms)12232026/10/01 09:39:13 OK 3_commit_push.sql (2.1ms)12242026/10/01 09:39:13 goose: up to current file version: 312252026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)12262026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)12272026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.84ms)12282026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.85ms)12292026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3ms)12302026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)1231--- PASS: TestReadProxy404 (0.73s)1232=== CONT TestSweepSkipsRowsLockedByPush12332026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (11.23ms)12342026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000012352026/10/01 09:39:13 OK 20260905000000_add_claims.sql (13.26ms)12362026/10/01 09:39:13 OK 20241026095416_initial_model.sql (18.35ms)12372026/10/01 09:39:13 OK 1_commit_pending_closure.sql (4.48ms)12382026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.45ms)12392026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (3.73ms)12402026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (6.93ms)12412026/10/01 09:39:13 OK 3_commit_push.sql (2.02ms)12422026/10/01 09:39:13 goose: up to current file version: 312432026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.3ms)12442026/10/01 09:39:13 goose: successfully migrated database to version: 202609231200001245--- PASS: TestReadProxyHead (0.75s)1246=== CONT TestFailedS3DeleteKeepsTombstone12472026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.88ms)12482026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.12ms)12492026-10-01 09:39:13.169 UTC [705] ERROR: relation "goose_db_version" does not exist at character 3612502026-10-01 09:39:13.169 UTC [705] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12512026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.6ms)12522026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.92ms)12532026/10/01 09:39:13 OK 3_commit_push.sql (3.56ms)12542026/10/01 09:39:13 goose: up to current file version: 312552026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.62ms)12562026/10/01 09:39:13 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12572026/10/01 09:39:13 WARN Refused reserved pin name=worker-x86_64-linux12582026/10/01 09:39:13 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12592026/10/01 09:39:13 INFO Received create pin request method=POST path=/api/pins/my-app12602026/10/01 09:39:13 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12612026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (1.92ms)1262--- PASS: TestCreatePin_ReservedPins (0.76s)1263=== CONT TestForceGCDuringPushOffersSweptObject1264=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1265=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1266=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1267=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1268=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12692026-10-01 09:39:13.183 UTC [708] ERROR: relation "goose_db_version" does not exist at character 3612702026-10-01 09:39:13.183 UTC [708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12712026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (4.21ms)12722026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000012732026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.55ms)12742026/10/01 09:39:13 OK 20241026095416_initial_model.sql (11.23ms)12752026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.98ms)12762026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.33ms)12772026/10/01 09:39:13 OK 3_commit_push.sql (2.32ms)12782026/10/01 09:39:13 goose: up to current file version: 312792026-10-01 09:39:13.192 UTC [710] ERROR: relation "goose_db_version" does not exist at character 3612802026-10-01 09:39:13.192 UTC [710] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12812026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.84ms)12822026/10/01 09:39:13 OK 20241026095416_initial_model.sql (27.39ms)12832026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (22.33ms)12842026/10/01 09:39:13 OK 20260905000000_add_claims.sql (5.09ms)12852026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.91ms)12862026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.66ms)12872026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.85ms)12882026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)12892026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.31ms)12902026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000012912026/10/01 09:39:13 OK 20251218171726_add_pins.sql (5.26ms)1292--- PASS: TestPresentReportsOnlyClosureRoots (0.81s)1293=== CONT TestGCSweepDeliversEachKeyOnce12942026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.18ms)12952026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.26ms)12962026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.01ms)1297--- PASS: TestReadProxyInvalidPath (0.82s)1298=== CONT TestTombstonedObjectOfferedWithoutWaiting12992026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (6.68ms)13002026/10/01 09:39:13 OK 3_commit_push.sql (2.05ms)13012026/10/01 09:39:13 goose: up to current file version: 313022026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.55ms)13032026/10/01 09:39:13 OK 20260905000000_add_claims.sql (12.75ms)13042026/10/01 09:39:13 OK 20260905000000_add_claims.sql (16.84ms)13052026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (4.69ms)13062026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.98ms)13072026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.43ms)13082026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013092026/10/01 09:39:13 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13102026/10/01 09:39:13 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13112026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.88ms)1312--- PASS: TestService_NativeMTLS (0.84s)1313=== CONT TestSkippedUploadsHandler13142026/10/01 09:39:13 INFO Client skipped oversized paths paths=3 nar_bytes=500000000013152026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.37ms)13162026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013172026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.45ms)13182026/10/01 09:39:13 OK 3_commit_push.sql (1.31ms)13192026/10/01 09:39:13 goose: up to current file version: 313202026-10-01 09:39:13.264 UTC [716] ERROR: relation "goose_db_version" does not exist at character 3613212026-10-01 09:39:13.264 UTC [716] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13222026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.89ms)13232026-10-01 09:39:13.269 UTC [717] ERROR: relation "goose_db_version" does not exist at character 3613242026-10-01 09:39:13.269 UTC [717] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1325--- PASS: TestSkippedUploadsHandler (0.01s)1326=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT13272026/10/01 09:39:13 OK 2_object_stats_trigger.sql (6.52ms)13282026/10/01 09:39:13 OK 3_commit_push.sql (5.17ms)13292026/10/01 09:39:13 goose: up to current file version: 313302026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.79ms)13312026-10-01 09:39:13.288 UTC [720] ERROR: relation "goose_db_version" does not exist at character 3613322026-10-01 09:39:13.288 UTC [720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13332026/10/01 09:39:13 OK 20241026095416_initial_model.sql (13.23ms)13342026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)13352026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)13362026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.05ms)13372026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)13382026/10/01 09:39:13 OK 20251218171726_add_pins.sql (7.03ms)13392026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.81ms)13402026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)13412026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.75ms)1342--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.89s)1343=== CONT TestGCSweepSkipsPendingObjects13442026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.69ms)13452026-10-01 09:39:13.306 UTC [721] ERROR: relation "goose_db_version" does not exist at character 3613462026-10-01 09:39:13.306 UTC [721] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13472026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.35ms)13482026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013492026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.8ms)13502026/10/01 09:39:13 OK 20241026095416_initial_model.sql (10.64ms)13512026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.33ms)13522026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)13532026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.74ms)13542026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.93ms)13552026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013562026/10/01 09:39:13 OK 3_commit_push.sql (1.29ms)13572026/10/01 09:39:13 goose: up to current file version: 313582026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.9ms)13592026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.77ms)13602026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.68ms)13612026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.58ms)13622026/10/01 09:39:13 OK 3_commit_push.sql (1.98ms)13632026/10/01 09:39:13 goose: up to current file version: 313642026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.12ms)13652026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.5ms)13662026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.35ms)13672026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.49ms)13682026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.23ms)13692026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013702026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.96ms)13712026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.38ms)13722026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.6ms)13732026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)13742026/10/01 09:39:13 OK 3_commit_push.sql (1.21ms)13752026/10/01 09:39:13 goose: up to current file version: 313762026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.07ms)1377--- PASS: TestReadProxyNarinfo (0.93s)1378=== CONT TestCompleteMultipartUnregistered13792026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (28.39ms)13802026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (4.9ms)13812026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013822026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.75ms)13832026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.26ms)13842026/10/01 09:39:13 OK 3_commit_push.sql (1.39ms)13852026/10/01 09:39:13 goose: up to current file version: 313862026-10-01 09:39:13.376 UTC [726] ERROR: relation "goose_db_version" does not exist at character 3613872026-10-01 09:39:13.376 UTC [726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13882026-10-01 09:39:13.380 UTC [727] ERROR: relation "goose_db_version" does not exist at character 3613892026-10-01 09:39:13.380 UTC [727] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13902026-10-01 09:39:13.395 UTC [728] ERROR: relation "goose_db_version" does not exist at character 3613912026-10-01 09:39:13.395 UTC [728] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13922026/10/01 09:39:13 OK 20241026095416_initial_model.sql (11.01ms)13932026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.04ms)13942026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)13952026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)13962026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.79ms)13972026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.96ms)13982026/10/01 09:39:13 OK 20241026095416_initial_model.sql (8.76ms)13992026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)14002026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)14012026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)14022026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.22ms)14032026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.46ms)14042026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.69ms)14052026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.43ms)14062026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.03ms)14072026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (1.42ms)14082026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014092026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (2.82ms)14102026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (1.63ms)14112026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014122026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.05ms)14132026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.71ms)14142026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.66ms)14152026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.81ms)14162026-10-01 09:39:13.423 UTC [729] ERROR: relation "goose_db_version" does not exist at character 3614172026-10-01 09:39:13.423 UTC [729] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14182026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2ms)14192026/10/01 09:39:13 OK 3_commit_push.sql (1.35ms)14202026/10/01 09:39:13 goose: up to current file version: 314212026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.42ms)14222026/10/01 09:39:13 OK 3_commit_push.sql (1.83ms)14232026/10/01 09:39:13 goose: up to current file version: 314242026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.97ms)14252026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014262026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.96ms)14272026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.04ms)14282026/10/01 09:39:13 OK 3_commit_push.sql (1.33ms)14292026/10/01 09:39:13 goose: up to current file version: 314302026/10/01 09:39:13 OK 20241026095416_initial_model.sql (8.74ms)14312026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures14322026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.5ms)14332026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.06ms)14342026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (2.48ms)14352026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.06ms)14362026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (1.34ms)14372026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (1.04ms)14382026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014392026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.33ms)14402026/10/01 09:39:13 OK 2_object_stats_trigger.sql (696.64µs)14412026/10/01 09:39:13 OK 3_commit_push.sql (604.43µs)14422026/10/01 09:39:13 goose: up to current file version: 314432026-10-01 09:39:13.459 UTC [730] ERROR: relation "goose_db_version" does not exist at character 3614442026-10-01 09:39:13.459 UTC [730] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14452026/10/01 09:39:13 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket1454912341/001/proxy.sock14462026/10/01 09:39:13 INFO Starting HTTP server address=127.0.0.1:3882114472026/10/01 09:39:13 WARN mTLS auth: subject not in bound subjects subject="CN=someone"14482026/10/01 09:39:13 INFO Shutdown signal received, draining in-flight requests timeout=10s1449--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.04s)1450=== CONT TestDeduplicatedObjectsRecordedAsPending14512026/10/01 09:39:13 OK 20241026095416_initial_model.sql (8.17ms)14522026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)14532026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.96ms)14542026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)14552026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.23ms)1456--- PASS: TestReadProxyNarStreaming (1.07s)1457=== CONT TestService_verifyS3Integrity14582026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.24ms)14592026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.65ms)14602026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014612026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.9ms)14622026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.13ms)14632026/10/01 09:39:13 OK 3_commit_push.sql (1.36ms)14642026/10/01 09:39:13 goose: up to current file version: 314652026/10/01 09:39:13 WARN readiness check failed error="closed pool"1466--- PASS: TestService_readinessHandler (0.61s)1467=== CONT TestPushDedupSurvivesConcurrentGC1468=== NAME TestNARDeduplicationMetadataUploadBug1469 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug706195208/001/store/wnazsnwmxacgv56sdl9q1ljfs85q3zvf-file1.txt14702026/10/01 09:39:13 INFO Received cleanup request method=DELETE path=/api/pending_closures1471--- PASS: TestMetricsInventory (0.67s)1472=== CONT TestService_createPendingClosureHandler14732026/10/01 09:39:13 INFO Aborted multipart uploads count=114742026-10-01 09:39:13.560 UTC [755] ERROR: relation "goose_db_version" does not exist at character 3614752026-10-01 09:39:13.560 UTC [755] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1476--- PASS: TestMultipartCleanup (1.14s)1477=== CONT TestGCMetrics1478--- PASS: TestService_healthCheckHandler (0.63s)1479=== CONT TestService_cleanupPendingClosuresHandler14802026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.96ms)14812026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.76ms)14822026/10/01 09:39:13 OK 20251218171726_add_pins.sql (4.37ms)14832026-10-01 09:39:13.591 UTC [779] ERROR: relation "goose_db_version" does not exist at character 3614842026-10-01 09:39:13.591 UTC [779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1485--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.17s)1486=== CONT TestGCBugBareHashReferences14872026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (6.29ms)14882026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.8ms)14892026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.75ms)14902026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.61ms)14912026/10/01 09:39:13 goose: successfully migrated database to version: 202609231200001492--- PASS: TestGCEndsOnShutdown (0.62s)1493=== CONT TestUploadHandlersRejectOversizedBody14942026/10/01 09:39:13 OK 20241026095416_initial_model.sql (10.06ms)14952026/10/01 09:39:13 OK 1_commit_pending_closure.sql (4.6ms)14962026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.72ms)14972026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.65ms)14982026/10/01 09:39:13 OK 3_commit_push.sql (1.57ms)14992026/10/01 09:39:13 goose: up to current file version: 315002026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.92ms)15012026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)15022026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.35ms)15032026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.77ms)15042026/10/01 09:39:13 INFO Received push request method=POST path=/api/pushes15052026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (12.22ms)15062026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000015072026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures15082026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.21ms)15092026/10/01 09:39:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15102026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.1ms)15112026/10/01 09:39:13 INFO Uploading wnazsnwmxacgv56sdl9q1ljfs85q3zvf-file1.txt (160B)15122026/10/01 09:39:13 OK 3_commit_push.sql (897.6µs)15132026/10/01 09:39:13 goose: up to current file version: 315142026-10-01 09:39:13.713 UTC [800] ERROR: relation "goose_db_version" does not exist at character 3615152026-10-01 09:39:13.713 UTC [800] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15162026/10/01 09:39:13 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15172026/10/01 09:39:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15182026/10/01 09:39:13 WARN Failed to register uploaded object key=wnazsnwmxacgv56sdl9q1ljfs85q3zvf.ls error="server returned 404: 404 page not found\n"15192026/10/01 09:39:13 INFO Signed narinfos id=1 count=115202026/10/01 09:39:13 INFO Uploading 1 narinfos15212026-10-01 09:39:13.716 UTC [801] ERROR: relation "goose_db_version" does not exist at character 3615222026-10-01 09:39:13.716 UTC [801] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15232026-10-01 09:39:13.716 UTC [802] ERROR: relation "goose_db_version" does not exist at character 3615242026-10-01 09:39:13.716 UTC [802] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15252026-10-01 09:39:13.716 UTC [804] ERROR: relation "goose_db_version" does not exist at character 3615262026-10-01 09:39:13.716 UTC [804] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15272026-10-01 09:39:13.717 UTC [805] ERROR: relation "goose_db_version" does not exist at character 3615282026-10-01 09:39:13.717 UTC [805] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15292026/10/01 09:39:13 INFO Received complete push request method=POST path=/api/pushes/1/complete15302026/10/01 09:39:13 WARN Failed to register uploaded object key=wnazsnwmxacgv56sdl9q1ljfs85q3zvf.narinfo error="server returned 404: 404 page not found\n"15312026/10/01 09:39:13 INFO Upload complete. (131ms)1532=== NAME TestNARDeduplicationMetadataUploadBug1533 metadata_upload_test.go:54: Retrieved narinfo from S3:1534 StorePath: /build/TestNARDeduplicationMetadataUploadBug706195208/001/store/wnazsnwmxacgv56sdl9q1ljfs85q3zvf-file1.txt1535 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1536 Compression: zstd1537 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1538 NarSize: 1601539 References: 1540 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf15412026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.75ms)1542=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1543=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1544=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart15452026/10/01 09:39:13 OK 20241026095416_initial_model.sql (72.64ms)1546=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1547=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts15482026/10/01 09:39:13 OK 20241026095416_initial_model.sql (72.83ms)1549=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts15502026/10/01 09:39:13 OK 20241026095416_initial_model.sql (72.78ms)1551=== NAME TestNARDeduplicationMetadataUploadBug15522026/10/01 09:39:13 OK 20241026095416_initial_model.sql (72.86ms)1553 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1554=== CONT TestLeadEndsOnShutdown1555=== NAME TestNARDeduplicationMetadataUploadBug1556 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1557 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15582026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)15592026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)15602026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.47ms)15612026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)15622026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)15632026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.98ms)15642026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.23ms)15652026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.78ms)15662026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.37ms)15672026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.74ms)15682026/10/01 09:39:13 INFO Aborted multipart uploads count=015692026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)15702026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.48ms)15712026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)15722026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.93ms)15732026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)15742026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period15752026/10/01 09:39:13 INFO Aborted multipart uploads count=015762026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.79ms)15772026/10/01 09:39:13 OK 20260905000000_add_claims.sql (2.66ms)15782026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.35ms)15792026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.11ms)15802026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.59ms)15812026/10/01 09:39:13 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=015822026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.16ms)15832026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.6ms)15842026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period15852026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.13ms)15862026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.02ms)15872026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000015882026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2ms)15892026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (1.52ms)15902026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000015912026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (1.38ms)15922026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000015932026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.02ms)15942026/10/01 09:39:13 INFO Vacuumed table table=pending_closures1595--- PASS: TestGetExistingObjectsLocksRows (0.76s)1596=== CONT TestUploadHandlersRejectInvalidKeys1597=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1598=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1599=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1600=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1601=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1602=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1603=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1604=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1605=== CONT TestIsValidUploadKey1606=== RUN TestIsValidUploadKey/narinfo16072026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (1.72ms)1608=== PAUSE TestIsValidUploadKey/narinfo16092026/10/01 09:39:13 goose: successfully migrated database to version: 202609231200001610=== RUN TestIsValidUploadKey/nar_zst16112026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.77ms)1612=== PAUSE TestIsValidUploadKey/nar_zst1613=== RUN TestIsValidUploadKey/nar_xz16142026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.13ms)1615=== PAUSE TestIsValidUploadKey/nar_xz16162026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.25ms)1617=== RUN TestIsValidUploadKey/nar_plain16182026/10/01 09:39:13 INFO Vacuumed table table=pending_objects1619=== PAUSE TestIsValidUploadKey/nar_plain1620=== RUN TestIsValidUploadKey/listing1621=== PAUSE TestIsValidUploadKey/listing1622=== RUN TestIsValidUploadKey/build_log1623=== PAUSE TestIsValidUploadKey/build_log1624=== RUN TestIsValidUploadKey/build_log_home-manager_file1625=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1626=== RUN TestIsValidUploadKey/build_log_plus_in_name1627=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1628=== RUN TestIsValidUploadKey/build_log_question_mark1629=== PAUSE TestIsValidUploadKey/build_log_question_mark1630=== RUN TestIsValidUploadKey/build_log_equals1631=== PAUSE TestIsValidUploadKey/build_log_equals1632=== RUN TestIsValidUploadKey/realisation16332026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads1634=== PAUSE TestIsValidUploadKey/realisation1635=== RUN TestIsValidUploadKey/realisation_plus_in_output16362026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.42ms)1637=== PAUSE TestIsValidUploadKey/realisation_plus_in_output16382026/10/01 09:39:13 goose: successfully migrated database to version: 202609231200001639=== RUN TestIsValidUploadKey/nix-cache-info1640=== PAUSE TestIsValidUploadKey/nix-cache-info1641=== RUN TestIsValidUploadKey/index.html1642=== PAUSE TestIsValidUploadKey/index.html1643=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1644=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1645=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1646=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1647=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1648=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1649=== RUN TestIsValidUploadKey/traversal1650=== PAUSE TestIsValidUploadKey/traversal1651=== RUN TestIsValidUploadKey/traversal_nar16522026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.47ms)1653=== PAUSE TestIsValidUploadKey/traversal_nar1654=== RUN TestIsValidUploadKey/absolute1655=== PAUSE TestIsValidUploadKey/absolute16562026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.35ms)1657=== RUN TestIsValidUploadKey/empty_key1658=== PAUSE TestIsValidUploadKey/empty_key1659=== RUN TestIsValidUploadKey/unknown_type1660=== PAUSE TestIsValidUploadKey/unknown_type1661=== CONT TestLeadElectsOneAndHandsOver16622026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.38ms)16632026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.05ms)16642026/10/01 09:39:13 OK 3_commit_push.sql (1.7ms)16652026/10/01 09:39:13 goose: up to current file version: 316662026/10/01 09:39:13 INFO Vacuumed table table=closures16672026/10/01 09:39:13 OK 3_commit_push.sql (1.65ms)16682026/10/01 09:39:13 goose: up to current file version: 316692026/10/01 09:39:13 INFO Vacuumed table table=objects16702026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.2ms)16712026/10/01 09:39:13 OK 3_commit_push.sql (2.18ms)16722026/10/01 09:39:13 goose: up to current file version: 316732026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.45ms)16742026/10/01 09:39:13 OK 3_commit_push.sql (542.19µs)16752026/10/01 09:39:13 goose: up to current file version: 316762026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.18ms)16772026/10/01 09:39:13 OK 3_commit_push.sql (1.06ms)16782026/10/01 09:39:13 goose: up to current file version: 316792026/10/01 09:39:13 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=01680--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.82s)1681=== CONT TestProxyWriteTimeout1682=== RUN TestProxyWriteTimeout/narinfo1683=== PAUSE TestProxyWriteTimeout/narinfo1684=== RUN TestProxyWriteTimeout/1_GiB_nar1685=== PAUSE TestProxyWriteTimeout/1_GiB_nar1686=== RUN TestProxyWriteTimeout/10_GiB_nar1687=== PAUSE TestProxyWriteTimeout/10_GiB_nar1688=== RUN TestProxyWriteTimeout/unknown_size1689=== PAUSE TestProxyWriteTimeout/unknown_size1690=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle16912026/10/01 09:39:13 INFO Vacuumed table table=pending_closures16922026/10/01 09:39:13 INFO Vacuumed table table=pending_objects16932026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads16942026/10/01 09:39:13 INFO Vacuumed table table=closures16952026/10/01 09:39:13 INFO Vacuumed table table=objects1696--- PASS: TestSweepRechecksPendingAfterLocking (0.78s)1697=== CONT TestResolveDBConnectionString1698=== NAME TestNARDeduplicationMetadataUploadBug1699 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug706195208/001/store/557xy0a4qbgw12k2jgzyx41wbfia21ig-file2.txt1700=== RUN TestResolveDBConnectionString/flag_wins1701=== PAUSE TestResolveDBConnectionString/flag_wins1702=== RUN TestResolveDBConnectionString/file_when_flag_empty1703=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1704=== RUN TestResolveDBConnectionString/missing_file_is_an_error1705=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1706=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1707=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1708=== RUN TestResolveDBConnectionString/nothing_configured1709=== PAUSE TestResolveDBConnectionString/nothing_configured1710=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1711--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.71s)1712=== CONT TestCompleteMultipartUpload_ErrorButObjectExists17132026/10/01 09:39:13 INFO Aborted multipart uploads count=01714=== NAME TestOrphanedObjectsGC1715 orphaned_objects_gc_test.go:290: GC Test Summary:1716 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1717 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1718 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1719 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1720 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1721--- PASS: TestOrphanedObjectsGC (1.42s)1722=== CONT TestClientFallsBackToClosures17232026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period17242026/10/01 09:39:13 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=017252026/10/01 09:39:13 INFO Vacuumed table table=pending_closures17262026/10/01 09:39:13 INFO Vacuumed table table=pending_objects17272026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads17282026/10/01 09:39:13 INFO Vacuumed table table=closures17292026/10/01 09:39:13 INFO Vacuumed table table=objects17302026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures17312026/10/01 09:39:13 INFO Aborted multipart uploads count=017322026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period17332026/10/01 09:39:13 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=017342026/10/01 09:39:13 INFO Vacuumed table table=pending_closures17352026/10/01 09:39:13 INFO Vacuumed table table=pending_objects17362026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads17372026/10/01 09:39:13 INFO Vacuumed table table=closures17382026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures17392026/10/01 09:39:13 INFO Vacuumed table table=objects1740--- PASS: TestSweepSkipsRowsLockedByPush (0.76s)1741=== CONT TestParseSize1742--- PASS: TestParseSize (0.00s)1743=== CONT TestClientPushesUseOnePush17442026-10-01 09:39:13.914 UTC [865] ERROR: relation "goose_db_version" does not exist at character 3617452026-10-01 09:39:13.914 UTC [865] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17462026/10/01 09:39:13 INFO Received push request method=POST path=/api/pushes17472026/10/01 09:39:13 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17482026/10/01 09:39:13 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17492026/10/01 09:39:13 INFO Signed narinfos id=2 count=117502026/10/01 09:39:13 WARN Failed to register uploaded object key=557xy0a4qbgw12k2jgzyx41wbfia21ig.ls error="server returned 404: 404 page not found\n"17512026/10/01 09:39:13 INFO Uploading 1 narinfos17522026/10/01 09:39:13 OK 20241026095416_initial_model.sql (10.87ms)17532026/10/01 09:39:13 INFO Received complete push request method=POST path=/api/pushes/2/complete17542026/10/01 09:39:13 WARN Failed to register uploaded object key=557xy0a4qbgw12k2jgzyx41wbfia21ig.narinfo error="server returned 404: 404 page not found\n"17552026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)17562026/10/01 09:39:13 INFO Upload complete. (54ms)1757=== NAME TestNARDeduplicationMetadataUploadBug1758 metadata_upload_test.go:76: Retrieved narinfo from S3:1759 StorePath: /build/TestNARDeduplicationMetadataUploadBug706195208/001/store/557xy0a4qbgw12k2jgzyx41wbfia21ig-file2.txt1760 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1761 Compression: zstd1762 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1763 NarSize: 1601764 References: 1765 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf17662026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.58ms)1767 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1768 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1769 {"version":1,"root":{"type":"regular","size":44}}17702026-10-01 09:39:13.941 UTC [885] ERROR: relation "goose_db_version" does not exist at character 3617712026-10-01 09:39:13.941 UTC [885] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17722026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.48ms)1773--- PASS: TestNARDeduplicationMetadataUploadBug (1.03s)1774=== CONT TestService_Rustfstest17752026/10/01 09:39:13 INFO Aborted multipart uploads count=017762026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.55ms)17772026-10-01 09:39:13.946 UTC [887] ERROR: relation "goose_db_version" does not exist at character 3617782026-10-01 09:39:13.946 UTC [887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17792026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period17802026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.18ms)17812026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures17822026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (10.48ms)17832026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000017842026/10/01 09:39:13 OK 20241026095416_initial_model.sql (15.68ms)17852026/10/01 09:39:13 OK 1_commit_pending_closure.sql (4.15ms)17862026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)17872026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.6ms)17882026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures17892026/10/01 09:39:13 OK 3_commit_push.sql (1.81ms)17902026/10/01 09:39:13 goose: up to current file version: 317912026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.27ms)1792--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.73s)1793=== CONT TestPinProtectsFromGC17942026/10/01 09:39:13 INFO Aborted multipart uploads count=017952026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)17962026/10/01 09:39:13 OK 20241026095416_initial_model.sql (11.53ms)17972026/10/01 09:39:13 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=017982026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period17992026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (4.03ms)18002026/10/01 09:39:13 INFO Vacuumed table table=pending_closures18012026/10/01 09:39:13 OK 20260905000000_add_claims.sql (6.51ms)18022026/10/01 09:39:13 INFO Vacuumed table table=pending_objects18032026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads18042026/10/01 09:39:13 INFO Vacuumed table table=closures18052026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.81ms)18062026/10/01 09:39:13 OK 20251218171726_add_pins.sql (6.4ms)18072026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.71ms)18082026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000018092026/10/01 09:39:13 INFO Vacuumed table table=objects1810--- PASS: TestGCSweepDeliversEachKeyOnce (0.76s)1811=== CONT TestPresignedUploadRegisteredBeforeCommit18122026/10/01 09:39:13 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."18132026/10/01 09:39:13 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."18142026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)18152026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.46ms)18162026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.6ms)1817--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.72s)1818=== CONT TestCompletedNarNotReofferedAcrossClosures18192026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.5ms)18202026/10/01 09:39:13 OK 3_commit_push.sql (1.24ms)1821--- PASS: TestFailedS3DeleteKeepsTombstone (0.83s)18222026/10/01 09:39:13 goose: up to current file version: 31823=== CONT TestClientSharedPathCommittedMidPush18242026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.15ms)18252026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures18262026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.02ms)18272026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000018282026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.85ms)18292026-10-01 09:39:14.001 UTC [897] ERROR: relation "goose_db_version" does not exist at character 3618302026-10-01 09:39:14.001 UTC [897] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18312026-10-01 09:39:14.002 UTC [895] ERROR: relation "goose_db_version" does not exist at character 3618322026-10-01 09:39:14.002 UTC [895] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18332026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.27ms)18342026/10/01 09:39:14 OK 3_commit_push.sql (1.27ms)18352026/10/01 09:39:14 goose: up to current file version: 318362026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18372026/10/01 09:39:14 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1838--- PASS: TestCompleteMultipartUnregistered (0.66s)1839=== CONT TestClientWithDependencies18402026-10-01 09:39:14.016 UTC [902] ERROR: relation "goose_db_version" does not exist at character 3618412026-10-01 09:39:14.016 UTC [902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18422026/10/01 09:39:14 INFO Aborted multipart uploads count=018432026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.05ms)18442026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.78ms)18452026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)18462026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period18472026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)18482026/10/01 09:39: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=018492026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5.64ms)18502026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.37ms)18512026/10/01 09:39:14 INFO Vacuumed table table=pending_closures18522026-10-01 09:39:14.030 UTC [905] ERROR: relation "goose_db_version" does not exist at character 3618532026-10-01 09:39:14.030 UTC [905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18542026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (15.92ms)18552026/10/01 09:39:14 OK 20241026095416_initial_model.sql (17.91ms)18562026/10/01 09:39:14 INFO Vacuumed table table=pending_objects18572026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (16.16ms)18582026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads18592026/10/01 09:39:14 INFO Vacuumed table table=closures18602026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures18612026/10/01 09:39:14 OK 20260905000000_add_claims.sql (5.45ms)18622026/10/01 09:39:14 INFO Vacuumed table table=objects18632026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (5.67ms)18642026/10/01 09:39:14 OK 20260905000000_add_claims.sql (6.66ms)18652026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.29ms)18662026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.22ms)18672026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.05ms)18682026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (4.11ms)18692026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000018702026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.18ms)18712026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.48ms)18722026/10/01 09:39:14 goose: successfully migrated database to version: 202609231200001873--- PASS: TestGCSweepSkipsPendingObjects (0.75s)1874=== CONT TestCacheConfigHandler1875=== RUN TestCacheConfigHandler/full_config,_no_issuer1876=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1877=== RUN TestCacheConfigHandler/no_cache_url_configured1878=== PAUSE TestCacheConfigHandler/no_cache_url_configured18792026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures1880=== RUN TestCacheConfigHandler/no_signing_keys1881=== PAUSE TestCacheConfigHandler/no_signing_keys1882=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator18832026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.25ms)1884=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1885=== CONT TestClientMultipleUploads18862026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)1887--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.59s)1888=== CONT TestService_ReadScope_PublicByDefault18892026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.57ms)18902026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.73ms)18912026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.36ms)18922026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.35ms)18932026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.6ms)18942026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.16ms)18952026/10/01 09:39:14 OK 3_commit_push.sql (1.74ms)18962026/10/01 09:39:14 goose: up to current file version: 318972026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.13ms)18982026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000018992026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.77ms)19002026/10/01 09:39:14 OK 2_object_stats_trigger.sql (5.26ms)19012026/10/01 09:39:14 OK 3_commit_push.sql (1.73ms)19022026/10/01 09:39:14 goose: up to current file version: 319032026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.99ms)19042026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4ms)19052026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.21ms)19062026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.72ms)19072026/10/01 09:39:14 OK 3_commit_push.sql (2.33ms)19082026/10/01 09:39:14 goose: up to current file version: 319092026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.13ms)19102026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000019112026-10-01 09:39:14.075 UTC [910] ERROR: relation "goose_db_version" does not exist at character 3619122026-10-01 09:39:14.075 UTC [910] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19132026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.79ms)19142026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.29ms)19152026/10/01 09:39:14 INFO Received cleanup request method=DELETE path=/api/pending_closures19162026/10/01 09:39:14 OK 3_commit_push.sql (1.45ms)19172026/10/01 09:39:14 goose: up to current file version: 319182026/10/01 09:39:14 INFO Aborted multipart uploads count=019192026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures19202026/10/01 09:39:14 OK 20241026095416_initial_model.sql (25.37ms)19212026/10/01 09:39:14 INFO Received cleanup request method=DELETE path=/api/pending_closures19222026/10/01 09:39:14 INFO Aborted multipart uploads count=119232026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)19242026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19252026-10-01 09:39:14.112 UTC [805] ERROR: Closure does not exist: id=119262026-10-01 09:39:14.112 UTC [805] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE19272026-10-01 09:39:14.112 UTC [805] STATEMENT: -- name: CommitPendingClosure :exec1928 SELECT commit_pending_closure($1::bigint)1929 1930--- PASS: TestService_cleanupPendingClosuresHandler (0.54s)1931=== CONT TestClientIntegration19322026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.76ms)1933--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.94s)1934=== CONT TestService_RequireScope_OIDC19352026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.34ms)19362026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.28ms)19372026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.76ms)19382026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.08ms)19392026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000019402026-10-01 09:39:14.129 UTC [913] ERROR: relation "goose_db_version" does not exist at character 3619412026-10-01 09:39:14.129 UTC [913] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19422026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.04ms)19432026-10-01 09:39:14.130 UTC [914] ERROR: relation "goose_db_version" does not exist at character 3619442026-10-01 09:39:14.130 UTC [914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19452026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.62ms)19462026/10/01 09:39:14 OK 3_commit_push.sql (964.85µs)19472026/10/01 09:39:14 goose: up to current file version: 319482026-10-01 09:39:14.132 UTC [916] ERROR: relation "goose_db_version" does not exist at character 3619492026-10-01 09:39:14.132 UTC [916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19502026/10/01 09:39:14 INFO Aborted multipart uploads count=019512026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period19522026-10-01 09:39:14.140 UTC [917] ERROR: relation "goose_db_version" does not exist at character 3619532026-10-01 09:39:14.140 UTC [917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19542026/10/01 09:39: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=019552026/10/01 09:39:14 INFO Vacuumed table table=pending_closures19562026/10/01 09:39:14 INFO Vacuumed table table=pending_objects19572026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.62ms)19582026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads19592026/10/01 09:39:14 INFO Vacuumed table table=closures19602026/10/01 09:39:14 INFO Vacuumed table table=objects19612026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures19622026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures19632026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures19642026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.56ms)19652026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.58ms)19662026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.22ms)19672026-10-01 09:39:14.150 UTC [918] ERROR: relation "goose_db_version" does not exist at character 3619682026-10-01 09:39:14.150 UTC [918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1969--- PASS: TestGCMetrics (0.59s)1970=== CONT TestClientErrorHandling1971=== RUN TestClientErrorHandling/InvalidStorePath1972=== PAUSE TestClientErrorHandling/InvalidStorePath1973=== RUN TestClientErrorHandling/InvalidAuthToken1974=== PAUSE TestClientErrorHandling/InvalidAuthToken1975=== RUN TestClientErrorHandling/ServerNotAvailable1976=== PAUSE TestClientErrorHandling/ServerNotAvailable1977=== CONT TestService_AuthMiddleware_OIDC19782026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.59ms)19792026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (3.58ms)19802026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (4.09ms)19812026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.01ms)19822026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.03ms)19832026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)19842026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.43ms)19852026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)19862026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)19872026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.71ms)19882026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.17ms)19892026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.65ms)1990--- PASS: TestPushWaitsForSweepHoldingRow (1.12s)1991=== CONT TestClientCADerivations19922026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.7ms)19932026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.15ms)19942026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.29ms)19952026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.9ms)19962026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.26ms)19972026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000019982026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)19992026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.54ms)20002026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)20012026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.67ms)20022026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.76ms)20032026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020042026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.1ms)20052026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.04ms)20062026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.3ms)20072026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020082026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.96ms)20092026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.1ms)20102026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.98ms)20112026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.3ms)20122026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.67ms)20132026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.47ms)20142026/10/01 09:39:14 OK 3_commit_push.sql (1.52ms)20152026/10/01 09:39:14 goose: up to current file version: 320162026/10/01 09:39:14 OK 3_commit_push.sql (11.33ms)20172026/10/01 09:39:14 goose: up to current file version: 320182026/10/01 09:39:14 OK 2_object_stats_trigger.sql (11.4ms)20192026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (11.72ms)20202026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020212026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (13.98ms)20222026/10/01 09:39:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46597/oidc20232026/10/01 09:39:14 OK 3_commit_push.sql (1.33ms)20242026/10/01 09:39:14 goose: up to current file version: 320252026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.81ms)20262026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.15ms)20272026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.37ms)20282026/10/01 09:39:14 OK 3_commit_push.sql (1.55ms)20292026/10/01 09:39:14 goose: up to current file version: 320302026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.81ms)20312026-10-01 09:39:14.194 UTC [922] ERROR: relation "goose_db_version" does not exist at character 3620322026-10-01 09:39:14.194 UTC [922] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20332026-10-01 09:39:14.194 UTC [923] ERROR: relation "goose_db_version" does not exist at character 3620342026-10-01 09:39:14.194 UTC [923] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20352026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.92ms)20362026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020372026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.42ms)20382026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.32ms)20392026/10/01 09:39:14 OK 3_commit_push.sql (1.03ms)20402026/10/01 09:39:14 goose: up to current file version: 320412026/10/01 09:39:14 INFO lead: acquired remote=192.0.2.1:123420422026/10/01 09:39:14 INFO lead: released remote=192.0.2.1:12342043--- PASS: TestLeadEndsOnShutdown (0.41s)2044=== CONT TestService_ReadAuthMiddleware20452026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.26ms)20462026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.07ms)20472026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)20482026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)20492026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures20502026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.06ms)20512026-10-01 09:39:14.216 UTC [927] ERROR: relation "goose_db_version" does not exist at character 3620522026-10-01 09:39:14.216 UTC [927] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20532026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5.7ms)20542026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)20552026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)20562026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.7ms)20572026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.79ms)20582026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.32ms)20592026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.7ms)20602026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020612026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.6ms)20622026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.35ms)20632026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.17ms)20642026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020652026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.88ms)20662026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.27ms)20672026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)20682026/10/01 09:39:14 OK 3_commit_push.sql (1.33ms)20692026/10/01 09:39:14 goose: up to current file version: 320702026/10/01 09:39:14 INFO lead: acquired remote=192.0.2.1:123420712026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.93ms)20722026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.51ms)20732026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.2ms)20742026/10/01 09:39:14 OK 3_commit_push.sql (2.19ms)20752026/10/01 09:39:14 goose: up to current file version: 320762026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)20772026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.1ms)20782026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.36ms)20792026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.15ms)20802026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020812026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.1ms)20822026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.93ms)20832026/10/01 09:39:14 OK 3_commit_push.sql (1.75ms)20842026/10/01 09:39:14 goose: up to current file version: 320852026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures20862026-10-01 09:39:14.285 UTC [929] ERROR: relation "goose_db_version" does not exist at character 3620872026-10-01 09:39:14.285 UTC [929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20882026/10/01 09:39:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38913/oidc20892026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures20902026/10/01 09:39:14 INFO Aborted multipart uploads count=020912026-10-01 09:39:14.292 UTC [931] ERROR: relation "goose_db_version" does not exist at character 3620922026-10-01 09:39:14.292 UTC [931] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20932026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.92ms)20942026/10/01 09:39: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=020952026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)20962026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.76ms)20972026/10/01 09:39:14 INFO Vacuumed table table=pending_closures20982026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.83ms)20992026/10/01 09:39:14 INFO Vacuumed table table=pending_objects21002026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)21012026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads21022026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)21032026/10/01 09:39:14 INFO Vacuumed table table=closures21042026-10-01 09:39:14.317 UTC [934] ERROR: relation "goose_db_version" does not exist at character 3621052026-10-01 09:39:14.317 UTC [934] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21062026/10/01 09:39:14 OK 20260905000000_add_claims.sql (11.66ms)21072026/10/01 09:39:14 OK 20251218171726_add_pins.sql (13.35ms)21082026/10/01 09:39:14 INFO Vacuumed table table=objects21092026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (4.58ms)21102026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.58ms)21112026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21122026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.49ms)21132026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021142026/10/01 09:39:14 INFO Aborted multipart uploads count=021152026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.26ms)21162026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.16ms)21172026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period21182026/10/01 09:39:14 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzA4ZWU0OTctNjU2My00ZTk4LWJiMjItMjAzNWU4MTA4YTgxLmNiZTFhOGMzLWRlNDQtNGNiYy04YzBkLTBiNTVhMTA3ZTg4M3gxNzkwODQ3NTU0Mjk5MTYzNzYw21192026/10/01 09:39: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=021202026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.26ms)21212026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.46ms)21222026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.85ms)21232026/10/01 09:39:14 OK 3_commit_push.sql (1.53ms)21242026/10/01 09:39:14 goose: up to current file version: 321252026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.94ms)21262026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021272026/10/01 09:39:14 INFO Vacuumed table table=pending_closures21282026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.72ms)21292026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.44ms)21302026/10/01 09:39:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzA4ZWU0OTctNjU2My00ZTk4LWJiMjItMjAzNWU4MTA4YTgxLmNiZTFhOGMzLWRlNDQtNGNiYy04YzBkLTBiNTVhMTA3ZTg4M3gxNzkwODQ3NTU0Mjk5MTYzNzYw parts=12131--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.50s)2132=== CONT TestCacheStatsHandler21332026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.94ms)21342026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.73ms)21352026/10/01 09:39:14 OK 3_commit_push.sql (1.07ms)21362026/10/01 09:39:14 goose: up to current file version: 321372026/10/01 09:39:14 INFO Vacuumed table table=pending_objects21382026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads21392026/10/01 09:39:14 INFO Vacuumed table table=closures21402026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)21412026/10/01 09:39:14 INFO Vacuumed table table=objects2142--- PASS: TestGCBugBareHashReferences (0.75s)2143=== CONT TestService_AuthMiddleware_MTLSBoundSubjects2144--- PASS: TestPushDedupSurvivesConcurrentGC (0.80s)2145=== CONT TestService_AuthMiddleware_MTLSProxyHeader21462026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.69ms)21472026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.79ms)21482026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.51ms)21492026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021502026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.67ms)21512026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.66ms)21522026/10/01 09:39:14 OK 3_commit_push.sql (2.05ms)21532026/10/01 09:39:14 goose: up to current file version: 321542026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21552026/10/01 09:39:14 INFO lead: released remote=192.0.2.1:123421562026-10-01 09:39:14.398 UTC [976] ERROR: relation "goose_db_version" does not exist at character 3621572026-10-01 09:39:14.398 UTC [976] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2158--- PASS: TestService_Rustfstest (0.46s)2159=== CONT TestPush_RejectsBadRequests21602026/10/01 09:39:14 OK 20241026095416_initial_model.sql (12.43ms)21612026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)21622026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.52ms)21632026/10/01 09:39:14 INFO lead: acquired remote=192.0.2.1:123421642026/10/01 09:39:14 INFO lead: released remote=192.0.2.1:12342165--- PASS: TestLeadElectsOneAndHandsOver (0.63s)2166=== CONT TestRedundantMultipartUpload21672026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (20.92ms)21682026/10/01 09:39:14 OK 20260905000000_add_claims.sql (5.4ms)21692026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures21702026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.46ms)21712026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.14ms)21722026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021732026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.73ms)21742026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.07ms)21752026/10/01 09:39:14 OK 3_commit_push.sql (1.54ms)21762026/10/01 09:39:14 goose: up to current file version: 321772026-10-01 09:39:14.466 UTC [1050] ERROR: relation "goose_db_version" does not exist at character 3621782026-10-01 09:39:14.466 UTC [1050] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21792026-10-01 09:39:14.474 UTC [1053] ERROR: relation "goose_db_version" does not exist at character 3621802026-10-01 09:39:14.474 UTC [1053] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21812026/10/01 09:39:14 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst21822026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures21832026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures2184--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.49s)2185=== CONT TestPush_SignsNarinfosOfItsPendingObjects21862026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.49ms)21872026-10-01 09:39:14.487 UTC [1072] ERROR: relation "goose_db_version" does not exist at character 3621882026-10-01 09:39:14.487 UTC [1072] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21892026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)21902026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.27ms)21912026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.73ms)21922026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21932026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)21942026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.78ms)21952026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)21962026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.73ms)21972026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.27ms)21982026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.27ms)21992026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.74ms)22002026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.43ms)22012026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.32ms)22022026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022032026/10/01 09:39:14 OK 20241026095416_initial_model.sql (12.44ms)22042026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.23ms)22052026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022062026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.11ms)22072026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)22082026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.18ms)22092026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.12ms)22102026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.92ms)22112026/10/01 09:39:14 OK 3_commit_push.sql (1.73ms)22122026/10/01 09:39:14 goose: up to current file version: 322132026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.41ms)22142026/10/01 09:39:14 OK 3_commit_push.sql (1.09ms)22152026/10/01 09:39:14 goose: up to current file version: 322162026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.67ms)22172026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.63ms)22182026/10/01 09:39:14 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzA4ZWU0OTctNjU2My00ZTk4LWJiMjItMjAzNWU4MTA4YTgxLjViZTQxYzNmLTNhN2EtNDE5Ni05YTUxLWVkMTMzZTNmNTU1M3gxNzkwODQ3NTU0MDY2NzI4NzQx parts=1022192026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22202026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.76ms)22212026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.77ms)22222026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022232026/10/01 09:39:14 INFO Completed upload id=122242026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.28ms)22252026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures22262026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures22272026-10-01 09:39:14.542 UTC [1166] ERROR: relation "goose_db_version" does not exist at character 3622282026-10-01 09:39:14.542 UTC [1166] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22292026/10/01 09:39:14 OK 2_object_stats_trigger.sql (18.24ms)22302026/10/01 09:39:14 OK 3_commit_push.sql (3.73ms)22312026/10/01 09:39:14 goose: up to current file version: 322322026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22332026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures22342026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures22352026/10/01 09:39:14 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22362026/10/01 09:39:14 INFO Uploading vw250ylvsg66cfvcijmpd1mjk0mqp3zv-shared-dep (136B)22372026/10/01 09:39:14 INFO Uploading 5raa6kmj0xbbbba8828k46y1bjcmdz0m-b (216B)22382026/10/01 09:39:14 WARN Failed to register uploaded object key=vw250ylvsg66cfvcijmpd1mjk0mqp3zv.ls error="server returned 404: 404 page not found\n"22392026/10/01 09:39:14 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo22402026/10/01 09:39:14 WARN Found objects in DB but missing from S3, will re-upload count=122412026/10/01 09:39:14 WARN Failed to register uploaded object key=xzf6lzm8pp1skrnhfwvmg9v9yw5my736.ls error="server returned 404: 404 page not found\n"2242--- PASS: TestService_verifyS3Integrity (1.08s)22432026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.8ms)2244=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit22452026/10/01 09:39:14 WARN Failed to register uploaded object key=5raa6kmj0xbbbba8828k46y1bjcmdz0m.ls error="server returned 404: 404 page not found\n"22462026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22472026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22482026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1zbkyzvryia0i2397prpj4891jfnlp6nvk0lz75yb6c6lp0wk373.nar.zst error="server returned 404: 404 page not found\n"22492026/10/01 09:39:14 INFO Signed narinfos id=1 count=222502026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22512026/10/01 09:39:14 INFO Signed narinfos id=2 count=222522026/10/01 09:39:14 INFO Uploading 4 narinfos22532026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)22542026/10/01 09:39:14 WARN Failed to register uploaded object key=vw250ylvsg66cfvcijmpd1mjk0mqp3zv.narinfo error="server returned 404: 404 page not found\n"22552026/10/01 09:39:14 WARN Failed to register uploaded object key=xzf6lzm8pp1skrnhfwvmg9v9yw5my736.narinfo error="server returned 404: 404 page not found\n"22562026/10/01 09:39:14 WARN Failed to register uploaded object key=5raa6kmj0xbbbba8828k46y1bjcmdz0m.narinfo error="server returned 404: 404 page not found\n"22572026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.3ms)22582026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22592026/10/01 09:39:14 WARN Failed to register uploaded object key=vw250ylvsg66cfvcijmpd1mjk0mqp3zv.narinfo error="server returned 404: 404 page not found\n"22602026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.33ms)22612026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.43ms)22622026/10/01 09:39:14 INFO Completed upload id=122632026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22642026/10/01 09:39:14 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzA4ZWU0OTctNjU2My00ZTk4LWJiMjItMjAzNWU4MTA4YTgxLjJhNzQ1YTIxLTBlOTctNGQ2OC05YTM3LWNjMTNiZTQ2NGQ5MHgxNzkwODQ3NTU0MTYxMDIwNzY4 parts=1022652026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22662026/10/01 09:39:14 INFO Completed upload id=222672026/10/01 09:39:14 INFO Upload complete. (96ms)22682026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.2ms)2269=== NAME TestClientFallsBackToClosures2270 client_pushes_test.go:112: Retrieved narinfo from S3:2271 StorePath: /build/TestClientFallsBackToClosures3165814040/001/store/vw250ylvsg66cfvcijmpd1mjk0mqp3zv-shared-dep2272 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2273 Compression: zstd2274 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822275 NarSize: 1362276 References: 2277 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2278--- PASS: TestService_ReadScope_PublicByDefault (0.52s)2279=== CONT TestPush_CompleteCommitsEveryRoot22802026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.53ms)22812026/10/01 09:39:14 goose: successfully migrated database to version: 202609231200002282=== NAME TestClientFallsBackToClosures2283 client_pushes_test.go:112: Retrieved narinfo from S3:2284 StorePath: /build/TestClientFallsBackToClosures3165814040/001/store/xzf6lzm8pp1skrnhfwvmg9v9yw5my736-a2285 URL: nar/1zbkyzvryia0i2397prpj4891jfnlp6nvk0lz75yb6c6lp0wk373.nar.zst2286 Compression: zstd2287 NarHash: sha256:1zbkyzvryia0i2397prpj4891jfnlp6nvk0lz75yb6c6lp0wk3732288 NarSize: 2162289 References: /build/TestClientFallsBackToClosures3165814040/001/store/vw250ylvsg66cfvcijmpd1mjk0mqp3zv-shared-dep2290 CA: text:sha256:15i93m107baggyv6yr70b5r1p1vxprjqg3qqvm7lh6s40s0wgx9922912026-10-01 09:39:14.582 UTC [1222] ERROR: relation "goose_db_version" does not exist at character 3622922026-10-01 09:39:14.582 UTC [1222] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22932026/10/01 09:39:14 INFO Completed upload id=12294 client_pushes_test.go:112: Retrieved narinfo from S3:22952026/10/01 09:39:14 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002296 StorePath: /build/TestClientFallsBackToClosures3165814040/001/store/5raa6kmj0xbbbba8828k46y1bjcmdz0m-b22972026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.5ms)2298 URL: nar/1zbkyzvryia0i2397prpj4891jfnlp6nvk0lz75yb6c6lp0wk373.nar.zst2299 Compression: zstd2300 NarHash: sha256:1zbkyzvryia0i2397prpj4891jfnlp6nvk0lz75yb6c6lp0wk3732301 NarSize: 2162302 References: /build/TestClientFallsBackToClosures3165814040/001/store/vw250ylvsg66cfvcijmpd1mjk0mqp3zv-shared-dep2303 CA: text:sha256:15i93m107baggyv6yr70b5r1p1vxprjqg3qqvm7lh6s40s0wgx9923042026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures23052026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.24ms)23062026/10/01 09:39:14 OK 3_commit_push.sql (1.22ms)23072026/10/01 09:39:14 goose: up to current file version: 323082026/10/01 09:39:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures2309--- PASS: TestClientFallsBackToClosures (0.75s)2310=== CONT TestParseSingleRange/start_far_past_EOF2311=== CONT TestParseSingleRange/none2312=== CONT TestParseSingleRange/start_past_EOF2313=== CONT TestParseSingleRange/single_byte2314=== CONT TestParseSingleRange/suffix_exceeds_size2315=== CONT TestParseSingleRange/suffix2316=== CONT TestParseSingleRange/end_clamped_to_size2317=== CONT TestParseSingleRange/open-ended2318=== CONT TestParseSingleRange/closed2319=== CONT TestParseSingleRange/malformed_end_before_start2320=== CONT TestParseSingleRange/malformed_both_empty2321=== CONT TestParseSingleRange/malformed_no_dash2322=== CONT TestParseSingleRange/multi-range_ignored2323=== CONT TestParseSingleRange/unknown_unit2324--- PASS: TestParseSingleRange (0.00s)2325 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2326 --- PASS: TestParseSingleRange/none (0.00s)2327 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2328 --- PASS: TestParseSingleRange/single_byte (0.00s)2329 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2330 --- PASS: TestParseSingleRange/suffix (0.00s)2331 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2332 --- PASS: TestParseSingleRange/open-ended (0.00s)2333 --- PASS: TestParseSingleRange/closed (0.00s)2334 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2335 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2336 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2337 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2338 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2339=== CONT TestIsValidCachePath/narinfo2340=== CONT TestIsValidCachePath/nix-cache-info2341=== CONT TestIsValidCachePath/realisation2342=== CONT TestIsValidCachePath/short_hash2343=== CONT TestIsValidCachePath/log2344=== CONT TestIsValidCachePath/ls2345=== CONT TestIsValidCachePath/nar_uncompressed2346=== CONT TestIsValidCachePath/nar_bz22347=== CONT TestIsValidCachePath/nar_xz2348=== CONT TestIsValidCachePath/nar_zst2349=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2350=== CONT TestIsValidCachePath/random_path2351=== CONT TestIsValidCachePath/wrong_extension2352=== CONT TestIsValidCachePath/leading_slash2353=== CONT TestIsValidCachePath/empty2354=== CONT TestIsValidCachePath/invalid_char_e2355=== CONT TestIsValidCachePath/invalid_char_u2356=== CONT TestIsValidCachePath/traversal_in_middle2357=== CONT TestIsValidCachePath/traversal_parent2358=== CONT TestIsValidCachePath/index.html2359--- PASS: TestIsValidCachePath (0.00s)2360 --- PASS: TestIsValidCachePath/narinfo (0.00s)2361 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2362 --- PASS: TestIsValidCachePath/realisation (0.00s)2363 --- PASS: TestIsValidCachePath/short_hash (0.00s)2364 --- PASS: TestIsValidCachePath/log (0.00s)2365 --- PASS: TestIsValidCachePath/ls (0.00s)2366 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2367 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2368 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2369 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2370 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2371 --- PASS: TestIsValidCachePath/random_path (0.00s)2372 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2373 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2374 --- PASS: TestIsValidCachePath/empty (0.00s)2375 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2376 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2377 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2378 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2379 --- PASS: TestIsValidCachePath/index.html (0.00s)2380=== CONT TestServerTLSConfig/no_client_CA2381=== CONT TestServerTLSConfig/missing_CA_file2382=== CONT TestServerTLSConfig/not_a_PEM_file2383=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2384=== NAME TestPinProtectsFromGC2385 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2028143616/001/store/wng89dz8cqg7cv899gvmvfk0k3wysrw2-pinned-file.txt2386 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2028143616/001/store/2rf78zhlmnykvdpybczk17fls48japzk-unpinned-file.txt2387--- PASS: TestServerTLSConfig (0.00s)2388 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2389 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2390 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)23912026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes23922026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes23932026/10/01 09:39:14 INFO Aborted multipart uploads count=023942026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.8ms)23952026/10/01 09:39:14 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)23962026/10/01 09:39:14 INFO Uploading phjgw8jlvafh6xhz8l688g4rqk7pihs9-top (224B)23972026/10/01 09:39:14 INFO Uploading 3p6jcd9h3rpkzn079i8im8hw1gpfsym9-shared-dep (136B)23982026/10/01 09:39:14 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23992026/10/01 09:39:14 INFO Uploading nlgmck4ai81r675zby74xr9d4x0pwn1i-shared-dep (136B)24002026/10/01 09:39:14 INFO Uploading waxg81fs6qcpxb58681ykp7b9nl8md3j-b (216B)24012026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.29ms)24022026-10-01 09:39:14.604 UTC [1298] ERROR: relation "goose_db_version" does not exist at character 3624032026-10-01 09:39:14.604 UTC [1298] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24042026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.66ms)24052026/10/01 09:39:14 WARN Failed to register uploaded object key=phjgw8jlvafh6xhz8l688g4rqk7pihs9.ls error="server returned 404: 404 page not found\n"24062026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24072026/10/01 09:39:14 WARN Failed to register uploaded object key=3p6jcd9h3rpkzn079i8im8hw1gpfsym9.ls error="server returned 404: 404 page not found\n"24082026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2409=== NAME TestClientMultipleUploads24102026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0v2yb0474000s19966ffhggbrqzayrnnsyyp9nn1p4v6x7g1l8y1.nar.zst error="server returned 404: 404 page not found\n"2411 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3678369305/001/store/xaq32fnz13jm8i5i2qbz48x993c0gvmz-test-file-0.txt24122026/10/01 09:39:14 INFO Signed narinfos id=1 count=224132026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1nc4n78mj7w4wxcskbf4g0sd5kkd59g9mxv4mh65q3dr3zx3ksva.nar.zst error="server returned 404: 404 page not found\n"24142026/10/01 09:39:14 INFO Uploading 2 narinfos24152026/10/01 09:39:14 WARN Failed to register uploaded object key=nlgmck4ai81r675zby74xr9d4x0pwn1i.ls error="server returned 404: 404 page not found\n"24162026/10/01 09:39: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=024172026/10/01 09:39:14 WARN Failed to register uploaded object key=waxg81fs6qcpxb58681ykp7b9nl8md3j.ls error="server returned 404: 404 page not found\n"24182026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24192026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24202026/10/01 09:39:14 WARN Failed to register uploaded object key=mq6znyjgndbx50cmfavxnki37097f5m3.ls error="server returned 404: 404 page not found\n"24212026/10/01 09:39:14 INFO Signed narinfos id=1 count=324222026/10/01 09:39:14 INFO Uploading 3 narinfos24232026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.31ms)24242026/10/01 09:39:14 WARN Failed to register uploaded object key=3p6jcd9h3rpkzn079i8im8hw1gpfsym9.narinfo error="server returned 404: 404 page not found\n"24252026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete24262026/10/01 09:39:14 WARN Failed to register uploaded object key=phjgw8jlvafh6xhz8l688g4rqk7pihs9.narinfo error="server returned 404: 404 page not found\n"24272026/10/01 09:39:14 INFO Vacuumed table table=pending_closures24282026/10/01 09:39:14 WARN Failed to register uploaded object key=nlgmck4ai81r675zby74xr9d4x0pwn1i.narinfo error="server returned 404: 404 page not found\n"24292026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete24302026/10/01 09:39:14 WARN Failed to register uploaded object key=mq6znyjgndbx50cmfavxnki37097f5m3.narinfo error="server returned 404: 404 page not found\n"24312026/10/01 09:39:14 WARN Failed to register uploaded object key=waxg81fs6qcpxb58681ykp7b9nl8md3j.narinfo error="server returned 404: 404 page not found\n"24322026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.93ms)24332026/10/01 09:39:14 INFO Vacuumed table table=pending_objects24342026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.89ms)24352026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads24362026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.71ms)24372026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000024382026/10/01 09:39:14 INFO Upload complete. (61ms)2439=== NAME TestClientSharedPathCommittedMidPush2440 client_integration_test.go:680: Retrieved narinfo from S3:2441 StorePath: /build/TestClientSharedPathCommittedMidPush1582412595/001/store/3p6jcd9h3rpkzn079i8im8hw1gpfsym9-shared-dep2442 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2443 Compression: zstd2444 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822445 NarSize: 1362446 References: 2447 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n24482026/10/01 09:39:14 INFO Upload complete. (71ms)24492026/10/01 09:39:14 INFO Vacuumed table table=closures24502026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.55ms)24512026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.52ms)2452=== NAME TestClientPushesUseOnePush2453 client_pushes_test.go:97: Retrieved narinfo from S3:2454 StorePath: /build/TestClientPushesUseOnePush1063635377/001/store/nlgmck4ai81r675zby74xr9d4x0pwn1i-shared-dep2455 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2456 Compression: zstd2457 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822458 NarSize: 1362459 References: 2460 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2461=== NAME TestClientSharedPathCommittedMidPush2462 client_integration_test.go:680: Retrieved narinfo from S3:2463 StorePath: /build/TestClientSharedPathCommittedMidPush1582412595/001/store/phjgw8jlvafh6xhz8l688g4rqk7pihs9-top2464 URL: nar/0v2yb0474000s19966ffhggbrqzayrnnsyyp9nn1p4v6x7g1l8y1.nar.zst2465 Compression: zstd24662026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.36ms)2467 NarHash: sha256:0v2yb0474000s19966ffhggbrqzayrnnsyyp9nn1p4v6x7g1l8y12468 NarSize: 2242469 References: /build/TestClientSharedPathCommittedMidPush1582412595/001/store/3p6jcd9h3rpkzn079i8im8hw1gpfsym9-shared-dep2470 CA: text:sha256:0brgnbdh1zp9f2g965hvrpq3p7ccjghz2rgjjg30r3mdvj8c7fgs24712026/10/01 09:39:14 INFO Vacuumed table table=objects24722026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)2473=== NAME TestClientPushesUseOnePush2474 client_pushes_test.go:97: Retrieved narinfo from S3:2475 StorePath: /build/TestClientPushesUseOnePush1063635377/001/store/mq6znyjgndbx50cmfavxnki37097f5m3-a2476 URL: nar/1nc4n78mj7w4wxcskbf4g0sd5kkd59g9mxv4mh65q3dr3zx3ksva.nar.zst24772026/10/01 09:39:14 OK 3_commit_push.sql (1.21ms)2478 Compression: zstd24792026/10/01 09:39:14 goose: up to current file version: 32480 NarHash: sha256:1nc4n78mj7w4wxcskbf4g0sd5kkd59g9mxv4mh65q3dr3zx3ksva2481 NarSize: 2162482 References: /build/TestClientPushesUseOnePush1063635377/001/store/nlgmck4ai81r675zby74xr9d4x0pwn1i-shared-dep2483 CA: text:sha256:05y84hyqajbp3s3slblf3hpmypm9ms0avklzyc2lddcnkz1mhc422484 client_pushes_test.go:97: Retrieved narinfo from S3:2485 StorePath: /build/TestClientPushesUseOnePush1063635377/001/store/waxg81fs6qcpxb58681ykp7b9nl8md3j-b2486 URL: nar/1nc4n78mj7w4wxcskbf4g0sd5kkd59g9mxv4mh65q3dr3zx3ksva.nar.zst2487 Compression: zstd2488 NarHash: sha256:1nc4n78mj7w4wxcskbf4g0sd5kkd59g9mxv4mh65q3dr3zx3ksva2489 NarSize: 2162490 References: /build/TestClientPushesUseOnePush1063635377/001/store/nlgmck4ai81r675zby74xr9d4x0pwn1i-shared-dep2491 CA: text:sha256:05y84hyqajbp3s3slblf3hpmypm9ms0avklzyc2lddcnkz1mhc422492--- PASS: TestClientSharedPathCommittedMidPush (0.63s)24932026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.03ms)2494=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2495--- PASS: TestClientPushesUseOnePush (0.72s)2496=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure24972026/10/01 09:39:14 INFO Received uploads request method=POST path=/24982026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)2499=== NAME TestClientWithDependencies2500 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3256482185/001/store/pnrky3dwrscpxw318ddaj3kaipai2x8r-test-script25012026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.16ms)25022026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.25ms)25032026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.59ms)25042026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000025052026/10/01 09:39:14 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002506--- PASS: TestService_createPendingClosureHandler (1.08s)2507=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25082026/10/01 09:39:14 INFO Received request for more parts method=POST path=/25092026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.19ms)25102026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.05ms)25112026/10/01 09:39:14 OK 3_commit_push.sql (1.21ms)25122026/10/01 09:39:14 goose: up to current file version: 32513=== RUN TestService_RequireScope_OIDC/builder_may_write2514=== PAUSE TestService_RequireScope_OIDC/builder_may_write2515=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2516=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2517=== RUN TestService_RequireScope_OIDC/ops_may_admin2518=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2519=== RUN TestService_RequireScope_OIDC/ops_may_not_write2520=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2521=== RUN TestService_RequireScope_OIDC/reader_may_not_write2522=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2523=== RUN TestService_RequireScope_OIDC/static_token_may_admin2524=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2525=== RUN TestService_RequireScope_OIDC/static_token_may_write2526=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2527=== RUN TestService_RequireScope_OIDC/reader_may_read2528=== PAUSE TestService_RequireScope_OIDC/reader_may_read2529=== RUN TestService_RequireScope_OIDC/writer_implies_read2530=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2531=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2532=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2533=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25342026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/2535=== NAME TestClientMultipleUploads2536 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3678369305/001/store/vpvmkjaprbra0wyq5l1nh3asmv9f1kix-test-file-1.txt2537=== NAME TestClientIntegration2538 client_integration_test.go:286: Created store path: /build/TestClientIntegration441798058/002/store/w81n8rnqfx26spgs244m98zag6s09j5v-test-file.txt2539--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.82s)2540=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info25412026/10/01 09:39:14 INFO Received uploads request method=POST path=/2542=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key25432026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/2544=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key25452026/10/01 09:39:14 INFO Received request for more parts method=POST path=/2546=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal25472026/10/01 09:39:14 INFO Received uploads request method=POST path=/2548--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2549 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2550 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2551 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2552 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2553=== CONT TestIsValidUploadKey/traversal_nar2554=== CONT TestIsValidUploadKey/narinfo2555=== CONT TestIsValidUploadKey/unknown_type2556=== CONT TestIsValidUploadKey/traversal2557=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2558=== CONT TestIsValidUploadKey/empty_key2559=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2560=== CONT TestIsValidUploadKey/absolute2561=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2562=== CONT TestIsValidUploadKey/index.html2563=== CONT TestIsValidUploadKey/nix-cache-info2564=== CONT TestIsValidUploadKey/build_log2565=== CONT TestIsValidUploadKey/realisation_plus_in_output2566--- PASS: TestService_ReadAuthMiddleware (0.46s)2567=== CONT TestIsValidUploadKey/build_log_home-manager_file2568=== CONT TestIsValidUploadKey/realisation2569=== CONT TestIsValidUploadKey/nar_xz2570=== CONT TestIsValidUploadKey/build_log_equals2571=== CONT TestIsValidUploadKey/nar_plain2572=== CONT TestIsValidUploadKey/build_log_question_mark2573=== CONT TestIsValidUploadKey/listing2574=== CONT TestIsValidUploadKey/build_log_plus_in_name2575=== CONT TestProxyWriteTimeout/narinfo2576=== CONT TestIsValidUploadKey/nar_zst2577--- PASS: TestIsValidUploadKey (0.00s)2578 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2579 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2580 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2581 --- PASS: TestIsValidUploadKey/traversal (0.00s)2582 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2583 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2584 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2585 --- PASS: TestIsValidUploadKey/absolute (0.00s)2586 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2587 --- PASS: TestIsValidUploadKey/index.html (0.00s)2588 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2589 --- PASS: TestIsValidUploadKey/build_log (0.00s)2590 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2591 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2592 --- PASS: TestIsValidUploadKey/realisation (0.00s)2593 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2594 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2595 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2596 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2597 --- PASS: TestIsValidUploadKey/listing (0.00s)2598 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2599 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2600=== CONT TestProxyWriteTimeout/10_GiB_nar2601=== CONT TestProxyWriteTimeout/1_GiB_nar2602=== CONT TestProxyWriteTimeout/unknown_size2603--- PASS: TestProxyWriteTimeout (0.00s)2604 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2605 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2606 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2607 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2608=== CONT TestResolveDBConnectionString/flag_wins2609=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2610=== CONT TestResolveDBConnectionString/missing_file_is_an_error2611=== CONT TestResolveDBConnectionString/nothing_configured2612=== CONT TestResolveDBConnectionString/file_when_flag_empty2613=== CONT TestCacheConfigHandler/full_config,_no_issuer2614=== CONT TestCacheConfigHandler/no_signing_keys2615=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2616=== CONT TestClientErrorHandling/InvalidStorePath2617=== CONT TestCacheConfigHandler/no_cache_url_configured2618--- PASS: TestCacheConfigHandler (0.00s)2619 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2620 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2621 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2622 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2623--- PASS: TestResolveDBConnectionString (0.00s)2624 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2625 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2626 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2627 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2628 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2629=== CONT TestClientErrorHandling/ServerNotAvailable2630=== NAME TestClientWithDependencies2631 client_integration_test.go:615: Found 1 dependencies (including self)2632=== CONT TestClientErrorHandling/InvalidAuthToken26332026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2634=== CONT TestService_RequireScope_OIDC/builder_may_write2635=== CONT TestService_RequireScope_OIDC/reader_may_read2636=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2637=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2638=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2639=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2640=== CONT TestService_RequireScope_OIDC/static_token_may_write2641=== CONT TestService_RequireScope_OIDC/static_token_may_admin2642=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2643=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2644=== CONT TestService_RequireScope_OIDC/reader_may_not_write2645=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2646=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2647=== CONT TestService_RequireScope_OIDC/ops_may_not_write2648=== CONT TestService_RequireScope_OIDC/ops_may_admin2649=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2650=== CONT TestService_RequireScope_OIDC/writer_implies_read2651=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2652=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2653=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26542026/10/01 09:39:14 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]2655=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26562026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26572026/10/01 09:39:14 INFO Uploading wng89dz8cqg7cv899gvmvfk0k3wysrw2-pinned-file.txt (128B)2658--- PASS: TestService_RequireScope_OIDC (0.53s)2659 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2660 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2661 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2662 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2663 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2664 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2665 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2666 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2667 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2668 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2669=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured26702026/10/01 09:39:14 WARN Authentication failed token_preview=eyJhbGciOi...MQoV3HdBMA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2671--- PASS: TestService_AuthMiddleware_OIDC (0.53s)2672 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2673 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2674 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2675 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)26762026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"26772026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26782026/10/01 09:39:14 WARN Failed to register uploaded object key=wng89dz8cqg7cv899gvmvfk0k3wysrw2.ls error="server returned 404: 404 page not found\n"26792026/10/01 09:39:14 INFO Signed narinfos id=1 count=126802026/10/01 09:39:14 INFO Uploading 1 narinfos2681=== NAME TestClientMultipleUploads2682 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3678369305/001/store/2pn344lh4i1a7rw14jcwpmldcvbz275d-test-file-2.txt26832026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete26842026-10-01 09:39:14.694 UTC [1463] ERROR: relation "goose_db_version" does not exist at character 3626852026-10-01 09:39:14.694 UTC [1463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26862026/10/01 09:39:14 WARN Failed to register uploaded object key=wng89dz8cqg7cv899gvmvfk0k3wysrw2.narinfo error="server returned 404: 404 page not found\n"26872026/10/01 09:39:14 INFO Upload complete. (74ms)26882026-10-01 09:39:14.711 UTC [1515] ERROR: relation "goose_db_version" does not exist at character 3626892026-10-01 09:39:14.711 UTC [1515] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26902026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.28ms)26912026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)2692--- PASS: TestCacheStatsHandler (0.38s)26932026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.06ms)26942026-10-01 09:39:14.721 UTC [1518] ERROR: relation "goose_db_version" does not exist at character 3626952026-10-01 09:39:14.721 UTC [1518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26962026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.83ms)26972026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.3ms)26982026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.93ms)2699=== NAME TestClientCADerivations2700 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3859792391/001/store/i2h0wyf51a34lc3k7xnc14z76qzm1l8c-ca-test27012026/10/01 09:39:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"27022026/10/01 09:39:14 WARN mTLS auth: bound subjects configured but subject DN unavailable27032026/10/01 09:39:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2704--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.38s)27052026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)27062026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.55ms)27072026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.13ms)27082026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000027092026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.91ms)27102026/10/01 09:39:14 OK 1_commit_pending_closure.sql (1.88ms)27112026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.61ms)27122026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.04ms)27132026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)27142026/10/01 09:39:14 OK 3_commit_push.sql (1.56ms)27152026/10/01 09:39:14 goose: up to current file version: 327162026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)27172026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes27182026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.29ms)27192026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.2ms)27202026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.48ms)27212026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27222026/10/01 09:39:14 INFO Uploading w81n8rnqfx26spgs244m98zag6s09j5v-test-file.txt (152B)27232026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)27242026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.78ms)27252026/10/01 09:39:14 goose: successfully migrated database to version: 202609231200002726--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.40s)27272026/10/01 09:39:14 WARN Failed to register uploaded object key=w81n8rnqfx26spgs244m98zag6s09j5v.ls error="server returned 404: 404 page not found\n"27282026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"27292026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27302026/10/01 09:39:14 INFO Signed narinfos id=1 count=127312026/10/01 09:39:14 INFO Uploading 1 narinfos27322026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.27ms)27332026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.48ms)27342026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.55ms)27352026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete27362026/10/01 09:39:14 WARN Failed to register uploaded object key=w81n8rnqfx26spgs244m98zag6s09j5v.narinfo error="server returned 404: 404 page not found\n"27372026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.27ms)27382026/10/01 09:39:14 OK 3_commit_push.sql (1.27ms)27392026/10/01 09:39:14 goose: up to current file version: 327402026/10/01 09:39:14 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27412026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes27422026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.49ms)27432026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000027442026-10-01 09:39:14.754 UTC [1609] ERROR: relation "goose_db_version" does not exist at character 3627452026-10-01 09:39:14.754 UTC [1609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27462026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.22ms)27472026/10/01 09:39:14 INFO Upload complete. (70ms)27482026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.37ms)27492026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27502026/10/01 09:39:14 INFO Uploading pnrky3dwrscpxw318ddaj3kaipai2x8r-test-script (136B)27512026/10/01 09:39:14 OK 3_commit_push.sql (1.3ms)27522026/10/01 09:39:14 goose: up to current file version: 327532026/10/01 09:39:14 WARN Failed to register uploaded object key=log/hc2nanakh3xps7m7qbnyhmb96a9nlj0y-test-script.drv error="server returned 404: 404 page not found\n"27542026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"27552026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27562026/10/01 09:39:14 WARN Failed to register uploaded object key=pnrky3dwrscpxw318ddaj3kaipai2x8r.ls error="server returned 404: 404 page not found\n"27572026/10/01 09:39:14 INFO Signed narinfos id=1 count=127582026/10/01 09:39:14 INFO Uploading 1 narinfos2759=== RUN TestPush_RejectsBadRequests/no_objects2760=== PAUSE TestPush_RejectsBadRequests/no_objects2761=== RUN TestPush_RejectsBadRequests/bad_root2762=== PAUSE TestPush_RejectsBadRequests/bad_root2763=== RUN TestPush_RejectsBadRequests/root_not_in_objects2764=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2765=== RUN TestPush_RejectsBadRequests/no_roots2766=== PAUSE TestPush_RejectsBadRequests/no_roots2767=== CONT TestPush_RejectsBadRequests/no_objects27682026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2769=== CONT TestPush_RejectsBadRequests/root_not_in_objects27702026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2771=== CONT TestPush_RejectsBadRequests/no_roots27722026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2773=== CONT TestPush_RejectsBadRequests/bad_root27742026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2775--- PASS: TestPush_RejectsBadRequests (0.36s)2776 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2777 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2778 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2779 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)27802026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete27812026/10/01 09:39:14 WARN Failed to register uploaded object key=pnrky3dwrscpxw318ddaj3kaipai2x8r.narinfo error="server returned 404: 404 page not found\n"27822026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.97ms)27832026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.48ms)27842026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes27852026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes27862026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures27872026/10/01 09:39:14 OK 20251218171726_add_pins.sql (10.76ms)27882026/10/01 09:39:14 INFO Upload complete. (71ms)27892026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27902026/10/01 09:39:14 INFO Uploading 2rf78zhlmnykvdpybczk17fls48japzk-unpinned-file.txt (128B)2791=== NAME TestClientWithDependencies2792 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3256482185/001/store) requires matching store prefix27932026/10/01 09:39:14 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)27942026/10/01 09:39:14 INFO Uploading 2pn344lh4i1a7rw14jcwpmldcvbz275d-test-file-2.txt (160B)27952026/10/01 09:39:14 INFO Uploading vpvmkjaprbra0wyq5l1nh3asmv9f1kix-test-file-1.txt (160B)27962026/10/01 09:39:14 INFO Uploading xaq32fnz13jm8i5i2qbz48x993c0gvmz-test-file-0.txt (160B)27972026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)27982026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"27992026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign28002026/10/01 09:39:14 WARN Failed to register uploaded object key=2rf78zhlmnykvdpybczk17fls48japzk.ls error="server returned 404: 404 page not found\n"28012026/10/01 09:39:14 INFO Signed narinfos id=2 count=128022026/10/01 09:39:14 INFO Uploading 1 narinfos2803--- PASS: TestClientWithDependencies (0.77s)28042026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.75ms)28052026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"28062026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"28072026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"28082026/10/01 09:39:14 WARN Failed to register uploaded object key=2pn344lh4i1a7rw14jcwpmldcvbz275d.ls error="server returned 404: 404 page not found\n"28092026/10/01 09:39:14 WARN Failed to register uploaded object key=vpvmkjaprbra0wyq5l1nh3asmv9f1kix.ls error="server returned 404: 404 page not found\n"28102026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28112026/10/01 09:39:14 WARN Failed to register uploaded object key=xaq32fnz13jm8i5i2qbz48x993c0gvmz.ls error="server returned 404: 404 page not found\n"28122026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/2/complete28132026/10/01 09:39:14 WARN Failed to register uploaded object key=2rf78zhlmnykvdpybczk17fls48japzk.narinfo error="server returned 404: 404 page not found\n"2814=== NAME TestClientCADerivations2815 client_ca_test.go:139: Found 1 dependencies (including self)28162026/10/01 09:39:14 INFO Signed narinfos id=1 count=328172026/10/01 09:39:14 INFO Uploading 3 narinfos28182026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.18ms)28192026/10/01 09:39:14 INFO Upload complete. (52ms)28202026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.19ms)28212026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000028222026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures28232026/10/01 09:39:14 WARN Failed to register uploaded object key=vpvmkjaprbra0wyq5l1nh3asmv9f1kix.narinfo error="server returned 404: 404 page not found\n"28242026-10-01 09:39:14.794 UTC [1680] ERROR: relation "goose_db_version" does not exist at character 3628252026-10-01 09:39:14.794 UTC [1680] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28262026/10/01 09:39:14 WARN Failed to register uploaded object key=2pn344lh4i1a7rw14jcwpmldcvbz275d.narinfo error="server returned 404: 404 page not found\n"28272026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete28282026/10/01 09:39:14 OK 1_commit_pending_closure.sql (1.76ms)28292026/10/01 09:39:14 WARN Failed to register uploaded object key=xaq32fnz13jm8i5i2qbz48x993c0gvmz.narinfo error="server returned 404: 404 page not found\n"28302026/10/01 09:39:14 OK 2_object_stats_trigger.sql (968.06µs)28312026/10/01 09:39:14 OK 3_commit_push.sql (655.57µs)28322026/10/01 09:39:14 goose: up to current file version: 328332026-10-01 09:39:14.797 UTC [1681] ERROR: relation "goose_db_version" does not exist at character 3628342026-10-01 09:39:14.797 UTC [1681] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28352026/10/01 09:39:14 INFO Upload complete. (70ms)2836=== NAME TestClientMultipleUploads2837 client_integration_test.go:369: Uploaded 3 paths in 108.986349ms28382026/10/01 09:39:14 INFO All 1 paths already cached2839=== NAME TestClientIntegration2840 client_integration_test.go:312: Retrieved narinfo from S3:2841 StorePath: /build/TestClientIntegration441798058/002/store/w81n8rnqfx26spgs244m98zag6s09j5v-test-file.txt2842 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2843 Compression: zstd2844 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12845 NarSize: 1522846 References: 2847 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk128482026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2849 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2850 client_integration_test.go:313: Decompressed .ls content (64 bytes):2851 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2852 client_integration_test.go:316: Testing garbage collection...28532026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.8ms)28542026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.19ms)28552026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)2856--- PASS: TestClientMultipleUploads (0.76s)28572026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)28582026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28592026/10/01 09:39:14 INFO Signed narinfos id=1 count=12860--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.34s)28612026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.34ms)28622026/10/01 09:39:14 OK 20251218171726_add_pins.sql (1.95ms)28632026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (2.55ms)28642026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.15ms)28652026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.72ms)28662026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.81ms)28672026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (1.53ms)28682026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (960.82µs)28692026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000028702026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.59ms)28712026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.04ms)28722026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000028732026/10/01 09:39:14 OK 1_commit_pending_closure.sql (1.55ms)28742026/10/01 09:39:14 OK 2_object_stats_trigger.sql (599.95µs)28752026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes28762026/10/01 09:39:14 OK 1_commit_pending_closure.sql (1.78ms)28772026/10/01 09:39:14 OK 3_commit_push.sql (1.09ms)28782026/10/01 09:39:14 goose: up to current file version: 328792026/10/01 09:39:14 OK 2_object_stats_trigger.sql (841.42µs)28802026/10/01 09:39:14 OK 3_commit_push.sql (587.28µs)28812026/10/01 09:39:14 goose: up to current file version: 328822026/10/01 09:39:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures28832026/10/01 09:39:14 INFO Garbage collection started28842026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete28852026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes28862026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes28872026/10/01 09:39:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures28882026/10/01 09:39:14 INFO Garbage collection started28892026/10/01 09:39:14 INFO Aborted multipart uploads count=028902026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period28912026/10/01 09:39:14 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=185.794542ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28922026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete28932026/10/01 09:39:14 INFO Aborted multipart uploads count=028942026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period28952026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete28962026/10/01 09:39:14 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=028972026/10/01 09:39:14 INFO Vacuumed table table=pending_closures2898--- PASS: TestPush_CompleteCommitsEveryRoot (0.29s)28992026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29002026/10/01 09:39:14 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzA4ZWU0OTctNjU2My00ZTk4LWJiMjItMjAzNWU4MTA4YTgxLjAxMDk1MDBiLTZmNDAtNDE0Ny1hYTY1LTEzYmU4N2YxYjhhOXgxNzkwODQ3NTU0NDg3NTU0NjMz parts=1229012026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads29022026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29032026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29042026/10/01 09:39:14 INFO Vacuumed table table=closures29052026/10/01 09:39:14 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=02906--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.88s)29072026/10/01 09:39:14 INFO Vacuumed table table=objects29082026/10/01 09:39:14 INFO Vacuumed table table=pending_closures29092026/10/01 09:39:14 INFO Aborted multipart uploads count=029102026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29112026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads29122026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period29132026/10/01 09:39:14 INFO Vacuumed table table=closures29142026/10/01 09:39:14 INFO Vacuumed table table=objects29152026/10/01 09:39:14 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=029162026/10/01 09:39:14 INFO Vacuumed table table=pending_closures29172026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29182026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29192026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads29202026/10/01 09:39:14 INFO Vacuumed table table=closures29212026/10/01 09:39:14 INFO Vacuumed table table=objects29222026/10/01 09:39:14 INFO Aborted multipart uploads count=029232026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period29242026/10/01 09:39:14 INFO Aborted multipart uploads count=029252026/10/01 09:39: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=029262026/10/01 09:39:14 INFO Vacuumed table table=pending_closures29272026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period29282026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29292026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads29302026/10/01 09:39:14 INFO Vacuumed table table=closures29312026/10/01 09:39:14 INFO Vacuumed table table=objects29322026/10/01 09:39:14 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=029332026/10/01 09:39:14 INFO Vacuumed table table=pending_closures29342026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29352026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes29362026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads2937--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2938 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.31s)2939 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.29s)29402026/10/01 09:39:14 INFO Vacuumed table table=closures29412026/10/01 09:39:14 INFO Vacuumed table table=objects29422026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)29432026/10/01 09:39:14 INFO Uploading i2h0wyf51a34lc3k7xnc14z76qzm1l8c-ca-test (144B)29442026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/2/complete2945--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.36s)29462026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"29472026/10/01 09:39:14 WARN Failed to register uploaded object key=i2h0wyf51a34lc3k7xnc14z76qzm1l8c.ls error="server returned 404: 404 page not found\n"29482026/10/01 09:39:14 WARN Failed to register uploaded object key=log/n7rpjq51sjymh3kz4cji240wciz6mk9y-ca-test.drv error="server returned 404: 404 page not found\n"29492026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29502026/10/01 09:39:14 INFO Signed narinfos id=1 count=129512026/10/01 09:39:14 INFO Uploading 1 narinfos29522026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete29532026/10/01 09:39:14 WARN Failed to register uploaded object key=i2h0wyf51a34lc3k7xnc14z76qzm1l8c.narinfo error="server returned 404: 404 page not found\n"29542026/10/01 09:39:14 INFO Upload complete. (109ms)2955=== NAME TestClientCADerivations2956 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3859792391/001/store/i2h0wyf51a34lc3k7xnc14z76qzm1l8c-ca-test2957 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2958 Compression: zstd2959 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2960 NarSize: 1442961 References: 2962 Deriver: /build/TestClientCADerivations3859792391/001/store/n7rpjq51sjymh3kz4cji240wciz6mk9y-ca-test.drv2963 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2964 client_ca_test.go:185: Checking for realisation files in S3...2965 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2966 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache29672026/10/01 09:39:14 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2968=== NAME TestOrphanedObjectsGCStressTest2969 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2970 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion29712026/10/01 09:39:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29722026/10/01 09:39:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=398.902984ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2973=== NAME TestClientCADerivations2974 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2975 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2976 error: binary cache 's3://bucket68?endpoint=http://localhost:33889®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3859792391/001/store'2977 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12978--- PASS: TestClientCADerivations (0.91s)2979--- PASS: TestUploadHandlersRejectOversizedBody (0.19s)2980 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2981 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2982 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.63s)29832026/10/01 09:39:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete29842026/10/01 09:39:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzA4ZWU0OTctNjU2My00ZTk4LWJiMjItMjAzNWU4MTA4YTgxLjdiYjZlNDcwLWZkZjgtNDM1ZC05ODM4LWQxMzNkYWEwZTcyMXgxNzkwODQ3NTU0Nzg4ODc1MjMy parts=122985--- PASS: TestRedundantMultipartUpload (0.84s)2986=== NAME TestOrphanedObjectsGCStressTest2987 orphaned_objects_gc_test.go:509: Stress test completed successfully:2988 orphaned_objects_gc_test.go:510: - Active objects preserved: 202989 orphaned_objects_gc_test.go:511: - Objects deleted: 2102990 orphaned_objects_gc_test.go:512: - Total GC'd: 2102991--- PASS: TestOrphanedObjectsGCStressTest (2.96s)29922026/10/01 09:39:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=817.198865ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29932026/10/01 09:39:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.533495684s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29942026/10/01 09:39:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=029952026/10/01 09:39:16 INFO Received create pin request method=POST path=/api/pins/myapp29962026/10/01 09:39:16 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2028143616/001/store/wng89dz8cqg7cv899gvmvfk0k3wysrw2-pinned-file.txt narinfo_key=wng89dz8cqg7cv899gvmvfk0k3wysrw2.narinfo29972026/10/01 09:39:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures29982026/10/01 09:39:16 INFO Garbage collection started29992026/10/01 09:39:16 INFO Aborted multipart uploads count=030002026/10/01 09:39:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03001=== NAME TestClientIntegration3002 client_integration_test.go:323: Objects in database after GC:3003 client_integration_test.go:323: Successfully deleted all objects with GC --force30042026/10/01 09:39:16 WARN Force mode enabled - objects will be deleted immediately without grace period30052026/10/01 09:39: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=030062026/10/01 09:39:16 INFO Vacuumed table table=pending_closures30072026/10/01 09:39:16 INFO Vacuumed table table=pending_objects30082026/10/01 09:39:16 INFO Vacuumed table table=multipart_uploads3009--- PASS: TestClientIntegration (2.74s)30102026/10/01 09:39:16 INFO Vacuumed table table=closures30112026/10/01 09:39:16 INFO Vacuumed table table=objects30122026/10/01 09:39:17 WARN Rate limiter enabled after throttle name=s3-test rate=530132026/10/01 09:39:17 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3014=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3015 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103016 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003017--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.94s)30182026/10/01 09:39:17 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30192026/10/01 09:39:17 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.061145ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30202026/10/01 09:39:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=426.34827ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30212026/10/01 09:39:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=774.285413ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config3022=== NAME TestPinProtectsFromGC3023 client_integration_test.go:840: Pin successfully protected closure from garbage collection3024--- PASS: TestPinProtectsFromGC (4.88s)30252026/10/01 09:39:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.539028164s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30262026/10/01 09:39:20 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"30272026/10/01 09:39:20 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30282026/10/01 09:39:20 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.252455ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30292026/10/01 09:39:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=379.161237ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30302026/10/01 09:39:21 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=817.71936ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30312026/10/01 09:39:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.632132041s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30322026/10/01 09:39:24 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30332026/10/01 09:39:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=213.802108ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30342026/10/01 09:39:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=420.10491ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30352026/10/01 09:39:24 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=774.885277ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30362026/10/01 09:39:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.565899739s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3037--- PASS: TestClientErrorHandling (0.00s)3038 --- PASS: TestClientErrorHandling/InvalidStorePath (0.30s)3039 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.35s)3040 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.44s)3041PASS30422026-10-01 09:39:27.455 UTC [130] LOG: received smart shutdown request30432026-10-01 09:39:27.458 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 130442026-10-01 09:39:27.469 UTC [135] LOG: shutting down30452026-10-01 09:39:27.470 UTC [135] LOG: checkpoint starting: shutdown immediate30462026-10-01 09:39:29.224 UTC [135] LOG: checkpoint complete: wrote 10793 buffers (65.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.356 s, sync=1.360 s, total=1.755 s; sync files=27976, longest=0.015 s, average=0.001 s; distance=387440 kB, estimate=387440 kB; lsn=0/191C1CF0, redo lsn=0/191C1CF030472026-10-01 09:39:29.278 UTC [130] LOG: database system is shut down3048Running OIDC tests...3049=== RUN TestAudienceForIssuer3050=== PAUSE TestAudienceForIssuer3051=== RUN TestGlobMatch3052=== PAUSE TestGlobMatch3053=== RUN TestValidateToken_ValidToken3054=== PAUSE TestValidateToken_ValidToken3055=== RUN TestValidateToken_WrongAudience3056=== PAUSE TestValidateToken_WrongAudience3057=== RUN TestValidateToken_Expired3058=== PAUSE TestValidateToken_Expired3059=== RUN TestValidateToken_BoundClaimsMismatch3060=== PAUSE TestValidateToken_BoundClaimsMismatch3061=== RUN TestValidateToken_BoundSubjectMismatch3062=== PAUSE TestValidateToken_BoundSubjectMismatch3063=== RUN TestValidateToken_MultipleProviders3064=== PAUSE TestValidateToken_MultipleProviders3065=== RUN TestValidateToken_NoMatchingProvider3066=== PAUSE TestValidateToken_NoMatchingProvider3067=== RUN TestValidateToken_KubernetesServiceAccount3068=== PAUSE TestValidateToken_KubernetesServiceAccount3069=== RUN TestNewValidator_KubernetesRequiresCA3070=== PAUSE TestNewValidator_KubernetesRequiresCA3071=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3072=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3073=== RUN TestPins_ReservedForMatchingRule3074=== PAUSE TestPins_ReservedForMatchingRule3075=== RUN TestPins_TopLevelShorthand3076=== PAUSE TestPins_TopLevelShorthand3077=== RUN TestPins_ConfigValidation3078=== PAUSE TestPins_ConfigValidation3079=== RUN TestScopes_LegacyProviderDefaultsToWrite3080=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3081=== RUN TestScopes_Rules3082=== PAUSE TestScopes_Rules3083=== RUN TestScopes_ConfigValidation3084=== PAUSE TestScopes_ConfigValidation3085=== CONT TestAudienceForIssuer3086=== CONT TestValidateToken_BoundClaimsMismatch3087=== CONT TestPins_ConfigValidation3088=== CONT TestValidateToken_KubernetesServiceAccount3089--- PASS: TestAudienceForIssuer (0.00s)3090=== CONT TestPins_TopLevelShorthand3091=== CONT TestValidateToken_Expired3092=== CONT TestValidateToken_WrongAudience3093=== CONT TestPins_ReservedForMatchingRule3094=== CONT TestValidateToken_ValidToken3095=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3096=== CONT TestGlobMatch3097=== RUN TestGlobMatch/foo_foo3098=== CONT TestNewValidator_KubernetesRequiresCA3099=== CONT TestValidateToken_MultipleProviders3100=== CONT TestScopes_Rules3101=== CONT TestValidateToken_NoMatchingProvider3102=== CONT TestScopes_ConfigValidation3103=== CONT TestValidateToken_BoundSubjectMismatch3104=== CONT TestScopes_LegacyProviderDefaultsToWrite3105--- PASS: TestPins_ConfigValidation (0.00s)3106--- PASS: TestScopes_ConfigValidation (0.00s)3107=== PAUSE TestGlobMatch/foo_foo3108=== RUN TestGlobMatch/foo_bar3109=== PAUSE TestGlobMatch/foo_bar3110=== RUN TestGlobMatch/*_3111=== PAUSE TestGlobMatch/*_3112=== RUN TestGlobMatch/*_anything3113=== PAUSE TestGlobMatch/*_anything3114=== RUN TestGlobMatch/foo*_foo3115=== PAUSE TestGlobMatch/foo*_foo3116=== RUN TestGlobMatch/foo*_foobar3117=== PAUSE TestGlobMatch/foo*_foobar3118=== RUN TestGlobMatch/foo*_bar3119=== PAUSE TestGlobMatch/foo*_bar3120=== RUN TestGlobMatch/*bar_bar3121=== PAUSE TestGlobMatch/*bar_bar3122=== RUN TestGlobMatch/*bar_foobar3123=== PAUSE TestGlobMatch/*bar_foobar3124=== RUN TestGlobMatch/*bar_foo3125=== PAUSE TestGlobMatch/*bar_foo3126=== RUN TestGlobMatch/foo*bar_foobar3127=== PAUSE TestGlobMatch/foo*bar_foobar3128=== RUN TestGlobMatch/foo*bar_foo123bar3129=== PAUSE TestGlobMatch/foo*bar_foo123bar3130=== RUN TestGlobMatch/foo*bar_foobarbaz3131=== PAUSE TestGlobMatch/foo*bar_foobarbaz3132=== RUN TestGlobMatch/*/*_foo/bar3133=== PAUSE TestGlobMatch/*/*_foo/bar3134=== RUN TestGlobMatch/*/*_foo3135=== PAUSE TestGlobMatch/*/*_foo3136=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3137=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3138=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03139=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03140=== RUN TestGlobMatch/refs/*/main_refs/heads/main3141=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3142=== RUN TestGlobMatch/fo?_foo3143=== PAUSE TestGlobMatch/fo?_foo3144=== RUN TestGlobMatch/fo?_fo3145=== PAUSE TestGlobMatch/fo?_fo3146=== RUN TestGlobMatch/fo?_fooo3147=== PAUSE TestGlobMatch/fo?_fooo3148=== RUN TestGlobMatch/?oo_foo3149=== PAUSE TestGlobMatch/?oo_foo3150=== RUN TestGlobMatch/?oo_boo3151=== PAUSE TestGlobMatch/?oo_boo3152=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3153=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3154=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3155=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3156=== CONT TestGlobMatch/foo_foo3157=== CONT TestGlobMatch/foo*bar_foobarbaz3158=== CONT TestGlobMatch/foo*bar_foo123bar3159=== CONT TestGlobMatch/foo*bar_foobar3160=== CONT TestGlobMatch/*bar_foo3161=== CONT TestGlobMatch/*bar_foobar3162=== CONT TestGlobMatch/*bar_bar3163=== CONT TestGlobMatch/foo*_bar3164=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3165=== CONT TestGlobMatch/*/*_foo/bar3166=== CONT TestGlobMatch/foo*_foobar3167=== CONT TestGlobMatch/*_3168=== CONT TestGlobMatch/foo_bar3169=== CONT TestGlobMatch/fo?_foo3170=== CONT TestGlobMatch/fo?_fooo3171=== CONT TestGlobMatch/fo?_fo3172=== CONT TestGlobMatch/?oo_foo3173=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03174=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3175=== CONT TestGlobMatch/*/*_foo3176=== CONT TestGlobMatch/?oo_boo3177=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3178=== CONT TestGlobMatch/*_anything3179=== CONT TestGlobMatch/foo*_foo3180=== CONT TestGlobMatch/refs/*/main_refs/heads/main3181--- PASS: TestGlobMatch (0.01s)3182 --- PASS: TestGlobMatch/foo_foo (0.00s)3183 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3184 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3185 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3186 --- PASS: TestGlobMatch/*bar_foo (0.00s)3187 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3188 --- PASS: TestGlobMatch/*bar_bar (0.00s)3189 --- PASS: TestGlobMatch/foo*_bar (0.00s)3190 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3191 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3192 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3193 --- PASS: TestGlobMatch/*_ (0.00s)3194 --- PASS: TestGlobMatch/foo_bar (0.00s)3195 --- PASS: TestGlobMatch/fo?_foo (0.00s)3196 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3197 --- PASS: TestGlobMatch/fo?_fo (0.00s)3198 --- PASS: TestGlobMatch/?oo_foo (0.00s)3199 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3200 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3201 --- PASS: TestGlobMatch/*/*_foo (0.00s)3202 --- PASS: TestGlobMatch/?oo_boo (0.00s)3203 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3204 --- PASS: TestGlobMatch/*_anything (0.00s)3205 --- PASS: TestGlobMatch/foo*_foo (0.00s)3206 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)32072026/10/01 09:39:31 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:362433208--- PASS: TestValidateToken_KubernetesServiceAccount (0.03s)32092026/10/01 09:39:31 http: TLS handshake error from 127.0.0.1:58840: remote error: tls: bad certificate3210--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)32112026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40101/oidc3212--- PASS: TestValidateToken_BoundClaimsMismatch (0.04s)32132026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44741/oidc32142026/10/01 09:39:31 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233215--- PASS: TestPins_ReservedForMatchingRule (0.05s)32162026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46189/oidc3217--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)3218--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)32192026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33973/oidc3220--- PASS: TestValidateToken_WrongAudience (0.06s)32212026/10/01 09:39:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33697/oidc32222026/10/01 09:39:31 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:35405/oidc3223--- PASS: TestValidateToken_MultipleProviders (0.06s)32242026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46121/oidc32252026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35123/oidc3226--- PASS: TestPins_TopLevelShorthand (0.07s)3227--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)32282026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36985/oidc3229--- PASS: TestValidateToken_Expired (0.08s)32302026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35707/oidc3231--- PASS: TestValidateToken_ValidToken (0.08s)32322026/10/01 09:39:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:41641/oidc3233--- PASS: TestValidateToken_NoMatchingProvider (0.08s)32342026/10/01 09:39:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46411/oidc3235--- PASS: TestScopes_Rules (0.17s)3236PASS3237Running hook tests...3238=== RUN TestSendPathsEmpty3239=== PAUSE TestSendPathsEmpty3240=== RUN TestQueueEnqueueAndFetch3241=== PAUSE TestQueueEnqueueAndFetch3242=== RUN TestQueueDeduplication3243=== PAUSE TestQueueDeduplication3244=== RUN TestQueueRemove3245=== PAUSE TestQueueRemove3246=== RUN TestQueueFetchBatchLimit3247=== PAUSE TestQueueFetchBatchLimit3248=== RUN TestQueueRetryMovesToBack3249=== PAUSE TestQueueRetryMovesToBack3250=== RUN TestQueueFetchRemoveLifecycle3251=== PAUSE TestQueueFetchRemoveLifecycle3252=== RUN TestQueueConcurrentWriters3253=== PAUSE TestQueueConcurrentWriters3254=== RUN TestQueueRemoveLargeClosure3255=== PAUSE TestQueueRemoveLargeClosure3256=== RUN TestServerClientIntegration3257=== PAUSE TestServerClientIntegration3258=== RUN TestServerQueueError3259=== PAUSE TestServerQueueError3260=== RUN TestGetListenerSocketActivation3261 server_test.go:210: === RUN TestGetListenerSocketActivation3262 --- PASS: TestGetListenerSocketActivation (0.00s)3263 PASS3264 3265--- PASS: TestGetListenerSocketActivation (0.01s)3266=== RUN TestDrainIsolatesPoisonPath3267=== PAUSE TestDrainIsolatesPoisonPath3268=== RUN TestRunNotBlockedByPoisonHead3269=== PAUSE TestRunNotBlockedByPoisonHead3270=== RUN TestDrainGivesUpWhenServerDown3271=== PAUSE TestDrainGivesUpWhenServerDown3272=== RUN TestFailedPathPrunedByLaterClosure3273=== PAUSE TestFailedPathPrunedByLaterClosure3274=== RUN TestWorkerUploadsAndRemoves3275=== PAUSE TestWorkerUploadsAndRemoves3276=== RUN TestWorkerSkipsGCdPaths3277=== PAUSE TestWorkerSkipsGCdPaths3278=== RUN TestWorkerPrunesClosureDeps3279=== PAUSE TestWorkerPrunesClosureDeps3280=== RUN TestDrainTimeout3281=== PAUSE TestDrainTimeout3282=== CONT TestSendPathsEmpty3283=== CONT TestServerQueueError3284=== CONT TestRunNotBlockedByPoisonHead3285--- PASS: TestSendPathsEmpty (0.00s)3286=== CONT TestServerClientIntegration3287=== CONT TestQueueRemoveLargeClosure3288=== CONT TestQueueConcurrentWriters3289=== CONT TestQueueFetchRemoveLifecycle32902026/10/01 09:39:31 ERROR Failed to queue paths error="permission denied" count=13291=== CONT TestQueueRetryMovesToBack3292=== CONT TestQueueFetchBatchLimit3293=== CONT TestQueueRemove3294=== CONT TestQueueDeduplication3295=== CONT TestQueueEnqueueAndFetch3296=== CONT TestDrainGivesUpWhenServerDown3297=== CONT TestFailedPathPrunedByLaterClosure3298=== CONT TestWorkerPrunesClosureDeps3299=== CONT TestDrainTimeout3300=== CONT TestWorkerSkipsGCdPaths3301=== CONT TestDrainIsolatesPoisonPath3302=== CONT TestWorkerUploadsAndRemoves3303--- PASS: TestServerQueueError (0.00s)3304--- PASS: TestServerClientIntegration (0.00s)33052026/10/01 09:39:31 INFO Uploading batch count=133062026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=133072026/10/01 09:39:31 INFO Uploading batch count=233082026/10/01 09:39:31 INFO Uploading batch count=433092026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=433102026/10/01 09:39:31 INFO Uploading batch count=233112026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=233122026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4240176181/002/a33132026/10/01 09:39:31 INFO Uploading batch count=133142026/10/01 09:39:31 INFO Upload queue status pending=233152026/10/01 09:39:31 INFO Upload queue status pending=23316--- PASS: TestQueueFetchBatchLimit (0.02s)33172026/10/01 09:39:31 INFO Uploading batch count=23318--- PASS: TestQueueEnqueueAndFetch (0.02s)33192026/10/01 09:39:31 INFO Upload queue status pending=23320--- PASS: TestQueueRemove (0.02s)33212026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2370641205/002/bbb33222026/10/01 09:39:31 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths136854985/002/nonexistent3323--- PASS: TestQueueFetchRemoveLifecycle (0.02s)33242026/10/01 09:39:31 INFO Upload queue status pending=333252026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4240176181/002/b33262026/10/01 09:39:31 INFO Uploading batch count=133272026/10/01 09:39:31 INFO Uploading batch count=133282026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=13329--- PASS: TestQueueRetryMovesToBack (0.02s)33302026/10/01 09:39:31 INFO Uploading batch count=133312026/10/01 09:39:31 INFO Uploading batch count=133322026/10/01 09:39:31 INFO Uploading batch count=233332026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=233342026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4240176181/002/c3335--- PASS: TestQueueDeduplication (0.02s)33362026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4240176181/002/d33372026/10/01 09:39:31 INFO Uploading batch count=133382026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=133392026/10/01 09:39:31 INFO Uploading batch count=233402026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=233412026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4240176181/002/e33422026/10/01 09:39:31 INFO Uploading batch count=133432026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=13344--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)33452026/10/01 09:39:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4240176181/002/f33462026/10/01 09:39:31 INFO Uploading batch count=133472026/10/01 09:39:31 ERROR Upload failed error="upload failed" count=133482026/10/01 09:39:31 ERROR Drain finished with paths left in queue remaining=1033492026/10/01 09:39:31 ERROR Drain finished with paths left in queue remaining=13350--- PASS: TestDrainIsolatesPoisonPath (0.02s)3351--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3352--- PASS: TestWorkerUploadsAndRemoves (0.03s)3353--- PASS: TestWorkerSkipsGCdPaths (0.03s)3354--- PASS: TestWorkerPrunesClosureDeps (0.04s)3355--- PASS: TestQueueRemoveLargeClosure (0.09s)33562026/10/01 09:39:31 ERROR Upload failed error="context deadline exceeded" count=233572026/10/01 09:39:31 ERROR Drain finished with paths left in queue remaining=43358--- PASS: TestDrainTimeout (0.22s)3359--- PASS: TestQueueConcurrentWriters (0.48s)33602026/10/01 09:39:32 INFO Uploading batch count=133612026/10/01 09:39:32 INFO Uploading batch count=133622026/10/01 09:39:32 INFO Uploading batch count=133632026/10/01 09:39:32 ERROR Upload failed error="upload failed" count=133642026/10/01 09:39:32 INFO Uploading batch count=133652026/10/01 09:39:32 ERROR Upload failed error="upload failed" count=133662026/10/01 09:39:32 INFO Uploading batch count=133672026/10/01 09:39:32 ERROR Upload failed error="upload failed" count=133682026/10/01 09:39:32 INFO Uploading batch count=133692026/10/01 09:39:32 ERROR Upload failed error="upload failed" count=133702026/10/01 09:39:32 ERROR Drain finished with paths left in queue remaining=13371--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3372PASS