niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #317
· raw
1tribuchet: building on eliza2Running 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.03s)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 TestPathInfoCACompatibility97=== RUN TestPathInfoCACompatibility/null_ca_field98=== PAUSE TestPathInfoCACompatibility/null_ca_field99=== RUN TestPathInfoCACompatibility/old_string_format_-_text100=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text101=== CONT TestScriptTokenEmptyCommand102--- PASS: TestScriptTokenEmptyCommand (0.00s)103=== CONT TestShellSplit104=== CONT TestEncodeNixBase32WithRealHash105--- PASS: TestShellSplit (0.00s)106=== CONT TestStreamPushBatchesUnderLoad107--- PASS: TestEncodeNixBase32WithRealHash (0.00s)108=== CONT TestDoWithRetry_BodyReplayedViaGetBody109=== CONT TestResolveStorePath110=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess111=== CONT TestRateLimiterFeedback112=== RUN TestRateLimiterFeedback/429_enables_limiter113=== PAUSE TestRateLimiterFeedback/429_enables_limiter114=== CONT TestScriptTokenScriptFails115=== CONT TestScriptTokenBadJSON116=== CONT TestScriptTokenEmptyToken117=== CONT TestScriptTokenCachesUntilRefresh118=== CONT TestScriptTokenNoExpiryRerunsEveryCall1192026/10/01 09:46:17 WARN Rate limiter enabled after throttle name=server-test rate=5120=== CONT TestUploadMultipart_SupersededByPeer121=== RUN TestUploadMultipart_SupersededByPeer/exists122=== CONT TestFileTokenEmpty123=== CONT TestFileTokenMissing124=== CONT TestDumpPathSingleFile125=== CONT TestFileTokenReadsAndCaches126=== CONT TestDumpPathMatchesNix127=== CONT TestStaticToken128=== CONT TestStreamPushRequestLine129=== CONT TestStreamPushGivesUpOnDeadServer130=== CONT TestSetClientTLSErrors131=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive132=== CONT TestStreamPushIsolatesFailures1332026/10/01 09:46:17 ERROR Upload failed error="connection refused" count=201342026/10/01 09:46:17 WARN Rate limiter enabled after throttle name=server-test rate=5135=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1362026/10/01 09:46:17 ERROR Server seems unavailable, giving up on batch untried=17137=== RUN TestRateLimiterFeedback/503_enables_limiter138=== CONT TestStreamPushReportsSignatures139--- PASS: TestResolveStorePath (0.00s)1402026/10/01 09:46:17 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:38501141=== CONT TestStreamPushReportsEveryPath142=== PAUSE TestUploadMultipart_SupersededByPeer/exists143=== CONT TestSetClientTLS1442026/10/01 09:46:17 ERROR Upload failed error="bad path" count=3145=== CONT TestShellSplitErrors146=== CONT TestClientSignaturesByStorePath147=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive148=== RUN TestUploadMultipart_SupersededByPeer/missing149=== CONT TestFilterOversizedClosures150=== RUN TestFilterOversizedClosures/no_limit_keeps_everything151=== CONT TestEncodeNixBase32152=== RUN TestEncodeNixBase32/test_string_hash153=== PAUSE TestRateLimiterFeedback/503_enables_limiter154=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter155--- PASS: TestScriptTokenScriptFails (0.00s)156--- PASS: TestFileTokenMissing (0.00s)157--- PASS: TestStaticToken (0.00s)158--- PASS: TestDoServerRequestAttachesToken (0.01s)159=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter160--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)1612026/10/01 09:46:17 ERROR Upload failed error=boom count=1162=== CONT TestPathInfoHashCompatibility1632026/10/01 09:46:17 WARN Rate limiter backed off name=server-test rate=51642026/10/01 09:46:17 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:38501165--- PASS: TestScriptTokenBadJSON (0.00s)166=== CONT TestCaseHackSuffix167=== CONT TestParsePathInfoJSONMultiplePaths168=== CONT TestUploadMultipart_PartsInParallel169=== RUN TestSetClientTLSErrors/missing_cert_file170=== CONT TestPartSizeForNAR171=== CONT TestRegisterUploadedObjectReusesConnections172=== PAUSE TestEncodeNixBase32/test_string_hash173=== RUN TestPathInfoCACompatibility/new_structured_format_-_text174--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)175=== CONT TestGetStorePathHash176=== CONT TestParsePathInfoJSON177=== PAUSE TestUploadMultipart_SupersededByPeer/missing178=== RUN TestEncodeNixBase32/empty_input179=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything180=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths181=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter182--- PASS: TestClientSignaturesByStorePath (0.00s)183=== RUN TestPartSizeForNAR/zero_stays_at_minimum184=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)185=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text186=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method187=== PAUSE TestSetClientTLSErrors/missing_cert_file188=== CONT TestConvertHashToNix32189=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum190=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)191=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter192--- PASS: TestFileTokenReadsAndCaches (0.00s)193--- PASS: TestShellSplitErrors (0.00s)194--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)195--- PASS: TestScriptTokenEmptyToken (0.01s)196--- PASS: TestFileTokenEmpty (0.00s)197=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method198=== CONT TestDumpPathWriterError1992026/10/01 09:46:17 ERROR Upload failed error=boom count=1200--- PASS: TestStreamPushIsolatesFailures (0.00s)201=== PAUSE TestEncodeNixBase32/empty_input202=== RUN TestGetStorePathHash/valid_store_path203=== RUN TestParsePathInfoJSON/Nix_format204=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped205=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped206=== RUN TestSetClientTLSErrors/missing_key_file207=== RUN TestConvertHashToNix32/SRI_format_to_Nix32208=== RUN TestPartSizeForNAR/small_stays_at_minimum209=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon210=== RUN TestSetClientTLS/rejects_connection_without_client_cert211=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths212=== CONT TestUploadMultipart_SupersededByPeer/exists213=== CONT TestRateLimiterFeedback/429_enables_limiter214=== CONT TestUploadMultipart_SupersededByPeer/missing215--- PASS: TestStreamPushReportsEveryPath (0.01s)216--- PASS: TestStreamPushReportsSignatures (0.03s)217=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter218=== PAUSE TestGetStorePathHash/valid_store_path219=== RUN TestGetStorePathHash/basename_without_hyphen_should_error220=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error221=== PAUSE TestParsePathInfoJSON/Nix_format222=== PAUSE TestSetClientTLSErrors/missing_key_file223=== RUN TestSetClientTLSErrors/missing_ca_file224=== RUN TestFilterOversizedClosures/all_closures_skipped2252026/10/01 09:46:17 WARN Rate limiter enabled after throttle name=server-test rate=5226=== PAUSE TestFilterOversizedClosures/all_closures_skipped2272026/10/01 09:46:17 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:42565228=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32229=== RUN TestConvertHashToNix32/already_Nix32_format230=== PAUSE TestConvertHashToNix32/already_Nix32_format231=== RUN TestConvertHashToNix32/invalid_format232=== PAUSE TestConvertHashToNix32/invalid_format233=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2342026/10/01 09:46:17 WARN Rate limiter backed off name=server-test rate=5235=== CONT TestRateLimiterFeedback/503_enables_limiter236=== CONT TestPathInfoCACompatibility/null_ca_field237=== PAUSE TestPartSizeForNAR/small_stays_at_minimum238=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert2392026/10/01 09:46:17 WARN Rate limiter enabled after throttle name=server-test rate=5240=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2412026/10/01 09:46:17 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:36445242=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths243=== CONT TestEncodeNixBase32/empty_input244=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error245=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error246=== RUN TestParsePathInfoJSON/Lix_format2472026/10/01 09:46:17 WARN Rate limiter backed off name=server-test rate=5248=== PAUSE TestSetClientTLSErrors/missing_ca_file249=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon250=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method251=== CONT TestFilterOversizedClosures/all_closures_skipped2522026/10/01 09:46:17 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=50253=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped254=== CONT TestConvertHashToNix32/SRI_format_to_Nix322552026/10/01 09:46:17 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=2000256=== CONT TestConvertHashToNix32/invalid_format257=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths258=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths259=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive260=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum261=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum262=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts263=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts264=== RUN TestPartSizeForNAR/1_TiB265=== CONT TestPathInfoCACompatibility/old_string_format_-_text266--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)267 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)268 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)269--- PASS: TestRateLimiterFeedback (0.01s)270 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)271 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)272 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)273 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)274=== CONT TestPathInfoCACompatibility/new_structured_format_-_text275--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)276=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA277=== CONT TestEncodeNixBase32/test_string_hash278=== CONT TestFilterOversizedClosures/no_limit_keeps_everything279=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error280=== PAUSE TestParsePathInfoJSON/Lix_format281=== RUN TestSetClientTLSErrors/invalid_ca_file282=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI283=== CONT TestConvertHashToNix32/already_Nix32_format284=== PAUSE TestPartSizeForNAR/1_TiB285--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)286 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)287 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)288=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA289=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error290=== PAUSE TestSetClientTLSErrors/invalid_ca_file291=== CONT TestSetClientTLSErrors/missing_cert_file292=== CONT TestSetClientTLSErrors/missing_key_file293=== CONT TestSetClientTLSErrors/invalid_ca_file294=== RUN TestParsePathInfoJSON/empty_input295=== RUN TestPartSizeForNAR/5_TiB_S3_max_object296--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)297=== RUN TestSetClientTLS/preserves_debug_logging_transport298=== PAUSE TestSetClientTLS/preserves_debug_logging_transport299=== CONT TestGetStorePathHash/valid_store_path300=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error301=== CONT TestGetStorePathHash/basename_without_hyphen_should_error302=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error303=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI304=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512305=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512306=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)307=== CONT TestSetClientTLSErrors/missing_ca_file308=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI309=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon310=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object311=== RUN TestPartSizeForNAR/capped_at_5_GiB312=== PAUSE TestPartSizeForNAR/capped_at_5_GiB313=== CONT TestPartSizeForNAR/zero_stays_at_minimum314=== CONT TestPartSizeForNAR/1_TiB315=== PAUSE TestParsePathInfoJSON/empty_input316=== CONT TestPartSizeForNAR/5_TiB_S3_max_object317=== RUN TestParsePathInfoJSON/whitespace_only318=== PAUSE TestParsePathInfoJSON/whitespace_only319=== CONT TestSetClientTLS/preserves_debug_logging_transport320=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA321=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512322=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts323=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum324=== CONT TestPartSizeForNAR/small_stays_at_minimum325=== CONT TestPartSizeForNAR/capped_at_5_GiB326--- PASS: TestPathInfoCACompatibility (0.01s)327 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)329 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)331 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)332=== CONT TestSetClientTLS/rejects_connection_without_client_cert333=== RUN TestParsePathInfoJSON/invalid_JSON334--- PASS: TestDumpPathSingleFile (0.03s)335--- PASS: TestPathInfoHashCompatibility (0.03s)336 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)337 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)338 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)339 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)340--- PASS: TestPartSizeForNAR (0.03s)341 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)342 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)343 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)344 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)345 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)346 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)347 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)348--- PASS: TestFilterOversizedClosures (0.03s)349 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)350 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)351 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)352--- PASS: TestGetStorePathHash (0.03s)353 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)354 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)355 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)356 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)357--- PASS: TestSetClientTLSErrors (0.03s)358 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)359 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)360 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)361 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)362--- PASS: TestEncodeNixBase32 (0.03s)363 --- PASS: TestEncodeNixBase32/empty_input (0.00s)364 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)365--- PASS: TestConvertHashToNix32 (0.03s)366 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)367 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)368 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)369=== PAUSE TestParsePathInfoJSON/invalid_JSON370=== CONT TestParsePathInfoJSON/Nix_format371=== CONT TestParsePathInfoJSON/empty_input372=== CONT TestParsePathInfoJSON/whitespace_only373=== CONT TestParsePathInfoJSON/invalid_JSON374=== CONT TestParsePathInfoJSON/Lix_format375--- PASS: TestParsePathInfoJSON (0.04s)376 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)377 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)378 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)379 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)380 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)3812026/10/01 09:46:17 http: TLS handshake error from 127.0.0.1:42876: remote error: tls: bad certificate382--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)383--- PASS: TestSetClientTLS (0.03s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)385 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestCaseHackSuffix (0.06s)388--- PASS: TestStreamPushRequestLine (0.06s)389--- PASS: TestDumpPathWriterError (0.07s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestDumpPathMatchesNix (0.11s)392--- PASS: TestUploadMultipart_PartsInParallel (0.65s)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/postgres2748403821/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/postgres2748403821/data -l logfile start422423/build/postgres2748403821:5432 - no response4242026-10-01 09:46:19.151 UTC [130] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:46:19.152 UTC [130] LOG: listening on Unix socket "/build/postgres2748403821/.s.PGSQL.5432"4262026-10-01 09:46:19.157 UTC [137] LOG: database system was shut down at 2026-10-01 09:46:18 UTC4272026-10-01 09:46:19.160 UTC [130] LOG: database system is ready to accept connections428/build/postgres2748403821:5432 - accepting connections429{"timestamp":"2026-10-01T09:46:19.354683317Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0fd6e70f-0567-410f-bb0f-3f0bdca9807f","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(206)"}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:46:19.537 UTC [374] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:46:19.537 UTC [374] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:46:19 OK 20241026095416_initial_model.sql (10.41ms)4762026/10/01 09:46:19 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)4772026/10/01 09:46:19 OK 20251218171726_add_pins.sql (3.02ms)4782026/10/01 09:46:19 OK 20260628120000_add_object_size_and_stats.sql (2.96ms)4792026/10/01 09:46:19 OK 20260905000000_add_claims.sql (3.16ms)4802026/10/01 09:46:19 OK 20260920000000_drop_claims.sql (2.52ms)4812026/10/01 09:46:19 OK 20260923120000_add_pushes.sql (1.92ms)4822026/10/01 09:46:19 goose: successfully migrated database to version: 202609231200004832026/10/01 09:46:19 OK 1_commit_pending_closure.sql (1.88ms)4842026/10/01 09:46:19 OK 2_object_stats_trigger.sql (950.27µs)4852026/10/01 09:46:19 OK 3_commit_push.sql (1.32ms)4862026/10/01 09:46:19 goose: up to current file version: 34872026/10/01 09:46:19 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:46:20 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:46:20 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:46:20 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.95s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:46:20.473 UTC [385] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:46:20.473 UTC [385] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:46:20 OK 20241026095416_initial_model.sql (9.09ms)4982026/10/01 09:46:20 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)4992026/10/01 09:46:20 OK 20251218171726_add_pins.sql (3.42ms)5002026/10/01 09:46:20 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)5012026/10/01 09:46:20 OK 20260905000000_add_claims.sql (3.49ms)5022026/10/01 09:46:20 OK 20260920000000_drop_claims.sql (2.58ms)5032026/10/01 09:46:20 OK 20260923120000_add_pushes.sql (1.85ms)5042026/10/01 09:46:20 goose: successfully migrated database to version: 202609231200005052026/10/01 09:46:20 OK 1_commit_pending_closure.sql (1.92ms)5062026/10/01 09:46:20 OK 2_object_stats_trigger.sql (1.47ms)5072026/10/01 09:46:20 OK 3_commit_push.sql (976.11µs)5082026/10/01 09:46:20 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.52s)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 TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 09:46:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 09:46:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"669--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)670=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== RUN TestProxyWriteTimeout673=== PAUSE TestProxyWriteTimeout674=== RUN TestIsValidUploadKey675=== PAUSE TestIsValidUploadKey676=== RUN TestUploadHandlersRejectInvalidKeys677=== PAUSE TestUploadHandlersRejectInvalidKeys678=== RUN TestUploadHandlersRejectOversizedBody679=== PAUSE TestUploadHandlersRejectOversizedBody680=== RUN TestService_cleanupPendingClosuresHandler681=== PAUSE TestService_cleanupPendingClosuresHandler682=== RUN TestService_createPendingClosureHandler683=== PAUSE TestService_createPendingClosureHandler684=== RUN TestService_verifyS3Integrity685=== PAUSE TestService_verifyS3Integrity686=== RUN TestCompleteMultipartUnregistered687=== PAUSE TestCompleteMultipartUnregistered688=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT689=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT690=== CONT TestSkippedUploadsHandler691=== CONT TestService_AuthMiddleware692=== CONT TestParseSize693--- PASS: TestParseSize (0.00s)694=== CONT TestPush_OverlappingRootsStoreOneRowPerKey695=== CONT TestService_cleanupPendingClosuresHandler6962026/10/01 09:46:21 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000697=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT698=== CONT TestCompleteMultipartUnregistered699=== CONT TestService_Rustfstest700=== CONT TestService_verifyS3Integrity701=== CONT TestPresignedUploadRegisteredBeforeCommit702=== CONT TestService_createPendingClosureHandler703=== CONT TestCompletedNarNotReofferedAcrossClosures704=== CONT TestIsValidUploadKey705=== RUN TestIsValidUploadKey/narinfo706=== CONT TestCompleteMultipartUpload_ErrorButObjectExists707=== CONT TestUploadHandlersRejectOversizedBody708=== CONT TestRedundantMultipartUpload709=== CONT TestUploadHandlersRejectInvalidKeys710=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info711=== CONT TestPush_SignsNarinfosOfItsPendingObjects712=== CONT TestPush_RejectsBadRequests713=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle714=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit715=== CONT TestGCTaskStore_GetEmpty716=== CONT TestGCTaskStore_ConflictDifferentParams717=== CONT TestPush_CompleteCommitsEveryRoot718=== CONT TestGCTaskStore_DeduplicateSameParams719=== PAUSE TestIsValidUploadKey/narinfo720--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)721--- PASS: TestGCTaskStore_GetEmpty (0.00s)722=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info723--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)724=== CONT TestReadRedirectUsesPublicS3URL725=== CONT TestGCEndsOnShutdown726=== CONT TestGCTaskStore_StartNew727--- PASS: TestGCTaskStore_StartNew (0.00s)728=== CONT TestReadProxyRangeRequest729=== RUN TestIsValidUploadKey/nar_zst730=== PAUSE TestIsValidUploadKey/nar_zst731=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal732=== RUN TestIsValidUploadKey/nar_xz733=== PAUSE TestIsValidUploadKey/nar_xz734=== RUN TestIsValidUploadKey/nar_plain735=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal736=== PAUSE TestIsValidUploadKey/nar_plain737=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key738=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key739=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key740=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key741=== RUN TestIsValidUploadKey/listing742=== PAUSE TestIsValidUploadKey/listing743=== CONT TestCommitRacingPendingCleanupKeepsObjects744=== RUN TestIsValidUploadKey/build_log745--- PASS: TestSkippedUploadsHandler (0.01s)746=== CONT TestReadRedirectKeepsNarinfoProxied747=== PAUSE TestIsValidUploadKey/build_log748=== RUN TestIsValidUploadKey/build_log_home-manager_file749=== PAUSE TestIsValidUploadKey/build_log_home-manager_file750=== RUN TestIsValidUploadKey/build_log_plus_in_name751=== PAUSE TestIsValidUploadKey/build_log_plus_in_name752=== RUN TestIsValidUploadKey/build_log_question_mark753=== PAUSE TestIsValidUploadKey/build_log_question_mark754=== RUN TestIsValidUploadKey/build_log_equals755=== PAUSE TestIsValidUploadKey/build_log_equals756=== RUN TestIsValidUploadKey/realisation757=== PAUSE TestIsValidUploadKey/realisation758=== RUN TestIsValidUploadKey/realisation_plus_in_output759=== PAUSE TestIsValidUploadKey/realisation_plus_in_output760=== RUN TestIsValidUploadKey/nix-cache-info761=== PAUSE TestIsValidUploadKey/nix-cache-info762=== RUN TestIsValidUploadKey/index.html763=== PAUSE TestIsValidUploadKey/index.html764=== RUN TestIsValidUploadKey/narinfo_key,_nar_type765=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type766=== RUN TestIsValidUploadKey/nar_key,_narinfo_type767=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type768=== RUN TestIsValidUploadKey/listing_key,_narinfo_type769=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type770=== RUN TestIsValidUploadKey/traversal771=== PAUSE TestIsValidUploadKey/traversal772=== RUN TestIsValidUploadKey/traversal_nar773=== PAUSE TestIsValidUploadKey/traversal_nar774=== RUN TestIsValidUploadKey/absolute775=== PAUSE TestIsValidUploadKey/absolute776=== RUN TestIsValidUploadKey/empty_key777=== PAUSE TestIsValidUploadKey/empty_key778=== RUN TestIsValidUploadKey/unknown_type779=== PAUSE TestIsValidUploadKey/unknown_type780=== CONT TestPushWaitsForSweepHoldingRow7812026-10-01 09:46:21.273 UTC [450] ERROR: relation "goose_db_version" does not exist at character 367822026-10-01 09:46:21.273 UTC [450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7832026-10-01 09:46:21.273 UTC [449] ERROR: relation "goose_db_version" does not exist at character 367842026-10-01 09:46:21.273 UTC [449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC785=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure786=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure787=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart788=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart789=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts790=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts791=== CONT TestReadRedirectNar7922026-10-01 09:46:21.326 UTC [454] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 09:46:21.326 UTC [454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026-10-01 09:46:21.336 UTC [455] ERROR: relation "goose_db_version" does not exist at character 367952026-10-01 09:46:21.336 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/10/01 09:46:21 OK 20241026095416_initial_model.sql (38.59ms)7972026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (4.41ms)7982026-10-01 09:46:21.352 UTC [456] ERROR: relation "goose_db_version" does not exist at character 367992026-10-01 09:46:21.352 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8002026-10-01 09:46:21.355 UTC [457] ERROR: relation "goose_db_version" does not exist at character 368012026-10-01 09:46:21.355 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8022026/10/01 09:46:21 OK 20241026095416_initial_model.sql (64.88ms)8032026-10-01 09:46:21.360 UTC [458] ERROR: relation "goose_db_version" does not exist at character 368042026-10-01 09:46:21.360 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8052026-10-01 09:46:21.364 UTC [459] ERROR: relation "goose_db_version" does not exist at character 368062026-10-01 09:46:21.364 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8072026/10/01 09:46:21 OK 20251218171726_add_pins.sql (20.84ms)8082026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (14.62ms)8092026-10-01 09:46:21.378 UTC [460] ERROR: relation "goose_db_version" does not exist at character 368102026-10-01 09:46:21.378 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8112026/10/01 09:46:21 OK 20251218171726_add_pins.sql (10.86ms)8122026/10/01 09:46:21 OK 20241026095416_initial_model.sql (32.09ms)8132026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (14.53ms)8142026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (3.99ms)8152026/10/01 09:46:21 OK 20241026095416_initial_model.sql (55.56ms)8162026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (51.25ms)8172026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (15.21ms)8182026/10/01 09:46:21 OK 20251218171726_add_pins.sql (60.6ms)8192026/10/01 09:46:21 OK 20241026095416_initial_model.sql (84.84ms)8202026/10/01 09:46:21 OK 20260905000000_add_claims.sql (81.04ms)8212026/10/01 09:46:21 OK 20260905000000_add_claims.sql (34.58ms)8222026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (7.65ms)8232026/10/01 09:46:21 OK 20241026095416_initial_model.sql (81.68ms)8242026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (7.29ms)8252026/10/01 09:46:21 OK 20251218171726_add_pins.sql (29.35ms)8262026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (5.73ms)8272026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (7.65ms)8282026/10/01 09:46:21 OK 20241026095416_initial_model.sql (104.75ms)8292026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (15.03ms)8302026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200008312026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (42.92ms)8322026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (17.28ms)8332026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200008342026/10/01 09:46:21 OK 20251218171726_add_pins.sql (24.2ms)8352026/10/01 09:46:21 OK 20241026095416_initial_model.sql (117.84ms)8362026-10-01 09:46:21.494 UTC [461] ERROR: relation "goose_db_version" does not exist at character 368372026-10-01 09:46:21.494 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8382026-10-01 09:46:21.502 UTC [462] ERROR: relation "goose_db_version" does not exist at character 368392026-10-01 09:46:21.502 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8402026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (20.73ms)8412026/10/01 09:46:21 OK 20260905000000_add_claims.sql (21.03ms)8422026/10/01 09:46:21 OK 1_commit_pending_closure.sql (20.99ms)8432026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (37.72ms)8442026/10/01 09:46:21 OK 1_commit_pending_closure.sql (21.09ms)8452026/10/01 09:46:21 OK 20251218171726_add_pins.sql (37.47ms)8462026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (19.67ms)8472026/10/01 09:46:21 OK 2_object_stats_trigger.sql (5.22ms)8482026/10/01 09:46:21 OK 2_object_stats_trigger.sql (6.65ms)8492026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (26.4ms)8502026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (8.01ms)8512026/10/01 09:46:21 OK 20251218171726_add_pins.sql (8.07ms)8522026/10/01 09:46:21 OK 3_commit_push.sql (3.03ms)8532026/10/01 09:46:21 goose: up to current file version: 38542026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (8.97ms)8552026/10/01 09:46:21 OK 20241026095416_initial_model.sql (73.32ms)8562026/10/01 09:46:21 OK 3_commit_push.sql (3.3ms)8572026/10/01 09:46:21 goose: up to current file version: 38582026-10-01 09:46:21.523 UTC [463] ERROR: relation "goose_db_version" does not exist at character 368592026-10-01 09:46:21.523 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8602026/10/01 09:46:21 OK 20260905000000_add_claims.sql (11.54ms)8612026/10/01 09:46:21 OK 20251218171726_add_pins.sql (15.48ms)8622026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.92ms)8632026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200008642026-10-01 09:46:21.525 UTC [464] ERROR: relation "goose_db_version" does not exist at character 368652026-10-01 09:46:21.525 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8662026/10/01 09:46:21 OK 20260905000000_add_claims.sql (7.38ms)8672026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (9.14ms)8682026/10/01 09:46:21 OK 20260905000000_add_claims.sql (8.38ms)8692026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (5.95ms)8702026-10-01 09:46:21.531 UTC [465] ERROR: relation "goose_db_version" does not exist at character 368712026-10-01 09:46:21.531 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8722026-10-01 09:46:21.533 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368732026-10-01 09:46:21.533 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8742026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (8.56ms)8752026/10/01 09:46:21 OK 1_commit_pending_closure.sql (8.51ms)8762026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.11ms)8772026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200008782026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (11.35ms)8792026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (8ms)8802026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (5.19ms)8812026-10-01 09:46:21.535 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368822026-10-01 09:46:21.535 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8832026-10-01 09:46:21.536 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368842026-10-01 09:46:21.536 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8852026-10-01 09:46:21.536 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368862026-10-01 09:46:21.536 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8872026/10/01 09:46:21 OK 2_object_stats_trigger.sql (5.7ms)8882026/10/01 09:46:21 OK 20260905000000_add_claims.sql (9.58ms)8892026/10/01 09:46:21 OK 1_commit_pending_closure.sql (5.09ms)8902026/10/01 09:46:21 OK 20241026095416_initial_model.sql (18.8ms)8912026-10-01 09:46:21.539 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368922026-10-01 09:46:21.539 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8932026/10/01 09:46:21 OK 20260905000000_add_claims.sql (7.45ms)8942026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (6.01ms)8952026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200008962026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (7.62ms)8972026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200008982026/10/01 09:46:21 OK 20251218171726_add_pins.sql (7.88ms)8992026/10/01 09:46:21 OK 3_commit_push.sql (3.22ms)9002026/10/01 09:46:21 goose: up to current file version: 39012026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.47ms)9022026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (4.05ms)9032026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (4.77ms)9042026-10-01 09:46:21.544 UTC [472] ERROR: relation "goose_db_version" does not exist at character 369052026-10-01 09:46:21.544 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9062026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (3.65ms)9072026-10-01 09:46:21.545 UTC [471] ERROR: relation "goose_db_version" does not exist at character 369082026-10-01 09:46:21.545 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9092026-10-01 09:46:21.545 UTC [474] ERROR: relation "goose_db_version" does not exist at character 369102026-10-01 09:46:21.545 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9112026-10-01 09:46:21.545 UTC [473] ERROR: relation "goose_db_version" does not exist at character 369122026-10-01 09:46:21.545 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9132026/10/01 09:46:21 OK 1_commit_pending_closure.sql (4.43ms)9142026/10/01 09:46:21 OK 20241026095416_initial_model.sql (15.53ms)9152026-10-01 09:46:21.546 UTC [475] ERROR: relation "goose_db_version" does not exist at character 369162026-10-01 09:46:21.546 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9172026/10/01 09:46:21 OK 3_commit_push.sql (4.53ms)9182026/10/01 09:46:21 goose: up to current file version: 39192026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.49ms)9202026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (6.19ms)9212026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200009222026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (5.94ms)9232026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200009242026/10/01 09:46:21 OK 20241026095416_initial_model.sql (17.88ms)9252026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)9262026/10/01 09:46:21 OK 1_commit_pending_closure.sql (11.52ms)9272026/10/01 09:46:21 OK 3_commit_push.sql (4.92ms)9282026/10/01 09:46:21 goose: up to current file version: 39292026/10/01 09:46:21 OK 1_commit_pending_closure.sql (5.44ms)9302026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.24ms)9312026/10/01 09:46:21 OK 20251218171726_add_pins.sql (13.02ms)9322026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (5.34ms)9332026/10/01 09:46:21 OK 2_object_stats_trigger.sql (2.51ms)9342026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (15.95ms)9352026/10/01 09:46:21 OK 2_object_stats_trigger.sql (5.92ms)9362026/10/01 09:46:21 OK 20241026095416_initial_model.sql (24.96ms)9372026/10/01 09:46:21 OK 2_object_stats_trigger.sql (4.27ms)9382026/10/01 09:46:21 OK 20251218171726_add_pins.sql (7.65ms)9392026/10/01 09:46:21 INFO Received cleanup request method=DELETE path=/api/pending_closures9402026/10/01 09:46:21 OK 3_commit_push.sql (3.12ms)9412026/10/01 09:46:21 goose: up to current file version: 39422026/10/01 09:46:21 OK 3_commit_push.sql (2.15ms)9432026/10/01 09:46:21 goose: up to current file version: 39442026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (3.3ms)9452026/10/01 09:46:21 INFO Aborted multipart uploads count=0 kept=09462026/10/01 09:46:21 OK 20241026095416_initial_model.sql (21.15ms)9472026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (7.78ms)9482026/10/01 09:46:21 OK 3_commit_push.sql (6.53ms)9492026/10/01 09:46:21 goose: up to current file version: 39502026/10/01 09:46:21 INFO Received uploads request method=POST path=/api/pending_closures9512026/10/01 09:46:21 OK 20260905000000_add_claims.sql (9.15ms)9522026/10/01 09:46:21 OK 20241026095416_initial_model.sql (25.16ms)9532026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (10.18ms)9542026/10/01 09:46:21 OK 20251218171726_add_pins.sql (8.46ms)9552026/10/01 09:46:21 OK 20251218171726_add_pins.sql (13.35ms)9562026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (6.53ms)9572026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (9.83ms)9582026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (5.73ms)9592026/10/01 09:46:21 OK 20241026095416_initial_model.sql (28.4ms)9602026/10/01 09:46:21 OK 20241026095416_initial_model.sql (24.01ms)9612026/10/01 09:46:21 OK 20241026095416_initial_model.sql (25.34ms)9622026/10/01 09:46:21 OK 20241026095416_initial_model.sql (24.63ms)9632026/10/01 09:46:21 OK 20260905000000_add_claims.sql (8.43ms)9642026/10/01 09:46:21 OK 20260905000000_add_claims.sql (18.71ms)9652026/10/01 09:46:21 OK 20241026095416_initial_model.sql (29.91ms)9662026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (12.15ms)9672026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (7.71ms)9682026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (6.06ms)9692026/10/01 09:46:21 OK 20241026095416_initial_model.sql (26.44ms)9702026/10/01 09:46:21 OK 20241026095416_initial_model.sql (28.31ms)9712026/10/01 09:46:21 OK 20241026095416_initial_model.sql (27.1ms)9722026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (7.65ms)9732026/10/01 09:46:21 OK 20241026095416_initial_model.sql (34.67ms)9742026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (6.33ms)9752026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (6.17ms)9762026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (11.93ms)9772026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200009782026/10/01 09:46:21 OK 20251218171726_add_pins.sql (10.58ms)9792026/10/01 09:46:21 OK 20251218171726_add_pins.sql (11.59ms)9802026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (14.44ms)9812026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (5.36ms)9822026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (6.62ms)9832026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (6.05ms)9842026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (6.2ms)9852026/10/01 09:46:21 OK 20251218171726_add_pins.sql (8.87ms)9862026/10/01 09:46:21 OK 20260905000000_add_claims.sql (11.13ms)9872026/10/01 09:46:21 OK 1_commit_pending_closure.sql (7.9ms)9882026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (7.69ms)9892026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (8.55ms)9902026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (9.32ms)9912026/10/01 09:46:21 goose: successfully migrated database to version: 202609231200009922026/10/01 09:46:21 INFO Received cleanup request method=DELETE path=/api/pending_closures9932026/10/01 09:46:21 OK 20260905000000_add_claims.sql (9.04ms)9942026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (12.62ms)9952026/10/01 09:46:21 OK 20251218171726_add_pins.sql (9.66ms)9962026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (9.15ms)9972026/10/01 09:46:21 OK 20251218171726_add_pins.sql (9.42ms)9982026/10/01 09:46:21 OK 20251218171726_add_pins.sql (9.39ms)9992026/10/01 09:46:21 OK 20251218171726_add_pins.sql (7.44ms)10002026/10/01 09:46:21 OK 2_object_stats_trigger.sql (2.93ms)10012026/10/01 09:46:21 INFO Aborted multipart uploads count=1 kept=010022026/10/01 09:46:21 OK 20251218171726_add_pins.sql (6.01ms)10032026/10/01 09:46:21 OK 20251218171726_add_pins.sql (6.5ms)10042026/10/01 09:46:21 OK 20251218171726_add_pins.sql (6.62ms)10052026/10/01 09:46:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10062026/10/01 09:46:21 OK 20251218171726_add_pins.sql (6.5ms)10072026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (5.93ms)10082026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (5.86ms)10092026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010102026/10/01 09:46:21 OK 20260905000000_add_claims.sql (7.49ms)10112026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (7.68ms)10122026/10/01 09:46:21 OK 3_commit_push.sql (4.59ms)10132026/10/01 09:46:21 goose: up to current file version: 310142026/10/01 09:46:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10152026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.88ms)10162026/10/01 09:46:21 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1017--- PASS: TestCompleteMultipartUnregistered (0.44s)1018=== CONT TestSweepRechecksPendingAfterLocking10192026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (8.66ms)10202026-10-01 09:46:21.604 UTC [450] ERROR: Closure does not exist: id=110212026-10-01 09:46:21.604 UTC [450] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE10222026-10-01 09:46:21.604 UTC [450] STATEMENT: -- name: CommitPendingClosure :exec1023 SELECT commit_pending_closure($1::bigint)1024 1025--- PASS: TestService_cleanupPendingClosuresHandler (0.45s)10262026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (9.37ms)1027=== CONT TestProxyWriteTimeout1028=== RUN TestProxyWriteTimeout/narinfo1029=== PAUSE TestProxyWriteTimeout/narinfo1030=== RUN TestProxyWriteTimeout/1_GiB_nar1031=== PAUSE TestProxyWriteTimeout/1_GiB_nar1032=== RUN TestProxyWriteTimeout/10_GiB_nar1033=== PAUSE TestProxyWriteTimeout/10_GiB_nar1034=== RUN TestProxyWriteTimeout/unknown_size1035=== PAUSE TestProxyWriteTimeout/unknown_size1036=== CONT TestGetExistingObjectsLocksRows10372026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (8.46ms)10382026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (11.15ms)10392026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (8.82ms)10402026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (11.31ms)10412026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (8.73ms)10422026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (11.22ms)10432026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (6.42ms)10442026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (6.51ms)10452026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (5.92ms)10462026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010472026/10/01 09:46:21 OK 2_object_stats_trigger.sql (7.4ms)10482026/10/01 09:46:21 OK 20260905000000_add_claims.sql (7.68ms)10492026/10/01 09:46:21 OK 20260905000000_add_claims.sql (13.77ms)10502026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (10.11ms)10512026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010522026/10/01 09:46:21 OK 1_commit_pending_closure.sql (10.04ms)10532026/10/01 09:46:21 OK 20260905000000_add_claims.sql (10.46ms)10542026/10/01 09:46:21 OK 20260905000000_add_claims.sql (9.69ms)10552026/10/01 09:46:21 OK 20260905000000_add_claims.sql (9.91ms)10562026/10/01 09:46:21 OK 20260905000000_add_claims.sql (10.18ms)10572026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (9.37ms)10582026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010592026/10/01 09:46:21 OK 20260905000000_add_claims.sql (10.33ms)10602026/10/01 09:46:21 OK 1_commit_pending_closure.sql (5.87ms)10612026/10/01 09:46:21 OK 20260905000000_add_claims.sql (10.41ms)10622026/10/01 09:46:21 OK 20260905000000_add_claims.sql (10.51ms)10632026/10/01 09:46:21 OK 3_commit_push.sql (8.29ms)10642026/10/01 09:46:21 goose: up to current file version: 310652026/10/01 09:46:21 OK 2_object_stats_trigger.sql (5.76ms)10662026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (8.82ms)10672026/10/01 09:46:21 OK 20260905000000_add_claims.sql (10.42ms)10682026/10/01 09:46:21 OK 1_commit_pending_closure.sql (8.76ms)10692026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (8.38ms)10702026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (4.16ms)10712026/10/01 09:46:21 OK 2_object_stats_trigger.sql (2.2ms)10722026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (3.77ms)10732026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (3.43ms)10742026/10/01 09:46:21 OK 1_commit_pending_closure.sql (4.55ms)10752026/10/01 09:46:21 OK 3_commit_push.sql (3.99ms)10762026/10/01 09:46:21 goose: up to current file version: 310772026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.73ms)10782026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.65ms)10792026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010802026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (4.56ms)10812026/10/01 09:46:21 OK 3_commit_push.sql (2.93ms)10822026/10/01 09:46:21 goose: up to current file version: 310832026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (6.27ms)10842026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (5.28ms)10852026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (5.61ms)10862026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (5.47ms)10872026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (8.15ms)10882026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010892026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.7ms)10902026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.55ms)10912026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010922026/10/01 09:46:21 OK 3_commit_push.sql (5.4ms)10932026/10/01 09:46:21 goose: up to current file version: 310942026/10/01 09:46:21 OK 2_object_stats_trigger.sql (5.66ms)10952026/10/01 09:46:21 OK 1_commit_pending_closure.sql (4.81ms)10962026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.01ms)10972026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000010982026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (6.97ms)10992026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011002026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011012026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (7.75ms)11022026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011032026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.47ms)11042026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011052026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (7.04ms)11062026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011072026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (6.43ms)11082026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011092026/10/01 09:46:21 OK 1_commit_pending_closure.sql (4.9ms)11102026/10/01 09:46:21 OK 1_commit_pending_closure.sql (4.81ms)11112026/10/01 09:46:21 OK 2_object_stats_trigger.sql (6.23ms)11122026/10/01 09:46:21 OK 2_object_stats_trigger.sql (2.94ms)11132026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.23ms)11142026/10/01 09:46:21 OK 3_commit_push.sql (6.47ms)11152026/10/01 09:46:21 goose: up to current file version: 311162026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.02ms)11172026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.08ms)11182026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.16ms)11192026/10/01 09:46:21 OK 1_commit_pending_closure.sql (6.65ms)11202026/10/01 09:46:21 OK 1_commit_pending_closure.sql (4.76ms)11212026/10/01 09:46:21 OK 2_object_stats_trigger.sql (2.52ms)11222026/10/01 09:46:21 OK 3_commit_push.sql (3.09ms)11232026/10/01 09:46:21 goose: up to current file version: 311242026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.06ms)11252026/10/01 09:46:21 OK 3_commit_push.sql (3.2ms)11262026/10/01 09:46:21 goose: up to current file version: 311272026/10/01 09:46:21 OK 1_commit_pending_closure.sql (9.12ms)11282026/10/01 09:46:21 OK 3_commit_push.sql (2.51ms)11292026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.75ms)11302026/10/01 09:46:21 goose: up to current file version: 311312026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.88ms)11322026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.83ms)11332026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.7ms)11342026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.8ms)11352026/10/01 09:46:21 OK 3_commit_push.sql (1.94ms)11362026/10/01 09:46:21 goose: up to current file version: 311372026/10/01 09:46:21 OK 3_commit_push.sql (2.28ms)11382026/10/01 09:46:21 goose: up to current file version: 311392026/10/01 09:46:21 OK 2_object_stats_trigger.sql (3.09ms)11402026/10/01 09:46:21 OK 3_commit_push.sql (4.21ms)11412026/10/01 09:46:21 goose: up to current file version: 311422026/10/01 09:46:21 OK 3_commit_push.sql (4.18ms)11432026/10/01 09:46:21 goose: up to current file version: 311442026/10/01 09:46:21 OK 3_commit_push.sql (4.32ms)11452026/10/01 09:46:21 goose: up to current file version: 311462026/10/01 09:46:21 OK 3_commit_push.sql (4.45ms)11472026/10/01 09:46:21 goose: up to current file version: 311482026/10/01 09:46:21 OK 3_commit_push.sql (2.78ms)11492026/10/01 09:46:21 goose: up to current file version: 31150--- PASS: TestService_Rustfstest (0.49s)1151=== CONT TestClientFallsBackToClosures11522026/10/01 09:46:21 INFO Received uploads request method=POST path=/api/pending_closures11532026-10-01 09:46:21.703 UTC [483] ERROR: relation "goose_db_version" does not exist at character 3611542026-10-01 09:46:21.703 UTC [483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11552026-10-01 09:46:21.704 UTC [484] ERROR: relation "goose_db_version" does not exist at character 3611562026-10-01 09:46:21.704 UTC [484] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11572026/10/01 09:46:21 OK 20241026095416_initial_model.sql (11.05ms)11582026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)11592026/10/01 09:46:21 OK 20241026095416_initial_model.sql (10.65ms)11602026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)11612026/10/01 09:46:21 OK 20251218171726_add_pins.sql (3.48ms)11622026/10/01 09:46:21 OK 20251218171726_add_pins.sql (3.45ms)11632026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)11642026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (4ms)11652026/10/01 09:46:21 INFO Received uploads request method=POST path=/api/pending_closures11662026/10/01 09:46:21 OK 20260905000000_add_claims.sql (4.02ms)11672026-10-01 09:46:21.740 UTC [485] ERROR: relation "goose_db_version" does not exist at character 3611682026-10-01 09:46:21.740 UTC [485] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11692026/10/01 09:46:21 OK 20260905000000_add_claims.sql (4.11ms)11702026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (3.8ms)11712026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (3.35ms)11722026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (4.52ms)11732026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011742026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (6.08ms)11752026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011762026/10/01 09:46:21 OK 1_commit_pending_closure.sql (2.53ms)11772026/10/01 09:46:21 OK 1_commit_pending_closure.sql (2.94ms)11782026/10/01 09:46:21 OK 2_object_stats_trigger.sql (1.23ms)11792026/10/01 09:46:21 OK 2_object_stats_trigger.sql (1.34ms)11802026/10/01 09:46:21 OK 3_commit_push.sql (882.11µs)11812026/10/01 09:46:21 goose: up to current file version: 311822026/10/01 09:46:21 OK 3_commit_push.sql (1.68ms)11832026/10/01 09:46:21 goose: up to current file version: 311842026/10/01 09:46:21 OK 20241026095416_initial_model.sql (9.71ms)11852026/10/01 09:46:21 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)11862026/10/01 09:46:21 OK 20251218171726_add_pins.sql (3.16ms)11872026/10/01 09:46:21 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)11882026/10/01 09:46:21 OK 20260905000000_add_claims.sql (3.15ms)11892026/10/01 09:46:21 OK 20260920000000_drop_claims.sql (6.44ms)11902026/10/01 09:46:21 OK 20260923120000_add_pushes.sql (5.93ms)11912026/10/01 09:46:21 goose: successfully migrated database to version: 2026092312000011922026/10/01 09:46:21 OK 1_commit_pending_closure.sql (3.27ms)11932026/10/01 09:46:21 OK 2_object_stats_trigger.sql (1.75ms)11942026/10/01 09:46:21 OK 3_commit_push.sql (1.81ms)11952026/10/01 09:46:21 goose: up to current file version: 311962026/10/01 09:46:21 INFO Received uploads request method=POST path=/api/pending_closures11972026/10/01 09:46:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11982026/10/01 09:46:21 INFO Received uploads request method=POST path=/api/pending_closures11992026/10/01 09:46:21 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzQ1MDBkYTYtNDc3Ni00ZDgxLTgyNTMtNmQ4MGU4OGZjODAzLjMwM2UzMTBkLTE2NGItNDJjMS05NmFjLWVmODBiNTQyN2U2M3gxNzkwODQ3OTgxODA5MDk2NDQ512002026/10/01 09:46:21 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzQ1MDBkYTYtNDc3Ni00ZDgxLTgyNTMtNmQ4MGU4OGZjODAzLjMwM2UzMTBkLTE2NGItNDJjMS05NmFjLWVmODBiNTQyN2U2M3gxNzkwODQ3OTgxODA5MDk2NDQ5 parts=112012026/10/01 09:46:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1202--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.72s)1203=== CONT TestRegisterCompletedObjectNeedsPendingRow1204--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.73s)1205=== CONT TestClientPushesUseOnePush12062026/10/01 09:46:21 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1207--- PASS: TestService_AuthMiddleware (0.77s)1208=== CONT TestSweepSkipsRowsLockedByPush1209=== RUN TestPush_RejectsBadRequests/no_roots1210=== PAUSE TestPush_RejectsBadRequests/no_roots1211=== RUN TestPush_RejectsBadRequests/no_objects1212=== PAUSE TestPush_RejectsBadRequests/no_objects1213=== RUN TestPush_RejectsBadRequests/bad_root1214=== PAUSE TestPush_RejectsBadRequests/bad_root1215=== RUN TestPush_RejectsBadRequests/root_not_in_objects1216=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1217=== CONT TestPinProtectsFromGC12182026-10-01 09:46:21.991 UTC [495] ERROR: relation "goose_db_version" does not exist at character 3612192026-10-01 09:46:21.991 UTC [495] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12202026-10-01 09:46:21.992 UTC [496] ERROR: relation "goose_db_version" does not exist at character 3612212026-10-01 09:46:21.992 UTC [496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12222026/10/01 09:46:22 OK 20241026095416_initial_model.sql (11.76ms)12232026/10/01 09:46:22 OK 20241026095416_initial_model.sql (12.35ms)12242026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (3.43ms)12252026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)1226--- PASS: TestReadRedirectUsesPublicS3URL (0.85s)1227=== CONT TestReadProxyDisabled12282026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.23ms)12292026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.04ms)12302026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.31ms)12312026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (7.83ms)12322026-10-01 09:46:22.029 UTC [498] ERROR: relation "goose_db_version" does not exist at character 3612332026-10-01 09:46:22.029 UTC [498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12342026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.01ms)12352026/10/01 09:46:22 OK 20260905000000_add_claims.sql (3.8ms)12362026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.72ms)12372026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.42ms)12382026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.42ms)12392026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000012402026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.24ms)12412026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000012422026/10/01 09:46:22 OK 1_commit_pending_closure.sql (3.14ms)12432026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.63ms)12442026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.7ms)12452026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.52ms)12462026/10/01 09:46:22 OK 3_commit_push.sql (2.5ms)12472026/10/01 09:46:22 goose: up to current file version: 312482026/10/01 09:46:22 OK 3_commit_push.sql (1.67ms)12492026/10/01 09:46:22 goose: up to current file version: 312502026/10/01 09:46:22 OK 20241026095416_initial_model.sql (11.55ms)12512026-10-01 09:46:22.048 UTC [500] ERROR: relation "goose_db_version" does not exist at character 3612522026-10-01 09:46:22.048 UTC [500] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12532026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)12542026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.29ms)12552026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.7ms)1256--- PASS: TestReadRedirectKeepsNarinfoProxied (0.88s)1257=== CONT TestFailedS3DeleteKeepsTombstone12582026/10/01 09:46:22 OK 20241026095416_initial_model.sql (12.64ms)12592026/10/01 09:46:22 OK 20260905000000_add_claims.sql (6.29ms)12602026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (3.14ms)12612026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (4.88ms)12622026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.06ms)12632026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.53ms)12642026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000012652026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.79ms)12662026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)12672026/10/01 09:46:22 OK 2_object_stats_trigger.sql (7.92ms)12682026/10/01 09:46:22 OK 20260905000000_add_claims.sql (7.93ms)12692026/10/01 09:46:22 OK 3_commit_push.sql (2.19ms)12702026/10/01 09:46:22 goose: up to current file version: 312712026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.95ms)12722026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.67ms)12732026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000012742026-10-01 09:46:22.095 UTC [503] ERROR: relation "goose_db_version" does not exist at character 3612752026-10-01 09:46:22.095 UTC [503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12762026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures12772026/10/01 09:46:22 OK 1_commit_pending_closure.sql (18.44ms)12782026/10/01 09:46:22 OK 2_object_stats_trigger.sql (3.76ms)12792026/10/01 09:46:22 OK 3_commit_push.sql (1.87ms)12802026/10/01 09:46:22 goose: up to current file version: 312812026/10/01 09:46:22 OK 20241026095416_initial_model.sql (12.23ms)12822026/10/01 09:46:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12832026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.53ms)12842026/10/01 09:46:22 OK 20251218171726_add_pins.sql (8.83ms)12852026-10-01 09:46:22.141 UTC [504] ERROR: relation "goose_db_version" does not exist at character 3612862026-10-01 09:46:22.141 UTC [504] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12872026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (4.32ms)12882026/10/01 09:46:22 OK 20260905000000_add_claims.sql (5.32ms)12892026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.8ms)12902026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.75ms)12912026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000012922026/10/01 09:46:22 OK 20241026095416_initial_model.sql (9.62ms)12932026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures12942026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures12952026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures12962026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)12972026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.03ms)12982026/10/01 09:46:22 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzQ1MDBkYTYtNDc3Ni00ZDgxLTgyNTMtNmQ4MGU4OGZjODAzLjk0ODMxMzdhLTUxYTEtNDg5OS05YmUxLTVjMmY2M2Q5YzVkNXgxNzkwODQ3OTgxNzAxOTA3MTIz parts=1012992026/10/01 09:46:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13002026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.93ms)13012026/10/01 09:46:22 OK 3_commit_push.sql (2.34ms)13022026/10/01 09:46:22 goose: up to current file version: 313032026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.95ms)13042026/10/01 09:46:22 INFO Completed upload id=113052026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures13062026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)13072026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures13082026/10/01 09:46:22 OK 20260905000000_add_claims.sql (3.95ms)13092026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.15ms)13102026/10/01 09:46:22 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13112026/10/01 09:46:22 WARN Found objects in DB but missing from S3, will re-upload count=11312--- PASS: TestService_verifyS3Integrity (1.01s)1313=== CONT TestCacheConfigHandler13142026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (1.94ms)1315=== RUN TestCacheConfigHandler/full_config,_no_issuer13162026/10/01 09:46:22 goose: successfully migrated database to version: 202609231200001317=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1318=== RUN TestCacheConfigHandler/no_cache_url_configured1319=== PAUSE TestCacheConfigHandler/no_cache_url_configured1320=== RUN TestCacheConfigHandler/no_signing_keys1321=== PAUSE TestCacheConfigHandler/no_signing_keys1322=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1323=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1324=== CONT TestForceGCDuringPushOffersSweptObject1325=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1326=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1327=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1328=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1329=== CONT TestReadProxyRootRedirectsToIndexHTML13302026/10/01 09:46:22 OK 1_commit_pending_closure.sql (1.82ms)13312026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.17ms)13322026/10/01 09:46:22 OK 3_commit_push.sql (677.79µs)13332026/10/01 09:46:22 goose: up to current file version: 313342026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes13352026/10/01 09:46:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13362026/10/01 09:46:22 INFO Signed narinfos id=1 count=11337--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (1.05s)1338=== CONT TestService_ReadScope_PublicByDefault13392026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes13402026-10-01 09:46:22.236 UTC [528] ERROR: relation "goose_db_version" does not exist at character 3613412026-10-01 09:46:22.236 UTC [528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13422026/10/01 09:46:22 INFO Received complete push request method=POST path=/api/pushes/1/complete13432026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures13442026/10/01 09:46:22 OK 20241026095416_initial_model.sql (10.95ms)1345--- PASS: TestPush_CompleteCommitsEveryRoot (1.09s)1346=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13472026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (5.11ms)13482026/10/01 09:46:22 OK 20251218171726_add_pins.sql (3.91ms)13492026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (3.4ms)13502026/10/01 09:46:22 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13512026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures13522026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.19ms)1353--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.11s)1354=== CONT TestReadProxyConditionalGet13552026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.41ms)13562026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes13572026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.6ms)13582026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000013592026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.43ms)13602026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.69ms)13612026/10/01 09:46:22 OK 3_commit_push.sql (1.04ms)13622026/10/01 09:46:22 goose: up to current file version: 313632026-10-01 09:46:22.282 UTC [535] ERROR: relation "goose_db_version" does not exist at character 3613642026-10-01 09:46:22.282 UTC [535] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13652026/10/01 09:46:22 INFO Received complete push request method=POST path=/api/pushes/1/complete13662026/10/01 09:46:22 OK 20241026095416_initial_model.sql (13.29ms)13672026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (9.51ms)13682026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes13692026/10/01 09:46:22 OK 20251218171726_add_pins.sql (6.17ms)13702026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)13712026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.66ms)13722026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.93ms)13732026-10-01 09:46:22.330 UTC [537] ERROR: relation "goose_db_version" does not exist at character 3613742026-10-01 09:46:22.330 UTC [537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13752026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.07ms)13762026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000013772026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.49ms)13782026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.42ms)13792026/10/01 09:46:22 OK 3_commit_push.sql (1.7ms)13802026/10/01 09:46:22 goose: up to current file version: 313812026-10-01 09:46:22.343 UTC [538] ERROR: relation "goose_db_version" does not exist at character 3613822026-10-01 09:46:22.343 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13832026/10/01 09:46:22 OK 20241026095416_initial_model.sql (8.76ms)13842026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (1.72ms)13852026/10/01 09:46:22 OK 20251218171726_add_pins.sql (3.41ms)13862026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=013872026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (4.29ms)13882026/10/01 09:46:22 WARN Force mode enabled - objects will be deleted immediately without grace period13892026/10/01 09:46:22 OK 20260905000000_add_claims.sql (3.45ms)13902026/10/01 09:46:22 OK 20241026095416_initial_model.sql (8.71ms)13912026/10/01 09:46:22 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013922026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (1.48ms)1393--- PASS: TestGCEndsOnShutdown (1.19s)1394=== CONT TestService_RequireScope_OIDC13952026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.39ms)13962026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (1.98ms)13972026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000013982026/10/01 09:46:22 INFO Vacuumed table table=pending_closures13992026/10/01 09:46:22 INFO Vacuumed table table=pending_objects14002026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.14ms)14012026/10/01 09:46:22 INFO Vacuumed table table=multipart_uploads14022026/10/01 09:46:22 OK 20251218171726_add_pins.sql (6.14ms)14032026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.73ms)14042026/10/01 09:46:22 INFO Vacuumed table table=closures14052026/10/01 09:46:22 OK 3_commit_push.sql (660.73µs)14062026/10/01 09:46:22 goose: up to current file version: 314072026/10/01 09:46:22 INFO Vacuumed table table=objects14082026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.84ms)14092026/10/01 09:46:22 OK 20260905000000_add_claims.sql (3.34ms)14102026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.39ms)1411--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.21s)1412=== CONT TestReadProxyHead14132026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=014142026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (1.84ms)14152026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000014162026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures14172026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.69ms)14182026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.12ms)14192026/10/01 09:46:22 WARN Force mode enabled - objects will be deleted immediately without grace period14202026/10/01 09:46:22 OK 3_commit_push.sql (989.67µs)14212026/10/01 09:46:22 goose: up to current file version: 314222026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures14232026/10/01 09:46:22 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=014242026/10/01 09:46:22 INFO Vacuumed table table=pending_closures14252026/10/01 09:46:22 INFO Vacuumed table table=pending_objects14262026/10/01 09:46:22 INFO Vacuumed table table=multipart_uploads14272026/10/01 09:46:22 INFO Vacuumed table table=closures14282026/10/01 09:46:22 INFO Vacuumed table table=objects14292026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes14302026/10/01 09:46:22 INFO Received complete push request method=POST path=/api/pushes/2/complete1431--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.25s)1432=== CONT TestService_AuthMiddleware_OIDC1433--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.27s)1434=== CONT TestReadProxyInvalidPath14352026-10-01 09:46:22.447 UTC [548] ERROR: relation "goose_db_version" does not exist at character 3614362026-10-01 09:46:22.447 UTC [548] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14372026/10/01 09:46:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38039/oidc1438--- PASS: TestReadProxyRangeRequest (1.29s)1439=== CONT TestService_ReadAuthMiddleware14402026/10/01 09:46:22 OK 20241026095416_initial_model.sql (15.9ms)14412026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (5.88ms)14422026/10/01 09:46:22 OK 20251218171726_add_pins.sql (8.05ms)14432026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (10.4ms)14442026/10/01 09:46:22 OK 20260905000000_add_claims.sql (9.91ms)14452026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (16.07ms)14462026/10/01 09:46:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14472026/10/01 09:46:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14482026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.46ms)14492026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000014502026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures14512026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.64ms)14522026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.59ms)14532026/10/01 09:46:22 OK 3_commit_push.sql (1.67ms)14542026/10/01 09:46:22 goose: up to current file version: 314552026-10-01 09:46:22.534 UTC [553] ERROR: relation "goose_db_version" does not exist at character 3614562026-10-01 09:46:22.534 UTC [553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14572026/10/01 09:46:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41533/oidc14582026-10-01 09:46:22.545 UTC [557] ERROR: relation "goose_db_version" does not exist at character 3614592026-10-01 09:46:22.545 UTC [557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14602026/10/01 09:46:22 OK 20241026095416_initial_model.sql (12.06ms)14612026/10/01 09:46:22 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzQ1MDBkYTYtNDc3Ni00ZDgxLTgyNTMtNmQ4MGU4OGZjODAzLjczZDNmYWQ5LTExNDQtNDIxOC05NzdhLTNkZmRlMjhlZDFiMHgxNzkwODQ3OTgyMTY2OTA4MDEy parts=1014622026/10/01 09:46:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14632026/10/01 09:46:22 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzQ1MDBkYTYtNDc3Ni00ZDgxLTgyNTMtNmQ4MGU4OGZjODAzLmEzMzcyZDdjLWQ1OTMtNGZkZS05OTJlLTNiZjI3ZTBmNDc4NHgxNzkwODQ3OTgyMTIwNDM0MzUz parts=1214642026/10/01 09:46:22 INFO Completed upload id=114652026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (6.08ms)14662026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures14672026/10/01 09:46:22 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014682026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures1469--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.40s)1470=== CONT TestGCSweepDeliversEachKeyOnce14712026/10/01 09:46:22 OK 20251218171726_add_pins.sql (12.59ms)14722026/10/01 09:46:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures1473--- PASS: TestReadRedirectNar (1.27s)1474=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14752026-10-01 09:46:22.573 UTC [559] ERROR: relation "goose_db_version" does not exist at character 3614762026-10-01 09:46:22.573 UTC [559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14772026/10/01 09:46:22 OK 20241026095416_initial_model.sql (21.04ms)14782026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (4.57ms)14792026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.76ms)14802026/10/01 09:46:22 OK 20251218171726_add_pins.sql (5.09ms)14812026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=014822026/10/01 09:46:22 OK 20260905000000_add_claims.sql (6.37ms)14832026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (8.27ms)14842026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (8.81ms)14852026/10/01 09:46:22 OK 20241026095416_initial_model.sql (15.1ms)14862026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.1ms)14872026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000014882026/10/01 09:46:22 OK 20260905000000_add_claims.sql (5.62ms)14892026/10/01 09:46:22 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=014902026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)14912026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.53ms)14922026/10/01 09:46:22 OK 1_commit_pending_closure.sql (3.89ms)14932026/10/01 09:46:22 INFO Vacuumed table table=pending_closures14942026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.03ms)14952026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.83ms)14962026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.1ms)14972026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000014982026/10/01 09:46:22 INFO Vacuumed table table=pending_objects14992026/10/01 09:46:22 OK 3_commit_push.sql (2.49ms)15002026/10/01 09:46:22 goose: up to current file version: 315012026/10/01 09:46:22 OK 1_commit_pending_closure.sql (3.3ms)15022026/10/01 09:46:22 INFO Vacuumed table table=multipart_uploads15032026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.32ms)15042026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.05ms)15052026/10/01 09:46:22 OK 3_commit_push.sql (1.22ms)15062026/10/01 09:46:22 goose: up to current file version: 315072026/10/01 09:46:22 INFO Vacuumed table table=closures15082026/10/01 09:46:22 INFO Vacuumed table table=objects15092026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.58ms)15102026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.68ms)15112026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=015122026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.68ms)15132026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000015142026/10/01 09:46:22 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001515--- PASS: TestService_createPendingClosureHandler (1.46s)15162026/10/01 09:46:22 WARN Force mode enabled - objects will be deleted immediately without grace period1517=== CONT TestTombstonedObjectOfferedWithoutWaiting15182026-10-01 09:46:22.630 UTC [566] ERROR: relation "goose_db_version" does not exist at character 3615192026-10-01 09:46:22.630 UTC [566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15202026/10/01 09:46:22 OK 1_commit_pending_closure.sql (10.95ms)15212026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.59ms)15222026/10/01 09:46:22 OK 3_commit_push.sql (2.25ms)15232026/10/01 09:46:22 goose: up to current file version: 315242026/10/01 09:46:22 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=015252026/10/01 09:46:22 INFO Vacuumed table table=pending_closures15262026/10/01 09:46:22 INFO Vacuumed table table=pending_objects15272026/10/01 09:46:22 INFO Vacuumed table table=multipart_uploads15282026/10/01 09:46:22 INFO Vacuumed table table=closures15292026/10/01 09:46:22 OK 20241026095416_initial_model.sql (10.31ms)1530--- PASS: TestGetExistingObjectsLocksRows (1.04s)1531=== CONT TestReadProxy40415322026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)15332026/10/01 09:46:22 INFO Vacuumed table table=objects15342026/10/01 09:46:22 OK 20251218171726_add_pins.sql (5.45ms)1535--- PASS: TestSweepRechecksPendingAfterLocking (1.05s)1536=== CONT TestGCSweepSkipsPendingObjects15372026-10-01 09:46:22.658 UTC [572] ERROR: relation "goose_db_version" does not exist at character 3615382026-10-01 09:46:22.658 UTC [572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15392026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.23ms)15402026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.92ms)15412026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.53ms)15422026-10-01 09:46:22.671 UTC [576] ERROR: relation "goose_db_version" does not exist at character 3615432026-10-01 09:46:22.671 UTC [576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15442026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.09ms)15452026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000015462026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.86ms)15472026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.86ms)15482026/10/01 09:46:22 OK 20241026095416_initial_model.sql (13.74ms)15492026/10/01 09:46:22 OK 3_commit_push.sql (4.25ms)15502026/10/01 09:46:22 goose: up to current file version: 315512026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.81ms)15522026/10/01 09:46:22 OK 20241026095416_initial_model.sql (11.56ms)15532026/10/01 09:46:22 OK 20251218171726_add_pins.sql (5.33ms)15542026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)15552026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (5.16ms)15562026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.68ms)15572026/10/01 09:46:22 OK 20260905000000_add_claims.sql (3.91ms)15582026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.99ms)15592026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (5.34ms)15602026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (2.64ms)15612026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000015622026/10/01 09:46:22 OK 20260905000000_add_claims.sql (5.06ms)15632026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.95ms)15642026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.05ms)15652026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.85ms)15662026/10/01 09:46:22 OK 3_commit_push.sql (1.81ms)15672026/10/01 09:46:22 goose: up to current file version: 315682026-10-01 09:46:22.715 UTC [594] ERROR: relation "goose_db_version" does not exist at character 3615692026-10-01 09:46:22.715 UTC [594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1570--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.83s)1571=== CONT TestReadProxyNarStreaming15722026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (12.66ms)15732026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000015742026/10/01 09:46:22 OK 1_commit_pending_closure.sql (3.11ms)15752026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.56ms)15762026/10/01 09:46:22 OK 3_commit_push.sql (1.36ms)15772026/10/01 09:46:22 goose: up to current file version: 315782026-10-01 09:46:22.737 UTC [598] ERROR: relation "goose_db_version" does not exist at character 3615792026-10-01 09:46:22.737 UTC [598] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15802026/10/01 09:46:22 OK 20241026095416_initial_model.sql (10.36ms)15812026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.47ms)15822026-10-01 09:46:22.743 UTC [599] ERROR: relation "goose_db_version" does not exist at character 3615832026-10-01 09:46:22.743 UTC [599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15842026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.57ms)15852026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)15862026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.5ms)15872026/10/01 09:46:22 OK 20241026095416_initial_model.sql (10.34ms)15882026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.14ms)15892026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)15902026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.22ms)15912026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000015922026/10/01 09:46:22 OK 20251218171726_add_pins.sql (3.78ms)15932026/10/01 09:46:22 OK 1_commit_pending_closure.sql (3.37ms)15942026/10/01 09:46:22 OK 20241026095416_initial_model.sql (11.47ms)15952026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.96ms)15962026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (6.19ms)15972026/10/01 09:46:22 OK 3_commit_push.sql (2.47ms)15982026/10/01 09:46:22 goose: up to current file version: 315992026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (4.04ms)16002026/10/01 09:46:22 OK 20260905000000_add_claims.sql (5.88ms)16012026/10/01 09:46:22 OK 20251218171726_add_pins.sql (5.26ms)16022026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.05ms)16032026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (5.37ms)16042026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (4.51ms)16052026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000016062026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.68ms)16072026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.83ms)16082026/10/01 09:46:22 OK 2_object_stats_trigger.sql (2.3ms)16092026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.94ms)16102026/10/01 09:46:22 OK 3_commit_push.sql (1.32ms)16112026/10/01 09:46:22 goose: up to current file version: 316122026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.75ms)16132026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000016142026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.09ms)16152026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.15ms)16162026-10-01 09:46:22.797 UTC [651] ERROR: relation "goose_db_version" does not exist at character 3616172026-10-01 09:46:22.797 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16182026/10/01 09:46:22 OK 3_commit_push.sql (1.7ms)16192026/10/01 09:46:22 goose: up to current file version: 316202026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=016212026/10/01 09:46:22 WARN Force mode enabled - objects will be deleted immediately without grace period16222026/10/01 09:46:22 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=016232026/10/01 09:46:22 INFO Vacuumed table table=pending_closures16242026/10/01 09:46:22 INFO Vacuumed table table=pending_objects16252026/10/01 09:46:22 INFO Vacuumed table table=multipart_uploads16262026/10/01 09:46:22 INFO Vacuumed table table=closures16272026/10/01 09:46:22 OK 20241026095416_initial_model.sql (9.9ms)16282026/10/01 09:46:22 INFO Vacuumed table table=objects16292026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)16302026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=016312026/10/01 09:46:22 OK 20251218171726_add_pins.sql (3.12ms)16322026/10/01 09:46:22 WARN Force mode enabled - objects will be deleted immediately without grace period16332026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (3.4ms)16342026/10/01 09:46:22 OK 20260905000000_add_claims.sql (3.08ms)16352026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (2.05ms)16362026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (1.7ms)16372026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000016382026/10/01 09:46:22 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=016392026/10/01 09:46:22 INFO Vacuumed table table=pending_closures16402026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.07ms)16412026/10/01 09:46:22 INFO Vacuumed table table=pending_objects1642--- PASS: TestReadProxyDisabled (0.81s)1643=== CONT TestService_AuthMiddleware_MTLSProxyHeader16442026/10/01 09:46:22 INFO Vacuumed table table=multipart_uploads16452026/10/01 09:46:22 INFO Vacuumed table table=closures16462026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.56ms)16472026/10/01 09:46:22 OK 3_commit_push.sql (1.28ms)16482026/10/01 09:46:22 goose: up to current file version: 316492026/10/01 09:46:22 INFO Vacuumed table table=objects1650--- PASS: TestSweepSkipsRowsLockedByPush (0.91s)1651=== CONT TestReadProxyNarinfoAlreadyDecompressed16522026/10/01 09:46:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16532026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures16542026/10/01 09:46:22 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzQ1MDBkYTYtNDc3Ni00ZDgxLTgyNTMtNmQ4MGU4OGZjODAzLjRjZTFkY2Y5LWZlMjUtNDYxNS1hMDcwLWY4N2IwZDNlNTQ0NngxNzkwODQ3OTgyMzkwMjc0MjI0 parts=121655--- PASS: TestRedundantMultipartUpload (1.70s)1656=== CONT TestDeduplicatedObjectsRecordedAsPending16572026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures16582026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures16592026/10/01 09:46:22 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16602026/10/01 09:46:22 INFO Uploading jp56bs1x3sd907rcj52jf5dc74q9pxhf-shared-dep (136B)16612026/10/01 09:46:22 INFO Uploading cp4rd47yv0xajm4l2w7mm5q3aw0fw6bc-a (216B)16622026/10/01 09:46:22 WARN Failed to register uploaded object key=yx70fwvxk808jzj3f9m9dlaid82khrfb.ls error="server returned 404: 404 page not found\n"16632026/10/01 09:46:22 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16642026/10/01 09:46:22 WARN Failed to register uploaded object key=nar/0s913pzyhihnsc6y34vjfimrg7qbf387lya6q29fmhdmd194h1cx.nar.zst error="server returned 404: 404 page not found\n"16652026/10/01 09:46:22 WARN Failed to register uploaded object key=jp56bs1x3sd907rcj52jf5dc74q9pxhf.ls error="server returned 404: 404 page not found\n"16662026/10/01 09:46:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16672026/10/01 09:46:22 WARN Failed to register uploaded object key=cp4rd47yv0xajm4l2w7mm5q3aw0fw6bc.ls error="server returned 404: 404 page not found\n"1668--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.72s)1669=== CONT TestReadProxyNarinfo1670=== NAME TestPinProtectsFromGC1671 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2178160130/001/store/r6pqz4m73fxmid2mxf41vzbgfcnrb8b2-pinned-file.txt1672 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2178160130/001/store/0jgf3bldm8iyrh34cavqwd0gw5i2smfz-unpinned-file.txt16732026/10/01 09:46:22 INFO Signed narinfos id=1 count=216742026/10/01 09:46:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16752026/10/01 09:46:22 INFO Signed narinfos id=2 count=216762026/10/01 09:46:22 INFO Uploading 4 narinfos16772026/10/01 09:46:22 WARN Failed to register uploaded object key=jp56bs1x3sd907rcj52jf5dc74q9pxhf.narinfo error="server returned 404: 404 page not found\n"16782026/10/01 09:46:22 WARN Failed to register uploaded object key=yx70fwvxk808jzj3f9m9dlaid82khrfb.narinfo error="server returned 404: 404 page not found\n"16792026/10/01 09:46:22 WARN Failed to register uploaded object key=cp4rd47yv0xajm4l2w7mm5q3aw0fw6bc.narinfo error="server returned 404: 404 page not found\n"16802026/10/01 09:46:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16812026/10/01 09:46:22 WARN Failed to register uploaded object key=jp56bs1x3sd907rcj52jf5dc74q9pxhf.narinfo error="server returned 404: 404 page not found\n"16822026/10/01 09:46:22 INFO Completed upload id=116832026/10/01 09:46:22 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16842026/10/01 09:46:22 INFO Completed upload id=216852026-10-01 09:46:22.915 UTC [786] ERROR: relation "goose_db_version" does not exist at character 3616862026-10-01 09:46:22.915 UTC [786] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16872026/10/01 09:46:22 INFO Upload complete. (84ms)16882026-10-01 09:46:22.916 UTC [787] ERROR: relation "goose_db_version" does not exist at character 3616892026-10-01 09:46:22.916 UTC [787] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1690=== NAME TestClientFallsBackToClosures1691 client_pushes_test.go:112: Retrieved narinfo from S3:1692 StorePath: /build/TestClientFallsBackToClosures1604023206/001/store/jp56bs1x3sd907rcj52jf5dc74q9pxhf-shared-dep1693 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1694 Compression: zstd1695 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821696 NarSize: 1361697 References: 1698 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1699--- PASS: TestService_ReadScope_PublicByDefault (0.71s)1700=== CONT TestCacheStatsHandler1701=== NAME TestClientFallsBackToClosures1702 client_pushes_test.go:112: Retrieved narinfo from S3:1703 StorePath: /build/TestClientFallsBackToClosures1604023206/001/store/cp4rd47yv0xajm4l2w7mm5q3aw0fw6bc-a1704 URL: nar/0s913pzyhihnsc6y34vjfimrg7qbf387lya6q29fmhdmd194h1cx.nar.zst1705 Compression: zstd1706 NarHash: sha256:0s913pzyhihnsc6y34vjfimrg7qbf387lya6q29fmhdmd194h1cx1707 NarSize: 2161708 References: /build/TestClientFallsBackToClosures1604023206/001/store/jp56bs1x3sd907rcj52jf5dc74q9pxhf-shared-dep1709 CA: text:sha256:13shq3x4x5s3dwx8h7qnbf86wdi53r8j326pz18vql9xw0xb98bx1710 client_pushes_test.go:112: Retrieved narinfo from S3:1711 StorePath: /build/TestClientFallsBackToClosures1604023206/001/store/yx70fwvxk808jzj3f9m9dlaid82khrfb-b1712 URL: nar/0s913pzyhihnsc6y34vjfimrg7qbf387lya6q29fmhdmd194h1cx.nar.zst1713 Compression: zstd1714 NarHash: sha256:0s913pzyhihnsc6y34vjfimrg7qbf387lya6q29fmhdmd194h1cx1715 NarSize: 2161716 References: /build/TestClientFallsBackToClosures1604023206/001/store/jp56bs1x3sd907rcj52jf5dc74q9pxhf-shared-dep1717 CA: text:sha256:13shq3x4x5s3dwx8h7qnbf86wdi53r8j326pz18vql9xw0xb98bx1718--- PASS: TestClientFallsBackToClosures (1.28s)1719=== CONT TestLeadEndsOnShutdown17202026/10/01 09:46:22 OK 20241026095416_initial_model.sql (14.62ms)17212026/10/01 09:46:22 OK 20241026095416_initial_model.sql (13.8ms)17222026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.59ms)17232026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (2.96ms)17242026/10/01 09:46:22 INFO Aborted multipart uploads count=0 kept=017252026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.29ms)17262026/10/01 09:46:22 OK 20251218171726_add_pins.sql (4.93ms)17272026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes17282026/10/01 09:46:22 WARN Force mode enabled - objects will be deleted immediately without grace period17292026-10-01 09:46:22.948 UTC [828] ERROR: relation "goose_db_version" does not exist at character 3617302026-10-01 09:46:22.948 UTC [828] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17312026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)17322026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (5.23ms)17332026/10/01 09:46:22 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17342026/10/01 09:46:22 INFO Uploading rp4206gdjs9spp01lrk3zz0rimcx2186-a (208B)17352026/10/01 09:46:22 INFO Uploading w3xgancr56b2gaygjrc007zsjap2gw7h-shared-dep (136B)17362026/10/01 09:46:22 OK 20260905000000_add_claims.sql (5.35ms)17372026/10/01 09:46:22 OK 20260905000000_add_claims.sql (5.03ms)17382026/10/01 09:46:22 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."17392026/10/01 09:46:22 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."17402026/10/01 09:46:22 WARN Failed to register uploaded object key=mbyhich4ajsac9rdgvb0wgz58gibs4rv.ls error="server returned 404: 404 page not found\n"17412026/10/01 09:46:22 WARN Failed to register uploaded object key=w3xgancr56b2gaygjrc007zsjap2gw7h.ls error="server returned 404: 404 page not found\n"17422026/10/01 09:46:22 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17432026/10/01 09:46:22 WARN Failed to register uploaded object key=rp4206gdjs9spp01lrk3zz0rimcx2186.ls error="server returned 404: 404 page not found\n"17442026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (3.38ms)17452026/10/01 09:46:22 WARN Failed to register uploaded object key=nar/0p72z78m96ipwcj3kpv3pyj48wfbsmk1n6yjvk3crcz47c63lmk2.nar.zst error="server returned 404: 404 page not found\n"17462026/10/01 09:46:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17472026/10/01 09:46:22 INFO Signed narinfos id=1 count=317482026/10/01 09:46:22 INFO Uploading 3 narinfos17492026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (5.98ms)1750--- PASS: TestFailedS3DeleteKeepsTombstone (0.90s)17512026/10/01 09:46:22 INFO Received uploads request method=POST path=/api/pending_closures1752=== CONT TestClientSharedPathCommittedMidPush17532026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.42ms)17542026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000017552026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.06ms)17562026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000017572026/10/01 09:46:22 OK 1_commit_pending_closure.sql (2.83ms)17582026/10/01 09:46:22 OK 20241026095416_initial_model.sql (12.25ms)17592026/10/01 09:46:22 WARN Failed to register uploaded object key=mbyhich4ajsac9rdgvb0wgz58gibs4rv.narinfo error="server returned 404: 404 page not found\n"17602026/10/01 09:46:22 INFO Received complete push request method=POST path=/api/pushes/1/complete17612026/10/01 09:46:22 WARN Failed to register uploaded object key=rp4206gdjs9spp01lrk3zz0rimcx2186.narinfo error="server returned 404: 404 page not found\n"17622026/10/01 09:46:22 INFO Received push request method=POST path=/api/pushes17632026/10/01 09:46:22 OK 1_commit_pending_closure.sql (5.79ms)17642026/10/01 09:46:22 OK 2_object_stats_trigger.sql (3.74ms)17652026/10/01 09:46:22 OK 20251210153512_drop_unused_gin_index.sql (4ms)17662026/10/01 09:46:22 OK 3_commit_push.sql (1.46ms)17672026/10/01 09:46:22 goose: up to current file version: 317682026/10/01 09:46:22 OK 2_object_stats_trigger.sql (1.9ms)17692026/10/01 09:46:22 WARN Failed to register uploaded object key=w3xgancr56b2gaygjrc007zsjap2gw7h.narinfo error="server returned 404: 404 page not found\n"17702026/10/01 09:46:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17712026/10/01 09:46:22 INFO Uploading r6pqz4m73fxmid2mxf41vzbgfcnrb8b2-pinned-file.txt (128B)17722026/10/01 09:46:22 OK 3_commit_push.sql (1.83ms)17732026/10/01 09:46:22 goose: up to current file version: 317742026/10/01 09:46:22 OK 20251218171726_add_pins.sql (3.98ms)17752026/10/01 09:46:22 INFO Upload complete. (73ms)1776=== NAME TestClientPushesUseOnePush1777 client_pushes_test.go:97: Retrieved narinfo from S3:1778 StorePath: /build/TestClientPushesUseOnePush638496527/001/store/w3xgancr56b2gaygjrc007zsjap2gw7h-shared-dep1779 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1780 Compression: zstd1781 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821782 NarSize: 1361783 References: 1784 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17852026/10/01 09:46:22 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17862026/10/01 09:46:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17872026/10/01 09:46:22 WARN Failed to register uploaded object key=r6pqz4m73fxmid2mxf41vzbgfcnrb8b2.ls error="server returned 404: 404 page not found\n"17882026-10-01 09:46:22.980 UTC [849] ERROR: relation "goose_db_version" does not exist at character 3617892026-10-01 09:46:22.980 UTC [849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17902026/10/01 09:46:22 OK 20260628120000_add_object_size_and_stats.sql (4.64ms)17912026/10/01 09:46:22 INFO Signed narinfos id=1 count=117922026/10/01 09:46:22 INFO Uploading 1 narinfos1793 client_pushes_test.go:97: Retrieved narinfo from S3:1794 StorePath: /build/TestClientPushesUseOnePush638496527/001/store/rp4206gdjs9spp01lrk3zz0rimcx2186-a1795 URL: nar/0p72z78m96ipwcj3kpv3pyj48wfbsmk1n6yjvk3crcz47c63lmk2.nar.zst1796 Compression: zstd1797 NarHash: sha256:0p72z78m96ipwcj3kpv3pyj48wfbsmk1n6yjvk3crcz47c63lmk21798 NarSize: 2081799 References: /build/TestClientPushesUseOnePush638496527/001/store/w3xgancr56b2gaygjrc007zsjap2gw7h-shared-dep1800 CA: text:sha256:1kari0syi56rqhna9rvnnm4psximcldn6w8jnsqnz6kgkw41fmpf18012026/10/01 09:46:22 INFO Received complete push request method=POST path=/api/pushes/1/complete18022026/10/01 09:46:22 WARN Failed to register uploaded object key=r6pqz4m73fxmid2mxf41vzbgfcnrb8b2.narinfo error="server returned 404: 404 page not found\n"18032026/10/01 09:46:22 OK 20260905000000_add_claims.sql (4.7ms)1804 client_pushes_test.go:97: Retrieved narinfo from S3:1805 StorePath: /build/TestClientPushesUseOnePush638496527/001/store/mbyhich4ajsac9rdgvb0wgz58gibs4rv-b1806 URL: nar/0p72z78m96ipwcj3kpv3pyj48wfbsmk1n6yjvk3crcz47c63lmk2.nar.zst1807 Compression: zstd1808 NarHash: sha256:0p72z78m96ipwcj3kpv3pyj48wfbsmk1n6yjvk3crcz47c63lmk21809 NarSize: 2081810 References: /build/TestClientPushesUseOnePush638496527/001/store/w3xgancr56b2gaygjrc007zsjap2gw7h-shared-dep1811 CA: text:sha256:1kari0syi56rqhna9rvnnm4psximcldn6w8jnsqnz6kgkw41fmpf1812--- PASS: TestClientPushesUseOnePush (1.10s)1813=== CONT TestClientWithDependencies1814--- PASS: TestReadProxyConditionalGet (0.72s)1815=== CONT TestClientMultipleUploads18162026/10/01 09:46:22 OK 20260920000000_drop_claims.sql (10.82ms)18172026/10/01 09:46:22 INFO Upload complete. (67ms)18182026/10/01 09:46:22 OK 20260923120000_add_pushes.sql (3.05ms)18192026/10/01 09:46:22 goose: successfully migrated database to version: 2026092312000018202026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.62ms)18212026/10/01 09:46:23 OK 2_object_stats_trigger.sql (2.41ms)18222026/10/01 09:46:23 OK 3_commit_push.sql (1.41ms)18232026/10/01 09:46:23 goose: up to current file version: 318242026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.26ms)18252026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)18262026-10-01 09:46:23.012 UTC [855] ERROR: relation "goose_db_version" does not exist at character 3618272026-10-01 09:46:23.012 UTC [855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18282026-10-01 09:46:23.013 UTC [856] ERROR: relation "goose_db_version" does not exist at character 3618292026-10-01 09:46:23.013 UTC [856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18302026/10/01 09:46:23 OK 20251218171726_add_pins.sql (12.03ms)18312026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (6.06ms)1832--- PASS: TestPushWaitsForSweepHoldingRow (1.81s)1833=== CONT TestClientIntegration1834--- PASS: TestReadProxyHead (0.65s)1835=== CONT TestClientErrorHandling1836=== RUN TestClientErrorHandling/InvalidStorePath1837=== PAUSE TestClientErrorHandling/InvalidStorePath1838=== RUN TestClientErrorHandling/InvalidAuthToken1839=== PAUSE TestClientErrorHandling/InvalidAuthToken1840=== RUN TestClientErrorHandling/ServerNotAvailable1841=== PAUSE TestClientErrorHandling/ServerNotAvailable1842=== CONT TestGCMetrics18432026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.4ms)18442026/10/01 09:46:23 OK 20241026095416_initial_model.sql (11.65ms)18452026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)18462026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.63ms)18472026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.2ms)18482026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)18492026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.29ms)18502026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000018512026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.06ms)18522026/10/01 09:46:23 OK 1_commit_pending_closure.sql (3.4ms)18532026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.08ms)18542026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.56ms)18552026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)18562026/10/01 09:46:23 OK 3_commit_push.sql (1.46ms)18572026/10/01 09:46:23 goose: up to current file version: 318582026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.54ms)18592026-10-01 09:46:23.049 UTC [879] ERROR: relation "goose_db_version" does not exist at character 3618602026-10-01 09:46:23.049 UTC [879] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1861--- PASS: TestReadProxyInvalidPath (0.62s)1862=== CONT TestClientCADerivations18632026/10/01 09:46:23 OK 20260905000000_add_claims.sql (5.13ms)18642026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.19ms)18652026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.14ms)18662026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.62ms)18672026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (3ms)18682026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000018692026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (3.43ms)18702026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000018712026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes18722026/10/01 09:46:23 OK 1_commit_pending_closure.sql (10.91ms)18732026/10/01 09:46:23 OK 1_commit_pending_closure.sql (9.88ms)18742026/10/01 09:46:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18752026/10/01 09:46:23 INFO Uploading 0jgf3bldm8iyrh34cavqwd0gw5i2smfz-unpinned-file.txt (128B)18762026/10/01 09:46:23 OK 20241026095416_initial_model.sql (14.53ms)18772026/10/01 09:46:23 OK 2_object_stats_trigger.sql (2.07ms)18782026/10/01 09:46:23 OK 2_object_stats_trigger.sql (2.15ms)18792026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.33ms)18802026/10/01 09:46:23 OK 3_commit_push.sql (1.9ms)18812026/10/01 09:46:23 goose: up to current file version: 318822026/10/01 09:46:23 OK 3_commit_push.sql (2.16ms)18832026/10/01 09:46:23 goose: up to current file version: 318842026/10/01 09:46:23 WARN Failed to register uploaded object key=0jgf3bldm8iyrh34cavqwd0gw5i2smfz.ls error="server returned 404: 404 page not found\n"18852026/10/01 09:46:23 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18862026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18872026/10/01 09:46:23 INFO Signed narinfos id=2 count=118882026/10/01 09:46:23 INFO Uploading 1 narinfos18892026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.55ms)18902026-10-01 09:46:23.080 UTC [899] ERROR: relation "goose_db_version" does not exist at character 3618912026-10-01 09:46:23.080 UTC [899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18922026-10-01 09:46:23.082 UTC [900] ERROR: relation "goose_db_version" does not exist at character 3618932026-10-01 09:46:23.082 UTC [900] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18942026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.79ms)18952026/10/01 09:46:23 INFO Received complete push request method=POST path=/api/pushes/2/complete18962026/10/01 09:46:23 WARN Failed to register uploaded object key=0jgf3bldm8iyrh34cavqwd0gw5i2smfz.narinfo error="server returned 404: 404 page not found\n"18972026/10/01 09:46:23 INFO Upload complete. (56ms)18982026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.38ms)18992026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.22ms)1900=== RUN TestService_RequireScope_OIDC/builder_may_write1901=== PAUSE TestService_RequireScope_OIDC/builder_may_write1902=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1903=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1904=== RUN TestService_RequireScope_OIDC/ops_may_admin1905=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1906=== RUN TestService_RequireScope_OIDC/ops_may_not_write1907=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1908=== RUN TestService_RequireScope_OIDC/reader_may_not_write1909=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1910=== RUN TestService_RequireScope_OIDC/static_token_may_admin1911=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1912=== RUN TestService_RequireScope_OIDC/static_token_may_write1913=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1914=== RUN TestService_RequireScope_OIDC/reader_may_read1915=== PAUSE TestService_RequireScope_OIDC/reader_may_read1916=== RUN TestService_RequireScope_OIDC/writer_implies_read1917=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1918=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1919=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1920=== CONT TestGCBugBareHashReferences19212026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (3.26ms)19222026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000019232026/10/01 09:46:23 OK 1_commit_pending_closure.sql (4.44ms)19242026/10/01 09:46:23 OK 20241026095416_initial_model.sql (12ms)19252026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.76ms)19262026/10/01 09:46:23 OK 20241026095416_initial_model.sql (12.4ms)19272026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)19282026/10/01 09:46:23 OK 3_commit_push.sql (1.86ms)19292026/10/01 09:46:23 goose: up to current file version: 319302026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)1931--- PASS: TestService_ReadAuthMiddleware (0.65s)1932=== CONT TestPushDedupSurvivesConcurrentGC19332026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.39ms)19342026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.8ms)19352026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.89ms)19362026-10-01 09:46:23.113 UTC [904] ERROR: relation "goose_db_version" does not exist at character 3619372026-10-01 09:46:23.113 UTC [904] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19382026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.3ms)19392026-10-01 09:46:23.114 UTC [905] ERROR: relation "goose_db_version" does not exist at character 3619402026-10-01 09:46:23.114 UTC [905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19412026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.16ms)19422026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.43ms)19432026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.71ms)19442026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.09ms)19452026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.79ms)19462026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000019472026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.4ms)19482026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000019492026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.61ms)19502026/10/01 09:46:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures19512026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.71ms)19522026/10/01 09:46:23 INFO Garbage collection started19532026/10/01 09:46:23 OK 2_object_stats_trigger.sql (2.73ms)19542026/10/01 09:46:23 OK 2_object_stats_trigger.sql (3.1ms)19552026/10/01 09:46:23 OK 3_commit_push.sql (2.56ms)19562026/10/01 09:46:23 goose: up to current file version: 319572026/10/01 09:46:23 OK 3_commit_push.sql (1.52ms)19582026/10/01 09:46:23 goose: up to current file version: 319592026/10/01 09:46:23 OK 20241026095416_initial_model.sql (11.34ms)19602026/10/01 09:46:23 OK 20241026095416_initial_model.sql (12.09ms)19612026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)19622026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)1963=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1964=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1965=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1966=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1967=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1968=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1969=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1970=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1971=== CONT TestResolveDBConnectionString1972=== RUN TestResolveDBConnectionString/flag_wins1973=== PAUSE TestResolveDBConnectionString/flag_wins1974=== RUN TestResolveDBConnectionString/file_when_flag_empty1975=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1976=== RUN TestResolveDBConnectionString/missing_file_is_an_error1977=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1978=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1979=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1980=== RUN TestResolveDBConnectionString/nothing_configured19812026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.37ms)1982=== PAUSE TestResolveDBConnectionString/nothing_configured1983=== CONT TestService_NativeMTLS19842026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.54ms)19852026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=019862026-10-01 09:46:23.142 UTC [927] ERROR: relation "goose_db_version" does not exist at character 3619872026-10-01 09:46:23.142 UTC [927] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19882026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (11.28ms)19892026/10/01 09:46:23 WARN Force mode enabled - objects will be deleted immediately without grace period19902026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (12.17ms)19912026/10/01 09:46:23 OK 20260905000000_add_claims.sql (5.38ms)19922026/10/01 09:46:23 OK 20260905000000_add_claims.sql (8.56ms)19932026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (10.27ms)19942026/10/01 09:46:23 OK 20241026095416_initial_model.sql (17.61ms)19952026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (10.21ms)19962026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (8.01ms)19972026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000019982026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (7.49ms)19992026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000020002026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (8.72ms)2001--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.92s)2002=== CONT TestLeadElectsOneAndHandsOver20032026-10-01 09:46:23.179 UTC [930] ERROR: relation "goose_db_version" does not exist at character 3620042026-10-01 09:46:23.179 UTC [930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20052026/10/01 09:46:23 OK 1_commit_pending_closure.sql (7.8ms)20062026/10/01 09:46:23 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=020072026/10/01 09:46:23 OK 1_commit_pending_closure.sql (10.1ms)20082026/10/01 09:46:23 OK 20251218171726_add_pins.sql (9.7ms)20092026/10/01 09:46:23 OK 2_object_stats_trigger.sql (10.94ms)20102026-10-01 09:46:23.194 UTC [933] ERROR: relation "goose_db_version" does not exist at character 3620112026-10-01 09:46:23.194 UTC [933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20122026/10/01 09:46:23 OK 2_object_stats_trigger.sql (8.42ms)20132026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (8.58ms)20142026/10/01 09:46:23 OK 3_commit_push.sql (8.6ms)20152026/10/01 09:46:23 goose: up to current file version: 320162026/10/01 09:46:23 INFO Vacuumed table table=pending_closures20172026/10/01 09:46:23 OK 3_commit_push.sql (8.97ms)20182026/10/01 09:46:23 goose: up to current file version: 320192026/10/01 09:46:23 OK 20260905000000_add_claims.sql (8.96ms)20202026/10/01 09:46:23 OK 20241026095416_initial_model.sql (15.06ms)20212026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (6.23ms)20222026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (5.29ms)20232026/10/01 09:46:23 INFO Vacuumed table table=pending_objects20242026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads20252026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (3.56ms)20262026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000020272026/10/01 09:46:23 INFO Vacuumed table table=closures20282026/10/01 09:46:23 OK 20251218171726_add_pins.sql (6.47ms)20292026/10/01 09:46:23 OK 20241026095416_initial_model.sql (14.3ms)20302026/10/01 09:46:23 OK 1_commit_pending_closure.sql (5.7ms)20312026/10/01 09:46:23 INFO Vacuumed table table=objects20322026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.77ms)20332026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (3.23ms)20342026-10-01 09:46:23.224 UTC [934] ERROR: relation "goose_db_version" does not exist at character 3620352026-10-01 09:46:23.224 UTC [934] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20362026/10/01 09:46:23 OK 3_commit_push.sql (1.72ms)20372026/10/01 09:46:23 goose: up to current file version: 320382026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.59ms)20392026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.49ms)20402026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.66ms)20412026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.12ms)20422026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.81ms)20432026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.35ms)20442026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000020452026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.56ms)20462026/10/01 09:46:23 OK 1_commit_pending_closure.sql (1.94ms)20472026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (1.94ms)20482026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.25ms)20492026/10/01 09:46:23 OK 20241026095416_initial_model.sql (9.63ms)20502026/10/01 09:46:23 OK 3_commit_push.sql (1.28ms)20512026/10/01 09:46:23 goose: up to current file version: 320522026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (1.96ms)20532026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000020542026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)20552026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.6ms)20562026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.62ms)20572026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.54ms)20582026/10/01 09:46:23 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20592026/10/01 09:46:23 WARN mTLS auth: bound subjects configured but subject DN unavailable20602026/10/01 09:46:23 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2061--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.67s)2062=== CONT TestProxyHeadersOnlyTrustedOnSocket20632026/10/01 09:46:23 OK 3_commit_push.sql (1.62ms)20642026/10/01 09:46:23 goose: up to current file version: 320652026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=020662026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.28ms)20672026/10/01 09:46:23 WARN Force mode enabled - objects will be deleted immediately without grace period20682026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.53ms)20692026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.18ms)20702026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.37ms)20712026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000020722026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.23ms)20732026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.65ms)20742026/10/01 09:46:23 OK 3_commit_push.sql (1.84ms)20752026/10/01 09:46:23 goose: up to current file version: 320762026/10/01 09:46:23 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=020772026/10/01 09:46:23 INFO Vacuumed table table=pending_closures20782026/10/01 09:46:23 INFO Vacuumed table table=pending_objects20792026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads20802026/10/01 09:46:23 INFO Vacuumed table table=closures20812026-10-01 09:46:23.272 UTC [938] ERROR: relation "goose_db_version" does not exist at character 3620822026-10-01 09:46:23.272 UTC [938] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20832026/10/01 09:46:23 INFO Vacuumed table table=objects2084--- PASS: TestGCSweepDeliversEachKeyOnce (0.71s)2085=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock20862026/10/01 09:46:23 INFO Received uploads request method=POST path=/api/pending_closures20872026/10/01 09:46:23 OK 20241026095416_initial_model.sql (14.34ms)2088--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.67s)2089=== CONT TestCreatePendingClosureRejectsOversizedNAR20902026/10/01 09:46:23 INFO Received uploads request method=POST path=/api/pending_closures2091--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2092=== CONT TestParseSingleRange2093=== RUN TestParseSingleRange/none2094=== PAUSE TestParseSingleRange/none2095=== RUN TestParseSingleRange/unknown_unit2096=== PAUSE TestParseSingleRange/unknown_unit2097=== RUN TestParseSingleRange/multi-range_ignored2098=== PAUSE TestParseSingleRange/multi-range_ignored2099=== RUN TestParseSingleRange/malformed_no_dash2100=== PAUSE TestParseSingleRange/malformed_no_dash2101=== RUN TestParseSingleRange/malformed_both_empty2102=== PAUSE TestParseSingleRange/malformed_both_empty2103=== RUN TestParseSingleRange/malformed_end_before_start2104=== PAUSE TestParseSingleRange/malformed_end_before_start2105=== RUN TestParseSingleRange/closed2106=== PAUSE TestParseSingleRange/closed2107=== RUN TestParseSingleRange/open-ended2108=== PAUSE TestParseSingleRange/open-ended2109=== RUN TestParseSingleRange/end_clamped_to_size2110=== PAUSE TestParseSingleRange/end_clamped_to_size2111=== RUN TestParseSingleRange/suffix2112=== PAUSE TestParseSingleRange/suffix2113=== RUN TestParseSingleRange/suffix_exceeds_size2114=== PAUSE TestParseSingleRange/suffix_exceeds_size2115=== RUN TestParseSingleRange/single_byte2116=== PAUSE TestParseSingleRange/single_byte2117=== RUN TestParseSingleRange/start_past_EOF2118=== PAUSE TestParseSingleRange/start_past_EOF2119=== RUN TestParseSingleRange/start_far_past_EOF2120=== PAUSE TestParseSingleRange/start_far_past_EOF2121=== CONT TestGCTaskStore_Fail2122--- PASS: TestGCTaskStore_Fail (0.00s)2123=== CONT TestMetricsInventory21242026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)21252026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.09ms)21262026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.82ms)2127--- PASS: TestReadProxy404 (0.66s)2128=== CONT TestPresentNotReportedWhileGCDeletesClosure21292026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.54ms)21302026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.19ms)21312026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.55ms)21322026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000021332026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.64ms)21342026/10/01 09:46:23 OK 2_object_stats_trigger.sql (2.23ms)21352026/10/01 09:46:23 OK 3_commit_push.sql (1.39ms)21362026/10/01 09:46:23 goose: up to current file version: 321372026-10-01 09:46:23.324 UTC [945] ERROR: relation "goose_db_version" does not exist at character 3621382026-10-01 09:46:23.324 UTC [945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21392026/10/01 09:46:23 INFO Received uploads request method=POST path=/api/pending_closures21402026/10/01 09:46:23 OK 20241026095416_initial_model.sql (9.23ms)21412026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)21422026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.46ms)21432026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)21442026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=021452026-10-01 09:46:23.356 UTC [947] ERROR: relation "goose_db_version" does not exist at character 3621462026-10-01 09:46:23.356 UTC [947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21472026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.81ms)21482026/10/01 09:46:23 WARN Force mode enabled - objects will be deleted immediately without grace period21492026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.17ms)21502026/10/01 09:46:23 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=021512026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.49ms)21522026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000021532026/10/01 09:46:23 INFO Vacuumed table table=pending_closures21542026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.19ms)21552026/10/01 09:46:23 INFO Vacuumed table table=pending_objects21562026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads21572026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.83ms)21582026/10/01 09:46:23 INFO Vacuumed table table=closures2159--- PASS: TestReadProxyNarStreaming (0.65s)2160=== CONT TestService_healthCheckHandler21612026/10/01 09:46:23 OK 3_commit_push.sql (1.03ms)21622026/10/01 09:46:23 goose: up to current file version: 321632026/10/01 09:46:23 INFO Vacuumed table table=objects21642026/10/01 09:46:23 OK 20241026095416_initial_model.sql (9.54ms)21652026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.72ms)21662026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.77ms)2167--- PASS: TestGCSweepSkipsPendingObjects (0.72s)2168=== CONT TestService_readinessHandler21692026-10-01 09:46:23.379 UTC [949] ERROR: relation "goose_db_version" does not exist at character 3621702026-10-01 09:46:23.379 UTC [949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21712026-10-01 09:46:23.383 UTC [951] ERROR: relation "goose_db_version" does not exist at character 3621722026-10-01 09:46:23.383 UTC [951] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21732026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (13.33ms)21742026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.7ms)2175--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.56s)2176=== CONT TestGracefulShutdownDrainsInflight21772026/10/01 09:46:23 INFO Starting HTTP server address=127.0.0.1:3531721782026/10/01 09:46:23 INFO Shutdown signal received, draining in-flight requests timeout=10s21792026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.09ms)21802026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.45ms)21812026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000021822026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.78ms)21832026/10/01 09:46:23 OK 20241026095416_initial_model.sql (11.41ms)21842026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.95ms)21852026/10/01 09:46:23 OK 20241026095416_initial_model.sql (12.3ms)21862026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)21872026/10/01 09:46:23 OK 3_commit_push.sql (1.23ms)21882026/10/01 09:46:23 goose: up to current file version: 321892026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)21902026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.91ms)21912026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.78ms)21922026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)21932026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.26ms)2194--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.59s)2195=== CONT TestNARDeduplicationMetadataUploadBug21962026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.51ms)21972026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.63ms)21982026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.51ms)21992026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.46ms)22002026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000022012026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.64ms)22022026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.18ms)22032026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000022042026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.8ms)22052026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.42ms)22062026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.59ms)22072026/10/01 09:46:23 OK 3_commit_push.sql (1.17ms)22082026/10/01 09:46:23 goose: up to current file version: 322092026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.26ms)22102026/10/01 09:46:23 OK 3_commit_push.sql (2.01ms)22112026/10/01 09:46:23 goose: up to current file version: 322122026-10-01 09:46:23.440 UTC [956] ERROR: relation "goose_db_version" does not exist at character 3622132026-10-01 09:46:23.440 UTC [956] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22142026/10/01 09:46:23 INFO Received uploads request method=POST path=/api/pending_closures2215--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.58s)2216=== CONT TestCacheConfigHandlerMaxNarSize2217--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)2218=== CONT TestObjectStatsTrigger22192026/10/01 09:46:23 OK 20241026095416_initial_model.sql (9.42ms)22202026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)22212026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.52ms)22222026-10-01 09:46:23.463 UTC [959] ERROR: relation "goose_db_version" does not exist at character 3622232026-10-01 09:46:23.463 UTC [959] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2224--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2225=== CONT TestGenerateLandingPage22262026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.32ms)2227--- PASS: TestGenerateLandingPage (0.00s)2228=== CONT TestCreatePin_ReservedPins22292026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.86ms)2230--- PASS: TestReadProxyNarinfo (0.58s)2231=== CONT TestGCTaskStore_CompletedAllowsNewTask2232--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)2233=== CONT TestOrphanedObjectsGCStressTest22342026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.48ms)22352026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.79ms)22362026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000022372026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.35ms)22382026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.55ms)22392026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.01ms)22402026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)22412026/10/01 09:46:23 OK 3_commit_push.sql (1.25ms)22422026/10/01 09:46:23 goose: up to current file version: 322432026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.35ms)22442026-10-01 09:46:23.490 UTC [962] ERROR: relation "goose_db_version" does not exist at character 3622452026-10-01 09:46:23.490 UTC [962] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22462026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (6.27ms)22472026/10/01 09:46:23 OK 20260905000000_add_claims.sql (12.34ms)22482026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.36ms)22492026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.46ms)22502026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000022512026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.57ms)2252--- PASS: TestCacheStatsHandler (0.59s)2253=== CONT TestGCTaskStore_PhaseUpdates2254--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)2255=== CONT TestOrphanedObjectsGC22562026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.72ms)22572026/10/01 09:46:23 OK 3_commit_push.sql (1.46ms)22582026/10/01 09:46:23 goose: up to current file version: 322592026/10/01 09:46:23 OK 20241026095416_initial_model.sql (12.51ms)22602026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)22612026/10/01 09:46:23 INFO lead: acquired remote=192.0.2.1:123422622026/10/01 09:46:23 INFO lead: released remote=192.0.2.1:12342263--- PASS: TestLeadEndsOnShutdown (0.59s)2264=== CONT TestIsValidCachePath2265=== RUN TestIsValidCachePath/narinfo2266=== PAUSE TestIsValidCachePath/narinfo2267=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2268=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2269=== RUN TestIsValidCachePath/nar_zst22702026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.45ms)2271=== PAUSE TestIsValidCachePath/nar_zst2272=== RUN TestIsValidCachePath/nar_xz2273=== PAUSE TestIsValidCachePath/nar_xz2274=== RUN TestIsValidCachePath/nar_bz22275=== PAUSE TestIsValidCachePath/nar_bz22276=== RUN TestIsValidCachePath/nar_uncompressed2277=== PAUSE TestIsValidCachePath/nar_uncompressed2278=== RUN TestIsValidCachePath/ls2279=== PAUSE TestIsValidCachePath/ls2280=== RUN TestIsValidCachePath/log2281=== PAUSE TestIsValidCachePath/log2282=== RUN TestIsValidCachePath/realisation2283=== PAUSE TestIsValidCachePath/realisation2284=== RUN TestIsValidCachePath/nix-cache-info2285=== PAUSE TestIsValidCachePath/nix-cache-info2286=== RUN TestIsValidCachePath/index.html2287=== PAUSE TestIsValidCachePath/index.html2288=== RUN TestIsValidCachePath/traversal_parent2289=== PAUSE TestIsValidCachePath/traversal_parent2290=== RUN TestIsValidCachePath/traversal_in_middle2291=== PAUSE TestIsValidCachePath/traversal_in_middle2292=== RUN TestIsValidCachePath/invalid_char_e2293=== PAUSE TestIsValidCachePath/invalid_char_e2294=== RUN TestIsValidCachePath/invalid_char_u2295=== PAUSE TestIsValidCachePath/invalid_char_u2296=== RUN TestIsValidCachePath/random_path2297=== PAUSE TestIsValidCachePath/random_path2298=== RUN TestIsValidCachePath/empty2299=== PAUSE TestIsValidCachePath/empty2300=== RUN TestIsValidCachePath/leading_slash2301=== PAUSE TestIsValidCachePath/leading_slash2302=== RUN TestIsValidCachePath/wrong_extension2303=== PAUSE TestIsValidCachePath/wrong_extension2304=== RUN TestIsValidCachePath/short_hash2305=== PAUSE TestIsValidCachePath/short_hash2306=== CONT TestGCTaskStore_GetReturnsLatest2307--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)2308=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded23092026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.32ms)23102026-10-01 09:46:23.532 UTC [966] ERROR: relation "goose_db_version" does not exist at character 3623112026-10-01 09:46:23.532 UTC [966] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23122026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.45ms)23132026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.21ms)23142026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (4.08ms)23152026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000023162026/10/01 09:46:23 OK 1_commit_pending_closure.sql (3.02ms)23172026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.38ms)23182026/10/01 09:46:23 OK 3_commit_push.sql (1.74ms)23192026/10/01 09:46:23 goose: up to current file version: 323202026/10/01 09:46:23 OK 20241026095416_initial_model.sql (9.87ms)23212026-10-01 09:46:23.550 UTC [968] ERROR: relation "goose_db_version" does not exist at character 3623222026-10-01 09:46:23.550 UTC [968] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23232026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)23242026/10/01 09:46:23 OK 20251218171726_add_pins.sql (5.12ms)23252026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)23262026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.13ms)23272026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.25ms)23282026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.02ms)23292026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)23302026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.71ms)23312026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000023322026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.65ms)23332026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.5ms)23342026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.33ms)23352026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)23362026/10/01 09:46:23 OK 3_commit_push.sql (1.35ms)23372026/10/01 09:46:23 goose: up to current file version: 323382026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.63ms)23392026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.61ms)23402026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.03ms)23412026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000023422026/10/01 09:46:23 OK 1_commit_pending_closure.sql (1.93ms)23432026/10/01 09:46:23 OK 2_object_stats_trigger.sql (845.21µs)23442026-10-01 09:46:23.589 UTC [970] ERROR: relation "goose_db_version" does not exist at character 3623452026-10-01 09:46:23.589 UTC [970] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23462026/10/01 09:46:23 OK 3_commit_push.sql (1.01ms)23472026/10/01 09:46:23 goose: up to current file version: 323482026-10-01 09:46:23.597 UTC [988] ERROR: relation "goose_db_version" does not exist at character 3623492026-10-01 09:46:23.597 UTC [988] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23502026/10/01 09:46:23 OK 20241026095416_initial_model.sql (11.08ms)23512026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)23522026/10/01 09:46:23 OK 20241026095416_initial_model.sql (8.86ms)23532026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.25ms)23542026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.46ms)23552026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (3.95ms)23562026/10/01 09:46:23 OK 20251218171726_add_pins.sql (2.89ms)2357=== NAME TestClientMultipleUploads2358 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3698228603/001/store/42y1zcxn6bpgnmhm6sdckrxr1x2x0n3w-test-file-0.txt23592026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.09ms)23602026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (2.88ms)23612026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.22ms)23622026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.53ms)23632026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (1.79ms)23642026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000023652026/10/01 09:46:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43995/oidc23662026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.1ms)23672026/10/01 09:46:23 OK 1_commit_pending_closure.sql (1.85ms)23682026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.24ms)23692026/10/01 09:46:23 OK 3_commit_push.sql (734.39µs)23702026/10/01 09:46:23 goose: up to current file version: 323712026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.67ms)23722026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000023732026/10/01 09:46:23 OK 1_commit_pending_closure.sql (1.9ms)23742026/10/01 09:46:23 OK 2_object_stats_trigger.sql (989.85µs)23752026/10/01 09:46:23 OK 3_commit_push.sql (732.71µs)23762026/10/01 09:46:23 goose: up to current file version: 32377 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3698228603/001/store/zal0437dlq75d78lzw25mmszpsfgdpyc-test-file-1.txt23782026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=023792026/10/01 09:46:23 WARN Force mode enabled - objects will be deleted immediately without grace period2380=== NAME TestClientIntegration2381 client_integration_test.go:286: Created store path: /build/TestClientIntegration1704530151/002/store/myvpqf1fb1pf23lxgbxxgfqsiw1cn483-test-file.txt23822026/10/01 09:46:23 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=023832026/10/01 09:46:23 INFO Vacuumed table table=pending_closures23842026/10/01 09:46:23 INFO Vacuumed table table=pending_objects23852026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads23862026/10/01 09:46:23 INFO Vacuumed table table=closures23872026/10/01 09:46:23 INFO Vacuumed table table=objects2388--- PASS: TestGCMetrics (0.64s)2389=== CONT TestMultipartCleanup2390=== NAME TestClientWithDependencies2391 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3434989046/001/store/8qnfxad8alhy5qj6ky787xvky1h6r72f-test-script2392=== NAME TestClientMultipleUploads2393 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3698228603/001/store/6ipnsb16zfm1bb0156l6ic1bisjqfdiw-test-file-2.txt23942026-10-01 09:46:23.694 UTC [1152] ERROR: relation "goose_db_version" does not exist at character 3623952026-10-01 09:46:23.694 UTC [1152] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23962026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes23972026/10/01 09:46:23 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)23982026/10/01 09:46:23 INFO Uploading knk3h0zrlc75a60qmwdr65xbq5rhv7xh-top (224B)23992026/10/01 09:46:23 INFO Uploading pcfhby5q8yvgnfa1zrj8jmxh0s7wvjjl-shared-dep (136B)24002026/10/01 09:46:23 WARN Failed to register uploaded object key=pcfhby5q8yvgnfa1zrj8jmxh0s7wvjjl.ls error="server returned 404: 404 page not found\n"24012026/10/01 09:46:23 WARN Failed to register uploaded object key=knk3h0zrlc75a60qmwdr65xbq5rhv7xh.ls error="server returned 404: 404 page not found\n"24022026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/1ygkxq649v34s419sbkx73xj93zdps5diara53rlf54pannxka5z.nar.zst error="server returned 404: 404 page not found\n"24032026/10/01 09:46:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24042026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24052026/10/01 09:46:23 INFO Signed narinfos id=1 count=224062026/10/01 09:46:23 INFO Uploading 2 narinfos24072026/10/01 09:46:23 OK 20241026095416_initial_model.sql (9.08ms)24082026/10/01 09:46:23 INFO Received complete push request method=POST path=/api/pushes/1/complete24092026/10/01 09:46:23 WARN Failed to register uploaded object key=knk3h0zrlc75a60qmwdr65xbq5rhv7xh.narinfo error="server returned 404: 404 page not found\n"24102026/10/01 09:46:23 WARN Failed to register uploaded object key=pcfhby5q8yvgnfa1zrj8jmxh0s7wvjjl.narinfo error="server returned 404: 404 page not found\n"24112026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)24122026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.31ms)2413=== NAME TestClientWithDependencies2414 client_integration_test.go:615: Found 1 dependencies (including self)24152026/10/01 09:46:23 INFO Upload complete. (60ms)24162026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)2417=== NAME TestClientSharedPathCommittedMidPush2418 client_integration_test.go:680: Retrieved narinfo from S3:2419 StorePath: /build/TestClientSharedPathCommittedMidPush2566484289/001/store/pcfhby5q8yvgnfa1zrj8jmxh0s7wvjjl-shared-dep2420 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2421 Compression: zstd2422 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822423 NarSize: 1362424 References: 2425 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n24262026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.5ms)2427 client_integration_test.go:680: Retrieved narinfo from S3:2428 StorePath: /build/TestClientSharedPathCommittedMidPush2566484289/001/store/knk3h0zrlc75a60qmwdr65xbq5rhv7xh-top2429 URL: nar/1ygkxq649v34s419sbkx73xj93zdps5diara53rlf54pannxka5z.nar.zst2430 Compression: zstd2431 NarHash: sha256:1ygkxq649v34s419sbkx73xj93zdps5diara53rlf54pannxka5z2432 NarSize: 2242433 References: /build/TestClientSharedPathCommittedMidPush2566484289/001/store/pcfhby5q8yvgnfa1zrj8jmxh0s7wvjjl-shared-dep2434 CA: text:sha256:1p7grngqlfzhbmcwzk1pxqk52p7kcj738hf9czjk4zjzx47j006f24352026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (3.02ms)2436--- PASS: TestClientSharedPathCommittedMidPush (0.76s)2437=== CONT TestPendingCleanupUsesOneCutoff24382026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (2.34ms)24392026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000024402026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes24412026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.68ms)24422026/10/01 09:46:23 OK 2_object_stats_trigger.sql (968.15µs)24432026/10/01 09:46:23 INFO Received uploads request method=POST path=/api/pending_closures24442026/10/01 09:46:23 OK 3_commit_push.sql (1.1ms)24452026/10/01 09:46:23 goose: up to current file version: 324462026/10/01 09:46:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24472026/10/01 09:46:23 INFO Uploading myvpqf1fb1pf23lxgbxxgfqsiw1cn483-test-file.txt (152B)24482026/10/01 09:46:23 WARN mTLS auth: subject not in bound subjects subject="CN=reader"24492026/10/01 09:46:23 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2450--- PASS: TestService_NativeMTLS (0.60s)2451=== CONT TestServerTLSConfig2452=== RUN TestServerTLSConfig/no_client_CA2453=== PAUSE TestServerTLSConfig/no_client_CA2454=== RUN TestServerTLSConfig/missing_CA_file2455=== PAUSE TestServerTLSConfig/missing_CA_file2456=== RUN TestServerTLSConfig/not_a_PEM_file2457=== PAUSE TestServerTLSConfig/not_a_PEM_file2458=== CONT TestPresentReportsOnlyClosureRoots24592026-10-01 09:46:23.738 UTC [1244] ERROR: relation "goose_db_version" does not exist at character 3624602026-10-01 09:46:23.738 UTC [1244] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24612026/10/01 09:46:23 WARN Failed to register uploaded object key=myvpqf1fb1pf23lxgbxxgfqsiw1cn483.ls error="server returned 404: 404 page not found\n"24622026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"24632026/10/01 09:46:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24642026/10/01 09:46:23 INFO Signed narinfos id=1 count=124652026/10/01 09:46:23 INFO Uploading 1 narinfos24662026/10/01 09:46:23 INFO Received complete push request method=POST path=/api/pushes/1/complete24672026/10/01 09:46:23 WARN Failed to register uploaded object key=myvpqf1fb1pf23lxgbxxgfqsiw1cn483.narinfo error="server returned 404: 404 page not found\n"24682026/10/01 09:46:23 INFO Upload complete. (61ms)24692026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.95ms)2470=== NAME TestClientCADerivations2471 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2335694667/001/store/c3m2hsk0vy0nrf17h4m0sh629h2fjzdm-ca-test24722026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)24732026/10/01 09:46:23 INFO lead: acquired remote=192.0.2.1:123424742026/10/01 09:46:23 OK 20251218171726_add_pins.sql (4.26ms)24752026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes24762026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (6.31ms)24772026/10/01 09:46:23 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)24782026/10/01 09:46:23 INFO Uploading 42y1zcxn6bpgnmhm6sdckrxr1x2x0n3w-test-file-0.txt (160B)24792026/10/01 09:46:23 INFO Uploading zal0437dlq75d78lzw25mmszpsfgdpyc-test-file-1.txt (160B)24802026/10/01 09:46:23 INFO Uploading 6ipnsb16zfm1bb0156l6ic1bisjqfdiw-test-file-2.txt (160B)24812026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.82ms)24822026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (9.7ms)24832026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"24842026/10/01 09:46:23 WARN Failed to register uploaded object key=42y1zcxn6bpgnmhm6sdckrxr1x2x0n3w.ls error="server returned 404: 404 page not found\n"24852026/10/01 09:46:23 WARN Failed to register uploaded object key=zal0437dlq75d78lzw25mmszpsfgdpyc.ls error="server returned 404: 404 page not found\n"24862026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"24872026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"24882026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (3.15ms)24892026/10/01 09:46:23 goose: successfully migrated database to version: 202609231200002490 client_ca_test.go:139: Found 1 dependencies (including self)24912026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.62ms)24922026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes24932026/10/01 09:46:23 OK 2_object_stats_trigger.sql (2.82ms)24942026/10/01 09:46:23 INFO Starting HTTP server address=127.0.0.1:4215724952026/10/01 09:46:23 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3127497500/001/proxy.sock24962026/10/01 09:46:23 WARN mTLS auth: subject not in bound subjects subject="CN=someone"24972026/10/01 09:46:23 INFO Shutdown signal received, draining in-flight requests timeout=10s2498--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.55s)2499=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info25002026/10/01 09:46:23 INFO Received uploads request method=POST path=/2501=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key25022026/10/01 09:46:23 INFO Received request for more parts method=POST path=/2503=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal25042026/10/01 09:46:23 INFO Received uploads request method=POST path=/2505=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key25062026/10/01 09:46:23 INFO Received complete multipart upload request method=POST path=/2507--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2508 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2509 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2510 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2511 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2512=== CONT TestIsValidUploadKey/narinfo2513=== CONT TestIsValidUploadKey/realisation_plus_in_output2514=== CONT TestIsValidUploadKey/unknown_type2515=== CONT TestIsValidUploadKey/empty_key2516=== CONT TestIsValidUploadKey/absolute2517=== CONT TestIsValidUploadKey/traversal_nar2518=== CONT TestIsValidUploadKey/traversal2519=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2520=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2521=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2522=== CONT TestIsValidUploadKey/index.html2523=== CONT TestIsValidUploadKey/nix-cache-info2524=== CONT TestIsValidUploadKey/build_log_equals2525=== CONT TestIsValidUploadKey/realisation2526=== CONT TestIsValidUploadKey/nar_plain2527=== CONT TestIsValidUploadKey/build_log_home-manager_file2528=== CONT TestIsValidUploadKey/build_log2529=== CONT TestIsValidUploadKey/build_log_question_mark2530=== CONT TestIsValidUploadKey/listing2531=== CONT TestIsValidUploadKey/build_log_plus_in_name2532=== CONT TestIsValidUploadKey/nar_xz2533=== CONT TestIsValidUploadKey/nar_zst2534=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure25352026/10/01 09:46:23 INFO Received uploads request method=POST path=/2536--- PASS: TestIsValidUploadKey (0.06s)2537 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2538 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2539 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2540 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2541 --- PASS: TestIsValidUploadKey/absolute (0.00s)2542 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2543 --- PASS: TestIsValidUploadKey/traversal (0.00s)2544 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2545 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2546 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2547 --- PASS: TestIsValidUploadKey/index.html (0.00s)2548 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2549 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2550 --- PASS: TestIsValidUploadKey/realisation (0.00s)2551 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2552 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2553 --- PASS: TestIsValidUploadKey/build_log (0.00s)2554 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2555 --- PASS: TestIsValidUploadKey/listing (0.00s)2556 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2557 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2558 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)25592026/10/01 09:46:23 INFO All 1 paths already cached25602026/10/01 09:46:23 OK 3_commit_push.sql (9.79ms)25612026/10/01 09:46:23 goose: up to current file version: 32562=== NAME TestClientIntegration2563 client_integration_test.go:312: Retrieved narinfo from S3:2564 StorePath: /build/TestClientIntegration1704530151/002/store/myvpqf1fb1pf23lxgbxxgfqsiw1cn483-test-file.txt2565 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2566 Compression: zstd2567 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12568 NarSize: 1522569 References: 2570 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk125712026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=025722026/10/01 09:46:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25732026/10/01 09:46:23 INFO Uploading 8qnfxad8alhy5qj6ky787xvky1h6r72f-test-script (136B)25742026/10/01 09:46:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25752026/10/01 09:46:23 WARN Failed to register uploaded object key=6ipnsb16zfm1bb0156l6ic1bisjqfdiw.ls error="server returned 404: 404 page not found\n"25762026/10/01 09:46:23 INFO Signed narinfos id=1 count=325772026/10/01 09:46:23 INFO Uploading 3 narinfos2578 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2579 client_integration_test.go:313: Decompressed .ls content (64 bytes):2580 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2581 client_integration_test.go:316: Testing garbage collection...25822026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"25832026/10/01 09:46:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25842026/10/01 09:46:23 WARN Failed to register uploaded object key=log/6nrn0zsq05yljgndb9xw14x6psx42f9g-test-script.drv error="server returned 404: 404 page not found\n"25852026/10/01 09:46:23 WARN Failed to register uploaded object key=8qnfxad8alhy5qj6ky787xvky1h6r72f.ls error="server returned 404: 404 page not found\n"25862026/10/01 09:46:23 WARN Failed to register uploaded object key=6ipnsb16zfm1bb0156l6ic1bisjqfdiw.narinfo error="server returned 404: 404 page not found\n"25872026/10/01 09:46:23 INFO Signed narinfos id=1 count=125882026/10/01 09:46:23 WARN Failed to register uploaded object key=zal0437dlq75d78lzw25mmszpsfgdpyc.narinfo error="server returned 404: 404 page not found\n"25892026/10/01 09:46:23 INFO Uploading 1 narinfos25902026/10/01 09:46:23 INFO Received complete push request method=POST path=/api/pushes/1/complete25912026/10/01 09:46:23 WARN Failed to register uploaded object key=42y1zcxn6bpgnmhm6sdckrxr1x2x0n3w.narinfo error="server returned 404: 404 page not found\n"25922026-10-01 09:46:23.812 UTC [1357] ERROR: relation "goose_db_version" does not exist at character 3625932026-10-01 09:46:23.812 UTC [1357] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25942026/10/01 09:46:23 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=025952026-10-01 09:46:23.813 UTC [1358] ERROR: relation "goose_db_version" does not exist at character 3625962026-10-01 09:46:23.813 UTC [1358] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25972026/10/01 09:46:23 INFO Received complete push request method=POST path=/api/pushes/1/complete25982026/10/01 09:46:23 WARN Failed to register uploaded object key=8qnfxad8alhy5qj6ky787xvky1h6r72f.narinfo error="server returned 404: 404 page not found\n"25992026/10/01 09:46:23 INFO Vacuumed table table=pending_closures26002026/10/01 09:46:23 INFO Vacuumed table table=pending_objects26012026/10/01 09:46:23 INFO Upload complete. (93ms)2602=== NAME TestClientMultipleUploads2603 client_integration_test.go:369: Uploaded 3 paths in 125.319989ms26042026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads26052026/10/01 09:46:23 INFO Vacuumed table table=closures26062026/10/01 09:46:23 INFO Upload complete. (70ms)26072026/10/01 09:46:23 INFO Vacuumed table table=objects2608=== NAME TestClientWithDependencies2609 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3434989046/001/store) requires matching store prefix26102026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.26ms)2611--- PASS: TestClientMultipleUploads (0.83s)26122026/10/01 09:46:23 OK 20241026095416_initial_model.sql (10.12ms)2613=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts26142026/10/01 09:46:23 INFO Received request for more parts method=POST path=/2615--- PASS: TestClientWithDependencies (0.84s)26162026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=02617=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart26182026/10/01 09:46:23 INFO Received complete multipart upload request method=POST path=/26192026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.72ms)26202026/10/01 09:46:23 WARN Force mode enabled - objects will be deleted immediately without grace period26212026/10/01 09:46:23 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)26222026/10/01 09:46:23 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=026232026/10/01 09:46:23 OK 20251218171726_add_pins.sql (2.8ms)26242026/10/01 09:46:23 OK 20251218171726_add_pins.sql (3.57ms)26252026/10/01 09:46:23 INFO Vacuumed table table=pending_closures26262026/10/01 09:46:23 INFO Vacuumed table table=pending_objects26272026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads26282026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)26292026/10/01 09:46:23 OK 20260628120000_add_object_size_and_stats.sql (3.48ms)26302026/10/01 09:46:23 INFO Vacuumed table table=closures26312026/10/01 09:46:23 OK 20260905000000_add_claims.sql (3.61ms)26322026/10/01 09:46:23 OK 20260905000000_add_claims.sql (4.68ms)26332026/10/01 09:46:23 INFO Vacuumed table table=objects2634--- PASS: TestPushDedupSurvivesConcurrentGC (0.74s)2635=== CONT TestProxyWriteTimeout/narinfo2636=== CONT TestProxyWriteTimeout/10_GiB_nar2637=== CONT TestProxyWriteTimeout/unknown_size2638=== CONT TestProxyWriteTimeout/1_GiB_nar2639--- PASS: TestProxyWriteTimeout (0.00s)2640 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2641 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2642 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2643 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2644=== CONT TestPush_RejectsBadRequests/no_roots26452026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes2646=== CONT TestPush_RejectsBadRequests/bad_root26472026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes26482026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.85ms)2649=== CONT TestPush_RejectsBadRequests/root_not_in_objects26502026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes2651=== CONT TestPush_RejectsBadRequests/no_objects26522026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes2653--- PASS: TestPush_RejectsBadRequests (0.80s)2654 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2655 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2656 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2657 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2658=== CONT TestCacheConfigHandler/full_config,_no_issuer2659=== CONT TestCacheConfigHandler/no_signing_keys2660=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2661=== CONT TestCacheConfigHandler/no_cache_url_configured2662--- PASS: TestCacheConfigHandler (0.00s)2663 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2664 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2665 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2666 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2667=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows26682026/10/01 09:46:23 OK 20260920000000_drop_claims.sql (2.88ms)26692026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (6.16ms)26702026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000026712026/10/01 09:46:23 OK 20260923120000_add_pushes.sql (7.23ms)26722026/10/01 09:46:23 goose: successfully migrated database to version: 2026092312000026732026/10/01 09:46:23 OK 1_commit_pending_closure.sql (2.37ms)26742026/10/01 09:46:23 OK 2_object_stats_trigger.sql (956.39µs)26752026/10/01 09:46:23 OK 1_commit_pending_closure.sql (3.17ms)26762026/10/01 09:46:23 OK 3_commit_push.sql (606.01µs)26772026/10/01 09:46:23 goose: up to current file version: 326782026/10/01 09:46:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures26792026/10/01 09:46:23 INFO Garbage collection started26802026/10/01 09:46:23 OK 2_object_stats_trigger.sql (1.06ms)26812026/10/01 09:46:23 OK 3_commit_push.sql (1.19ms)26822026/10/01 09:46:23 goose: up to current file version: 326832026/10/01 09:46:23 INFO Aborted multipart uploads count=0 kept=02684--- PASS: TestMetricsInventory (0.57s)2685=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check26862026/10/01 09:46:23 WARN Force mode enabled - objects will be deleted immediately without grace period2687=== CONT TestClientErrorHandling/InvalidStorePath2688=== CONT TestClientErrorHandling/ServerNotAvailable26892026/10/01 09:46:23 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=026902026/10/01 09:46:23 INFO Vacuumed table table=pending_closures26912026/10/01 09:46:23 INFO Received push request method=POST path=/api/pushes26922026/10/01 09:46:23 INFO Vacuumed table table=pending_objects26932026/10/01 09:46:23 INFO Vacuumed table table=multipart_uploads26942026/10/01 09:46:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26952026/10/01 09:46:23 INFO Uploading c3m2hsk0vy0nrf17h4m0sh629h2fjzdm-ca-test (144B)26962026/10/01 09:46:23 INFO Vacuumed table table=closures26972026/10/01 09:46:23 INFO Vacuumed table table=objects26982026/10/01 09:46:23 WARN Failed to register uploaded object key=c3m2hsk0vy0nrf17h4m0sh629h2fjzdm.ls error="server returned 404: 404 page not found\n"26992026/10/01 09:46:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27002026/10/01 09:46:23 WARN Failed to register uploaded object key=log/blx5y6h6w55w3kicx72vsg5hqfx5451j-ca-test.drv error="server returned 404: 404 page not found\n"27012026/10/01 09:46:23 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"27022026/10/01 09:46:23 INFO Signed narinfos id=1 count=127032026/10/01 09:46:23 INFO Uploading 1 narinfos2704--- PASS: TestService_healthCheckHandler (0.54s)2705=== CONT TestClientErrorHandling/InvalidAuthToken27062026/10/01 09:46:23 INFO Received complete push request method=POST path=/api/pushes/1/complete27072026/10/01 09:46:23 WARN Failed to register uploaded object key=c3m2hsk0vy0nrf17h4m0sh629h2fjzdm.narinfo error="server returned 404: 404 page not found\n"2708--- PASS: TestGCBugBareHashReferences (0.82s)2709=== CONT TestService_RequireScope_OIDC/builder_may_write2710=== CONT TestService_RequireScope_OIDC/writer_implies_read27112026/10/01 09:46:23 INFO lead: released remote=192.0.2.1:12342712=== CONT TestService_RequireScope_OIDC/reader_may_read2713=== CONT TestService_RequireScope_OIDC/static_token_may_write2714=== CONT TestService_RequireScope_OIDC/static_token_may_admin2715=== CONT TestService_RequireScope_OIDC/reader_may_not_write2716=== CONT TestService_RequireScope_OIDC/ops_may_not_write2717=== CONT TestService_RequireScope_OIDC/ops_may_admin2718=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2719=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2720=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2721--- PASS: TestService_RequireScope_OIDC (0.73s)2722 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2723 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2724 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2725 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2726 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2727 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2728 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2729 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2730 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2731 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)27322026/10/01 09:46:23 INFO Upload complete. (94ms)2733=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected27342026/10/01 09:46:23 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]2735=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2736=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected27372026/10/01 09:46:23 WARN Authentication failed token_preview=eyJhbGciOi...wBiT_EA8uA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2738=== CONT TestResolveDBConnectionString/flag_wins2739=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2740=== CONT TestResolveDBConnectionString/nothing_configured2741=== CONT TestResolveDBConnectionString/missing_file_is_an_error2742=== CONT TestResolveDBConnectionString/file_when_flag_empty2743--- PASS: TestService_AuthMiddleware_OIDC (0.72s)2744 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2745 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2746 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2747 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2748=== CONT TestParseSingleRange/none2749=== CONT TestParseSingleRange/open-ended2750=== CONT TestParseSingleRange/suffix_exceeds_size2751=== CONT TestParseSingleRange/suffix2752=== CONT TestParseSingleRange/end_clamped_to_size2753=== CONT TestParseSingleRange/malformed_both_empty2754=== CONT TestParseSingleRange/single_byte2755=== CONT TestParseSingleRange/closed2756=== CONT TestParseSingleRange/start_far_past_EOF2757=== CONT TestParseSingleRange/start_past_EOF2758=== CONT TestParseSingleRange/malformed_end_before_start2759=== CONT TestParseSingleRange/multi-range_ignored2760=== CONT TestParseSingleRange/malformed_no_dash2761=== CONT TestParseSingleRange/unknown_unit2762--- PASS: TestParseSingleRange (0.00s)2763 --- PASS: TestParseSingleRange/none (0.00s)2764 --- PASS: TestParseSingleRange/open-ended (0.00s)2765 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2766 --- PASS: TestParseSingleRange/suffix (0.00s)2767 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2768 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2769 --- PASS: TestParseSingleRange/single_byte (0.00s)2770 --- PASS: TestParseSingleRange/closed (0.00s)2771 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2772 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2773 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2774 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2775 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2776 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2777=== CONT TestIsValidCachePath/narinfo2778=== CONT TestIsValidCachePath/index.html2779=== CONT TestIsValidCachePath/short_hash2780=== CONT TestIsValidCachePath/nar_uncompressed2781--- PASS: TestResolveDBConnectionString (0.00s)2782 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2783 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2784 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2785 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2786 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2787=== CONT TestIsValidCachePath/wrong_extension2788=== CONT TestIsValidCachePath/nix-cache-info2789=== CONT TestIsValidCachePath/leading_slash2790=== CONT TestIsValidCachePath/empty2791=== CONT TestIsValidCachePath/realisation2792=== CONT TestIsValidCachePath/random_path2793=== CONT TestIsValidCachePath/log2794=== CONT TestIsValidCachePath/invalid_char_u2795=== CONT TestIsValidCachePath/ls2796=== CONT TestIsValidCachePath/invalid_char_e2797=== CONT TestIsValidCachePath/nar_zst2798=== CONT TestIsValidCachePath/traversal_in_middle2799=== CONT TestIsValidCachePath/nar_xz2800=== CONT TestIsValidCachePath/traversal_parent2801=== CONT TestIsValidCachePath/nar_bz22802=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2803--- PASS: TestIsValidCachePath (0.00s)2804 --- PASS: TestIsValidCachePath/narinfo (0.00s)2805 --- PASS: TestIsValidCachePath/index.html (0.00s)2806 --- PASS: TestIsValidCachePath/short_hash (0.00s)2807 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2808 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2809 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2810 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2811 --- PASS: TestIsValidCachePath/empty (0.00s)2812 --- PASS: TestIsValidCachePath/realisation (0.00s)2813 --- PASS: TestIsValidCachePath/random_path (0.00s)2814 --- PASS: TestIsValidCachePath/log (0.00s)2815 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2816 --- PASS: TestIsValidCachePath/ls (0.00s)2817 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2818 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2819 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2820 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2821 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2822 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2823 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2824=== CONT TestServerTLSConfig/no_client_CA2825=== CONT TestServerTLSConfig/missing_CA_file2826=== CONT TestServerTLSConfig/not_a_PEM_file2827--- PASS: TestServerTLSConfig (0.00s)2828 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2829 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2830 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2831=== NAME TestClientCADerivations2832 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2335694667/001/store/c3m2hsk0vy0nrf17h4m0sh629h2fjzdm-ca-test2833 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2834 Compression: zstd2835 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2836 NarSize: 1442837 References: 2838 Deriver: /build/TestClientCADerivations2335694667/001/store/blx5y6h6w55w3kicx72vsg5hqfx5451j-ca-test.drv2839 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2840 client_ca_test.go:185: Checking for realisation files in S3...2841 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2842 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache28432026-10-01 09:46:23.927 UTC [1458] ERROR: relation "goose_db_version" does not exist at character 3628442026-10-01 09:46:23.927 UTC [1458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28452026/10/01 09:46:23 WARN readiness check failed error="closed pool"2846--- PASS: TestService_readinessHandler (0.56s)28472026/10/01 09:46:23 INFO lead: acquired remote=192.0.2.1:123428482026/10/01 09:46:23 INFO lead: released remote=192.0.2.1:12342849--- PASS: TestLeadElectsOneAndHandsOver (0.79s)2850=== NAME TestClientCADerivations2851 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2852 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2853 error: binary cache 's3://bucket62?endpoint=http://localhost:37731®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2335694667/001/store'2854 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12855--- PASS: TestClientCADerivations (0.96s)28562026/10/01 09:46:24 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/present28572026/10/01 09:46:24 OK 20241026095416_initial_model.sql (9.41ms)28582026/10/01 09:46:24 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)28592026-10-01 09:46:24.352 UTC [1593] ERROR: relation "goose_db_version" does not exist at character 3628602026-10-01 09:46:24.352 UTC [1593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28612026/10/01 09:46:24 OK 20251218171726_add_pins.sql (3.33ms)28622026-10-01 09:46:24.357 UTC [1594] ERROR: relation "goose_db_version" does not exist at character 3628632026-10-01 09:46:24.357 UTC [1594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28642026/10/01 09:46:24 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)28652026/10/01 09:46:24 OK 20260905000000_add_claims.sql (4.43ms)28662026/10/01 09:46:24 OK 20260920000000_drop_claims.sql (5.87ms)28672026/10/01 09:46:24 OK 20241026095416_initial_model.sql (13.3ms)28682026/10/01 09:46:24 OK 20241026095416_initial_model.sql (9.89ms)28692026/10/01 09:46:24 OK 20260923120000_add_pushes.sql (3.79ms)28702026/10/01 09:46:24 goose: successfully migrated database to version: 2026092312000028712026/10/01 09:46:24 OK 20251210153512_drop_unused_gin_index.sql (3.41ms)28722026/10/01 09:46:24 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)28732026/10/01 09:46:24 OK 1_commit_pending_closure.sql (2.34ms)28742026/10/01 09:46:24 OK 2_object_stats_trigger.sql (1.52ms)28752026/10/01 09:46:24 OK 20251218171726_add_pins.sql (3.69ms)28762026/10/01 09:46:24 OK 3_commit_push.sql (1.05ms)28772026/10/01 09:46:24 goose: up to current file version: 328782026/10/01 09:46:24 OK 20251218171726_add_pins.sql (3.7ms)28792026/10/01 09:46:24 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)28802026/10/01 09:46:24 OK 20260628120000_add_object_size_and_stats.sql (3.93ms)28812026/10/01 09:46:24 OK 20260905000000_add_claims.sql (3.35ms)28822026/10/01 09:46:24 OK 20260905000000_add_claims.sql (3.1ms)28832026/10/01 09:46:24 OK 20260920000000_drop_claims.sql (2.58ms)28842026/10/01 09:46:24 OK 20260920000000_drop_claims.sql (2.6ms)2885--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.08s)28862026/10/01 09:46:24 OK 20260923120000_add_pushes.sql (2.36ms)28872026/10/01 09:46:24 goose: successfully migrated database to version: 2026092312000028882026-10-01 09:46:24.391 UTC [1596] ERROR: relation "goose_db_version" does not exist at character 3628892026-10-01 09:46:24.391 UTC [1596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28902026/10/01 09:46:24 OK 20260923120000_add_pushes.sql (2.45ms)28912026/10/01 09:46:24 goose: successfully migrated database to version: 2026092312000028922026/10/01 09:46:24 OK 1_commit_pending_closure.sql (2.18ms)28932026/10/01 09:46:24 OK 1_commit_pending_closure.sql (1.82ms)28942026/10/01 09:46:24 OK 2_object_stats_trigger.sql (1.13ms)28952026/10/01 09:46:24 OK 2_object_stats_trigger.sql (1.14ms)28962026/10/01 09:46:24 OK 3_commit_push.sql (529.26µs)28972026/10/01 09:46:24 goose: up to current file version: 328982026/10/01 09:46:24 OK 3_commit_push.sql (688.29µs)28992026/10/01 09:46:24 goose: up to current file version: 329002026/10/01 09:46:24 OK 20241026095416_initial_model.sql (7.71ms)2901=== NAME TestNARDeduplicationMetadataUploadBug2902 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1522609374/001/store/5z1475ccrwhscf9ih3a758fh80nvb0a5-file1.txt2903--- PASS: TestObjectStatsTrigger (0.95s)29042026/10/01 09:46:24 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)29052026/10/01 09:46:24 OK 20251218171726_add_pins.sql (2.51ms)29062026/10/01 09:46:24 OK 20260628120000_add_object_size_and_stats.sql (3.04ms)29072026/10/01 09:46:24 OK 20260905000000_add_claims.sql (2.9ms)29082026/10/01 09:46:24 OK 20260920000000_drop_claims.sql (1.9ms)29092026/10/01 09:46:24 OK 20260923120000_add_pushes.sql (2.07ms)29102026/10/01 09:46:24 goose: successfully migrated database to version: 2026092312000029112026/10/01 09:46:24 OK 1_commit_pending_closure.sql (2.15ms)29122026/10/01 09:46:24 OK 2_object_stats_trigger.sql (1.13ms)29132026/10/01 09:46:24 OK 3_commit_push.sql (1.27ms)29142026/10/01 09:46:24 goose: up to current file version: 329152026/10/01 09:46:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.993927ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2916--- PASS: TestUploadHandlersRejectOversizedBody (0.14s)2917 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2918 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2919 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.74s)29202026/10/01 09:46:24 INFO Received uploads request method=POST path=/api/pending_closures29212026/10/01 09:46:24 INFO Received push request method=POST path=/api/pushes29222026/10/01 09:46:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)29232026/10/01 09:46:24 INFO Uploading 5z1475ccrwhscf9ih3a758fh80nvb0a5-file1.txt (160B)29242026/10/01 09:46:24 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"29252026/10/01 09:46:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29262026/10/01 09:46:24 WARN Failed to register uploaded object key=5z1475ccrwhscf9ih3a758fh80nvb0a5.ls error="server returned 404: 404 page not found\n"29272026/10/01 09:46:24 INFO Signed narinfos id=1 count=129282026/10/01 09:46:24 INFO Uploading 1 narinfos29292026/10/01 09:46:24 INFO Received complete push request method=POST path=/api/pushes/1/complete29302026/10/01 09:46:24 WARN Failed to register uploaded object key=5z1475ccrwhscf9ih3a758fh80nvb0a5.narinfo error="server returned 404: 404 page not found\n"2931--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (1.03s)29322026/10/01 09:46:24 INFO Upload complete. (127ms)2933=== NAME TestNARDeduplicationMetadataUploadBug2934 metadata_upload_test.go:54: Retrieved narinfo from S3:2935 StorePath: /build/TestNARDeduplicationMetadataUploadBug1522609374/001/store/5z1475ccrwhscf9ih3a758fh80nvb0a5-file1.txt2936 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2937 Compression: zstd2938 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2939 NarSize: 1602940 References: 2941 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2942 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2943 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2944 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}29452026/10/01 09:46:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux29462026/10/01 09:46:24 WARN Refused reserved pin name=worker-x86_64-linux29472026/10/01 09:46:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux29482026/10/01 09:46:24 INFO Received create pin request method=POST path=/api/pins/my-app29492026/10/01 09:46:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2950--- PASS: TestCreatePin_ReservedPins (1.10s)29512026/10/01 09:46:24 INFO Received uploads request method=POST path=/api/pending_closures2952=== NAME TestNARDeduplicationMetadataUploadBug2953 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1522609374/001/store/pr1fwagim4sk7491asf1cd4w4z2a8khh-file2.txt2954--- PASS: TestPresentReportsOnlyClosureRoots (0.87s)29552026/10/01 09:46:24 INFO Received uploads request method=POST path=/api/pending_closures29562026/10/01 09:46:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=382.800476ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2957--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.35s)29582026/10/01 09:46:24 INFO Received uploads request method=POST path=/api/pending_closures29592026/10/01 09:46:24 INFO Received cleanup request method=DELETE path=/api/pending_closures29602026/10/01 09:46:24 INFO Received uploads request method=POST path=/api/pending_closures29612026/10/01 09:46:24 INFO Aborted multipart uploads count=0 kept=029622026/10/01 09:46:24 INFO Received push request method=POST path=/api/pushes29632026/10/01 09:46:24 WARN Force mode enabled - objects will be deleted immediately without grace period29642026/10/01 09:46:24 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)29652026/10/01 09:46:24 WARN Failed to register uploaded object key=pr1fwagim4sk7491asf1cd4w4z2a8khh.ls error="server returned 404: 404 page not found\n"29662026/10/01 09:46:24 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign29672026/10/01 09:46:24 INFO Signed narinfos id=2 count=129682026/10/01 09:46:24 INFO Uploading 1 narinfos29692026/10/01 09:46:24 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=029702026/10/01 09:46:24 INFO Vacuumed table table=pending_closures29712026/10/01 09:46:24 INFO Vacuumed table table=pending_objects29722026/10/01 09:46:24 INFO Received complete push request method=POST path=/api/pushes/2/complete29732026/10/01 09:46:24 INFO Vacuumed table table=multipart_uploads29742026/10/01 09:46:24 WARN Failed to register uploaded object key=pr1fwagim4sk7491asf1cd4w4z2a8khh.narinfo error="server returned 404: 404 page not found\n"29752026/10/01 09:46:24 INFO Vacuumed table table=closures29762026/10/01 09:46:24 INFO Received uploads request method=POST path=/api/pending_closures29772026/10/01 09:46:24 INFO Upload complete. (48ms)29782026/10/01 09:46:24 INFO Vacuumed table table=objects2979=== NAME TestNARDeduplicationMetadataUploadBug2980 metadata_upload_test.go:76: Retrieved narinfo from S3:2981 StorePath: /build/TestNARDeduplicationMetadataUploadBug1522609374/001/store/pr1fwagim4sk7491asf1cd4w4z2a8khh-file2.txt2982 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2983 Compression: zstd2984 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2985 NarSize: 1602986 References: 2987 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2988 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2989 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2990 {"version":1,"root":{"type":"regular","size":44}}2991--- PASS: TestNARDeduplicationMetadataUploadBug (1.27s)29922026/10/01 09:46:24 INFO Aborted multipart uploads count=0 kept=029932026/10/01 09:46:24 WARN Force mode enabled - objects will be deleted immediately without grace period29942026/10/01 09:46:24 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=029952026/10/01 09:46:24 INFO Received cleanup request method=DELETE path=/api/pending_closures29962026/10/01 09:46:24 INFO Vacuumed table table=pending_closures29972026/10/01 09:46:24 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket79/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""29982026/10/01 09:46:24 INFO Aborted multipart uploads count=0 kept=129992026/10/01 09:46:24 INFO Vacuumed table table=pending_objects30002026/10/01 09:46:24 INFO Vacuumed table table=multipart_uploads30012026/10/01 09:46:24 INFO Vacuumed table table=closures30022026/10/01 09:46:24 INFO Vacuumed table table=objects30032026/10/01 09:46:24 INFO Received cleanup request method=DELETE path=/api/pending_closures30042026/10/01 09:46:24 INFO Aborted multipart uploads count=1 kept=03005--- PASS: TestMultipartCleanup (1.04s)3006--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3007 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.85s)3008 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.84s)30092026/10/01 09:46:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30102026/10/01 09:46:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"3011=== NAME TestOrphanedObjectsGC3012 orphaned_objects_gc_test.go:290: GC Test Summary:3013 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A3014 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B3015 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)3016 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)3017 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects3018--- PASS: TestOrphanedObjectsGC (1.34s)30192026/10/01 09:46:25 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=868.171455ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30202026/10/01 09:46:25 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=030212026/10/01 09:46:25 INFO Received create pin request method=POST path=/api/pins/myapp30222026/10/01 09:46:25 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2178160130/001/store/r6pqz4m73fxmid2mxf41vzbgfcnrb8b2-pinned-file.txt narinfo_key=r6pqz4m73fxmid2mxf41vzbgfcnrb8b2.narinfo30232026/10/01 09:46:25 INFO Starting cleanup of old closures method=DELETE path=/api/closures30242026/10/01 09:46:25 INFO Garbage collection started30252026/10/01 09:46:25 INFO Aborted multipart uploads count=0 kept=030262026/10/01 09:46:25 WARN Force mode enabled - objects will be deleted immediately without grace period30272026/10/01 09:46:25 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=030282026/10/01 09:46:25 INFO Vacuumed table table=pending_closures30292026/10/01 09:46:25 INFO Vacuumed table table=pending_objects30302026/10/01 09:46:25 INFO Vacuumed table table=multipart_uploads30312026/10/01 09:46:25 INFO Vacuumed table table=closures30322026/10/01 09:46:25 INFO Vacuumed table table=objects30332026/10/01 09:46:25 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03034=== NAME TestClientIntegration3035 client_integration_test.go:323: Objects in database after GC:3036 client_integration_test.go:323: Successfully deleted all objects with GC --force3037--- PASS: TestClientIntegration (2.83s)30382026/10/01 09:46:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.477632618s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3039=== NAME TestOrphanedObjectsGCStressTest3040 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains3041 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion3042 orphaned_objects_gc_test.go:509: Stress test completed successfully:3043 orphaned_objects_gc_test.go:510: - Active objects preserved: 203044 orphaned_objects_gc_test.go:511: - Objects deleted: 2103045 orphaned_objects_gc_test.go:512: - Total GC'd: 2103046--- PASS: TestOrphanedObjectsGCStressTest (2.82s)30472026/10/01 09:46:26 WARN Rate limiter enabled after throttle name=s3-test rate=530482026/10/01 09:46:26 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3049=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3050 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103051 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003052--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.21s)3053=== NAME TestPinProtectsFromGC3054 client_integration_test.go:840: Pin successfully protected closure from garbage collection3055--- PASS: TestPinProtectsFromGC (5.18s)30562026/10/01 09:46:27 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-config30572026/10/01 09:46:27 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=193.560547ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30582026/10/01 09:46:27 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=398.539357ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30592026/10/01 09:46:28 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=877.539357ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30602026/10/01 09:46:28 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.582713245s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30612026/10/01 09:46:30 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"30622026/10/01 09:46:30 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-config30632026/10/01 09:46:30 INFO Aborted multipart uploads count=1 kept=030642026/10/01 09:46:30 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.902374ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30652026/10/01 09:46:30 INFO Received cleanup request method=DELETE path=/api/pending_closures30662026/10/01 09:46:30 INFO Aborted multipart uploads count=1 kept=03067--- PASS: TestPendingCleanupUsesOneCutoff (6.93s)30682026/10/01 09:46:30 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=427.132479ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30692026/10/01 09:46:31 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=821.132729ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 09:46:32 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.458915723s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30712026/10/01 09:46:33 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_closures30722026/10/01 09:46:33 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.425502ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30732026/10/01 09:46:33 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=391.581481ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30742026/10/01 09:46:34 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=874.251689ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30752026/10/01 09:46:35 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.710841354s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3076--- PASS: TestClientErrorHandling (0.00s)3077 --- PASS: TestClientErrorHandling/InvalidStorePath (0.85s)3078 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.92s)3079 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.99s)3080PASS30812026-10-01 09:46:37.082 UTC [130] LOG: received smart shutdown request30822026-10-01 09:46:37.086 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 130832026-10-01 09:46:37.097 UTC [135] LOG: shutting down30842026-10-01 09:46:37.097 UTC [135] LOG: checkpoint starting: shutdown immediate30852026-10-01 09:46:38.164 UTC [135] LOG: checkpoint complete: wrote 10773 buffers (65.8%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.212 s, sync=0.831 s, total=1.067 s; sync files=28648, longest=0.027 s, average=0.001 s; distance=396466 kB, estimate=396466 kB; lsn=0/19A92568, redo lsn=0/19A9256830862026-10-01 09:46:38.237 UTC [130] LOG: database system is shut down3087Running OIDC tests...3088=== RUN TestAudienceForIssuer3089=== PAUSE TestAudienceForIssuer3090=== RUN TestGlobMatch3091=== PAUSE TestGlobMatch3092=== RUN TestValidateToken_ValidToken3093=== PAUSE TestValidateToken_ValidToken3094=== RUN TestValidateToken_WrongAudience3095=== PAUSE TestValidateToken_WrongAudience3096=== RUN TestValidateToken_Expired3097=== PAUSE TestValidateToken_Expired3098=== RUN TestValidateToken_BoundClaimsMismatch3099=== PAUSE TestValidateToken_BoundClaimsMismatch3100=== RUN TestValidateToken_BoundSubjectMismatch3101=== PAUSE TestValidateToken_BoundSubjectMismatch3102=== RUN TestValidateToken_MultipleProviders3103=== PAUSE TestValidateToken_MultipleProviders3104=== RUN TestValidateToken_NoMatchingProvider3105=== PAUSE TestValidateToken_NoMatchingProvider3106=== RUN TestValidateToken_KubernetesServiceAccount3107=== PAUSE TestValidateToken_KubernetesServiceAccount3108=== RUN TestNewValidator_KubernetesRequiresCA3109=== PAUSE TestNewValidator_KubernetesRequiresCA3110=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3111=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3112=== RUN TestPins_ReservedForMatchingRule3113=== PAUSE TestPins_ReservedForMatchingRule3114=== RUN TestPins_TopLevelShorthand3115=== PAUSE TestPins_TopLevelShorthand3116=== RUN TestPins_ConfigValidation3117=== PAUSE TestPins_ConfigValidation3118=== RUN TestScopes_LegacyProviderDefaultsToWrite3119=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3120=== RUN TestScopes_Rules3121=== PAUSE TestScopes_Rules3122=== RUN TestScopes_ConfigValidation3123=== PAUSE TestScopes_ConfigValidation3124=== CONT TestAudienceForIssuer3125=== CONT TestValidateToken_KubernetesServiceAccount3126=== CONT TestScopes_ConfigValidation3127--- PASS: TestAudienceForIssuer (0.00s)3128=== CONT TestValidateToken_NoMatchingProvider3129=== CONT TestValidateToken_WrongAudience3130=== CONT TestValidateToken_MultipleProviders3131=== CONT TestValidateToken_BoundSubjectMismatch3132=== CONT TestPins_ConfigValidation3133=== CONT TestValidateToken_ValidToken3134=== CONT TestGlobMatch3135=== RUN TestGlobMatch/foo_foo3136=== PAUSE TestGlobMatch/foo_foo3137=== RUN TestGlobMatch/foo_bar3138=== PAUSE TestGlobMatch/foo_bar3139=== RUN TestGlobMatch/*_3140=== PAUSE TestGlobMatch/*_3141=== RUN TestGlobMatch/*_anything3142=== PAUSE TestGlobMatch/*_anything3143=== CONT TestValidateToken_Expired3144=== CONT TestPins_ReservedForMatchingRule3145=== CONT TestPins_TopLevelShorthand3146=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3147=== CONT TestScopes_Rules3148=== CONT TestScopes_LegacyProviderDefaultsToWrite3149=== CONT TestNewValidator_KubernetesRequiresCA3150=== CONT TestValidateToken_BoundClaimsMismatch3151=== RUN TestGlobMatch/foo*_foo3152=== PAUSE TestGlobMatch/foo*_foo3153=== RUN TestGlobMatch/foo*_foobar3154=== PAUSE TestGlobMatch/foo*_foobar3155=== RUN TestGlobMatch/foo*_bar3156--- PASS: TestScopes_ConfigValidation (0.00s)3157=== PAUSE TestGlobMatch/foo*_bar3158=== RUN TestGlobMatch/*bar_bar3159=== PAUSE TestGlobMatch/*bar_bar3160=== RUN TestGlobMatch/*bar_foobar3161=== PAUSE TestGlobMatch/*bar_foobar3162=== RUN TestGlobMatch/*bar_foo3163=== PAUSE TestGlobMatch/*bar_foo3164=== RUN TestGlobMatch/foo*bar_foobar3165=== PAUSE TestGlobMatch/foo*bar_foobar3166=== RUN TestGlobMatch/foo*bar_foo123bar3167=== PAUSE TestGlobMatch/foo*bar_foo123bar3168=== RUN TestGlobMatch/foo*bar_foobarbaz3169=== PAUSE TestGlobMatch/foo*bar_foobarbaz3170=== RUN TestGlobMatch/*/*_foo/bar3171=== PAUSE TestGlobMatch/*/*_foo/bar3172=== RUN TestGlobMatch/*/*_foo3173=== PAUSE TestGlobMatch/*/*_foo3174=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3175=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3176=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03177=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03178=== RUN TestGlobMatch/refs/*/main_refs/heads/main3179=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3180=== RUN TestGlobMatch/fo?_foo3181=== PAUSE TestGlobMatch/fo?_foo3182=== RUN TestGlobMatch/fo?_fo3183=== PAUSE TestGlobMatch/fo?_fo3184=== RUN TestGlobMatch/fo?_fooo3185--- PASS: TestPins_ConfigValidation (0.00s)3186=== PAUSE TestGlobMatch/fo?_fooo3187=== RUN TestGlobMatch/?oo_foo3188=== PAUSE TestGlobMatch/?oo_foo3189=== RUN TestGlobMatch/?oo_boo3190=== PAUSE TestGlobMatch/?oo_boo3191=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3192=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3193=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3194=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3195=== CONT TestGlobMatch/foo_foo3196=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3197=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3198=== CONT TestGlobMatch/foo*bar_foo123bar3199=== CONT TestGlobMatch/foo*bar_foobar3200=== CONT TestGlobMatch/*bar_foo3201=== CONT TestGlobMatch/*bar_foobar3202=== CONT TestGlobMatch/*bar_bar3203=== CONT TestGlobMatch/foo*_bar3204=== CONT TestGlobMatch/foo*_foobar3205=== CONT TestGlobMatch/foo*_foo3206=== CONT TestGlobMatch/*_anything3207=== CONT TestGlobMatch/foo*bar_foobarbaz3208=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03209=== CONT TestGlobMatch/*/*_foo3210=== CONT TestGlobMatch/*/*_foo/bar3211=== CONT TestGlobMatch/*_3212=== CONT TestGlobMatch/foo_bar3213=== CONT TestGlobMatch/fo?_foo3214=== CONT TestGlobMatch/?oo_boo3215=== CONT TestGlobMatch/?oo_foo3216=== CONT TestGlobMatch/fo?_fooo3217=== CONT TestGlobMatch/fo?_fo3218=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3219=== CONT TestGlobMatch/refs/*/main_refs/heads/main3220--- PASS: TestGlobMatch (0.00s)3221 --- PASS: TestGlobMatch/foo_foo (0.00s)3222 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3223 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3224 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3225 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3226 --- PASS: TestGlobMatch/*bar_foo (0.00s)3227 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3228 --- PASS: TestGlobMatch/*bar_bar (0.00s)3229 --- PASS: TestGlobMatch/foo*_bar (0.00s)3230 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3231 --- PASS: TestGlobMatch/foo*_foo (0.00s)3232 --- PASS: TestGlobMatch/*_anything (0.00s)3233 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3234 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3235 --- PASS: TestGlobMatch/*/*_foo (0.00s)3236 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3237 --- PASS: TestGlobMatch/*_ (0.00s)3238 --- PASS: TestGlobMatch/foo_bar (0.00s)3239 --- PASS: TestGlobMatch/fo?_foo (0.00s)3240 --- PASS: TestGlobMatch/?oo_boo (0.00s)3241 --- PASS: TestGlobMatch/?oo_foo (0.00s)3242 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3243 --- PASS: TestGlobMatch/fo?_fo (0.00s)3244 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3245 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)32462026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40541/oidc3247--- PASS: TestValidateToken_WrongAudience (0.03s)32482026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45381/oidc3249--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)32502026/10/01 09:46:39 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:4474532512026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42571/oidc3252--- PASS: TestPins_TopLevelShorthand (0.07s)3253--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)32542026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46297/oidc32552026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45451/oidc3256--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)3257--- PASS: TestValidateToken_ValidToken (0.11s)32582026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46279/oidc3259--- PASS: TestValidateToken_BoundSubjectMismatch (0.12s)32602026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33653/oidc3261--- PASS: TestValidateToken_Expired (0.13s)32622026/10/01 09:46:39 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42519/oidc32632026/10/01 09:46:39 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43665/oidc3264--- PASS: TestValidateToken_MultipleProviders (0.15s)32652026/10/01 09:46:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35319/oidc32662026/10/01 09:46:39 http: TLS handshake error from 127.0.0.1:48596: remote error: tls: bad certificate3267--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)3268--- PASS: TestPins_ReservedForMatchingRule (0.16s)32692026/10/01 09:46:39 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233270--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.18s)32712026/10/01 09:46:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38573/oidc32722026/10/01 09:46:40 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38743/oidc3273--- PASS: TestScopes_Rules (0.31s)3274--- PASS: TestValidateToken_NoMatchingProvider (0.31s)3275PASS3276Running hook tests...3277=== RUN TestSendPathsEmpty3278=== PAUSE TestSendPathsEmpty3279=== RUN TestQueueEnqueueAndFetch3280=== PAUSE TestQueueEnqueueAndFetch3281=== RUN TestQueueDeduplication3282=== PAUSE TestQueueDeduplication3283=== RUN TestQueueRemove3284=== PAUSE TestQueueRemove3285=== RUN TestQueueFetchBatchLimit3286=== PAUSE TestQueueFetchBatchLimit3287=== RUN TestQueueRetryMovesToBack3288=== PAUSE TestQueueRetryMovesToBack3289=== RUN TestQueueFetchRemoveLifecycle3290=== PAUSE TestQueueFetchRemoveLifecycle3291=== RUN TestQueueConcurrentWriters3292=== PAUSE TestQueueConcurrentWriters3293=== RUN TestQueueRemoveLargeClosure3294=== PAUSE TestQueueRemoveLargeClosure3295=== RUN TestServerClientIntegration3296=== PAUSE TestServerClientIntegration3297=== RUN TestServerQueueError3298=== PAUSE TestServerQueueError3299=== RUN TestGetListenerSocketActivation3300 server_test.go:210: === RUN TestGetListenerSocketActivation3301 --- PASS: TestGetListenerSocketActivation (0.00s)3302 PASS3303 3304--- PASS: TestGetListenerSocketActivation (0.01s)3305=== RUN TestDrainIsolatesPoisonPath3306=== PAUSE TestDrainIsolatesPoisonPath3307=== RUN TestRunNotBlockedByPoisonHead3308=== PAUSE TestRunNotBlockedByPoisonHead3309=== RUN TestDrainGivesUpWhenServerDown3310=== PAUSE TestDrainGivesUpWhenServerDown3311=== RUN TestFailedPathPrunedByLaterClosure3312=== PAUSE TestFailedPathPrunedByLaterClosure3313=== RUN TestWorkerUploadsAndRemoves3314=== PAUSE TestWorkerUploadsAndRemoves3315=== RUN TestWorkerSkipsGCdPaths3316=== PAUSE TestWorkerSkipsGCdPaths3317=== RUN TestWorkerPrunesClosureDeps3318=== PAUSE TestWorkerPrunesClosureDeps3319=== RUN TestDrainTimeout3320=== PAUSE TestDrainTimeout3321=== CONT TestSendPathsEmpty3322=== CONT TestWorkerUploadsAndRemoves3323--- PASS: TestSendPathsEmpty (0.00s)3324=== CONT TestDrainTimeout3325=== CONT TestServerClientIntegration3326=== CONT TestWorkerSkipsGCdPaths3327=== CONT TestWorkerPrunesClosureDeps3328=== CONT TestRunNotBlockedByPoisonHead3329=== CONT TestQueueRemoveLargeClosure3330=== CONT TestFailedPathPrunedByLaterClosure3331=== CONT TestQueueConcurrentWriters3332=== CONT TestQueueFetchRemoveLifecycle3333=== CONT TestDrainGivesUpWhenServerDown3334=== CONT TestQueueRetryMovesToBack3335=== CONT TestQueueDeduplication3336=== CONT TestQueueRemove3337=== CONT TestQueueEnqueueAndFetch3338--- PASS: TestServerClientIntegration (0.00s)3339=== CONT TestQueueFetchBatchLimit3340=== CONT TestDrainIsolatesPoisonPath3341=== CONT TestServerQueueError33422026/10/01 09:46:40 ERROR Failed to queue paths error="permission denied" count=13343--- PASS: TestServerQueueError (0.00s)33442026/10/01 09:46:40 INFO Upload queue status pending=233452026/10/01 09:46:40 INFO Uploading batch count=233462026/10/01 09:46:40 INFO Uploading batch count=133472026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=133482026/10/01 09:46:40 INFO Uploading batch count=133492026/10/01 09:46:40 INFO Uploading batch count=433502026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=433512026/10/01 09:46:40 INFO Upload queue status pending=233522026/10/01 09:46:40 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3809863670/002/nonexistent33532026/10/01 09:46:40 INFO Uploading batch count=23354--- PASS: TestQueueEnqueueAndFetch (0.02s)33552026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=233562026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown531292801/002/a3357--- PASS: TestQueueFetchBatchLimit (0.02s)33582026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2926898299/002/bbb33592026/10/01 09:46:40 INFO Uploading batch count=133602026/10/01 09:46:40 INFO Upload queue status pending=333612026/10/01 09:46:40 INFO Uploading batch count=13362--- PASS: TestQueueDeduplication (0.02s)33632026/10/01 09:46:40 INFO Uploading batch count=133642026/10/01 09:46:40 INFO Upload queue status pending=233652026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=133662026/10/01 09:46:40 INFO Uploading batch count=233672026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown531292801/002/b33682026/10/01 09:46:40 INFO Uploading batch count=13369--- PASS: TestQueueRemove (0.02s)33702026/10/01 09:46:40 INFO Uploading batch count=233712026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=233722026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown531292801/002/c3373--- PASS: TestQueueRetryMovesToBack (0.02s)3374--- PASS: TestQueueFetchRemoveLifecycle (0.02s)33752026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown531292801/002/d33762026/10/01 09:46:40 INFO Uploading batch count=133772026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=133782026/10/01 09:46:40 INFO Uploading batch count=233792026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=233802026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown531292801/002/e33812026/10/01 09:46:40 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown531292801/002/f33822026/10/01 09:46:40 INFO Uploading batch count=133832026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=13384--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)33852026/10/01 09:46:40 INFO Uploading batch count=133862026/10/01 09:46:40 ERROR Upload failed error="upload failed" count=133872026/10/01 09:46:40 ERROR Drain finished with paths left in queue remaining=1033882026/10/01 09:46:40 ERROR Drain finished with paths left in queue remaining=13389--- PASS: TestDrainIsolatesPoisonPath (0.02s)3390--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3391--- PASS: TestWorkerPrunesClosureDeps (0.04s)3392--- PASS: TestWorkerUploadsAndRemoves (0.04s)3393--- PASS: TestWorkerSkipsGCdPaths (0.04s)3394--- PASS: TestQueueRemoveLargeClosure (0.14s)33952026/10/01 09:46:40 ERROR Upload failed error="context deadline exceeded" count=233962026/10/01 09:46:40 ERROR Drain finished with paths left in queue remaining=43397--- PASS: TestDrainTimeout (0.22s)3398--- PASS: TestQueueConcurrentWriters (0.22s)33992026/10/01 09:46:41 INFO Uploading batch count=134002026/10/01 09:46:41 INFO Uploading batch count=134012026/10/01 09:46:41 INFO Uploading batch count=134022026/10/01 09:46:41 ERROR Upload failed error="upload failed" count=134032026/10/01 09:46:41 INFO Uploading batch count=134042026/10/01 09:46:41 ERROR Upload failed error="upload failed" count=134052026/10/01 09:46:41 INFO Uploading batch count=134062026/10/01 09:46:41 ERROR Upload failed error="upload failed" count=134072026/10/01 09:46:41 INFO Uploading batch count=134082026/10/01 09:46:41 ERROR Upload failed error="upload failed" count=134092026/10/01 09:46:41 ERROR Drain finished with paths left in queue remaining=13410--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3411PASS