niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #290
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.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 TestShellSplit97--- PASS: TestShellSplit (0.00s)98=== CONT TestParsePathInfoJSONMultiplePaths99=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths100=== CONT TestSetClientTLSErrors101=== CONT TestScriptTokenEmptyCommand102=== CONT TestScriptTokenScriptFails103--- PASS: TestScriptTokenEmptyCommand (0.00s)104=== CONT TestParsePathInfoJSON105=== CONT TestScriptTokenBadJSON106=== CONT TestScriptTokenEmptyToken107=== CONT TestScriptTokenCachesUntilRefresh108=== CONT TestScriptTokenNoExpiryRerunsEveryCall109=== CONT TestFileTokenEmpty110=== CONT TestFileTokenMissing111=== CONT TestFileTokenReadsAndCaches112=== CONT TestStaticToken113=== CONT TestSetClientTLSDoesNotMutateDefaultTransport114=== CONT TestUploadMultipart_SupersededByPeer115=== RUN TestUploadMultipart_SupersededByPeer/exists116=== CONT TestEncodeNixBase32117=== RUN TestEncodeNixBase32/test_string_hash118=== CONT TestDumpPathWriterError119=== CONT TestDumpPathSingleFile120=== PAUSE TestEncodeNixBase32/test_string_hash121=== RUN TestEncodeNixBase32/empty_input122=== CONT TestDumpPathMatchesNix123=== CONT TestDoWithRetry_BodyReplayedViaGetBody124=== CONT TestResolveStorePath125=== CONT TestEncodeNixBase32WithRealHash126=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess127=== CONT TestRateLimiterFeedback128=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths129=== RUN TestParsePathInfoJSON/Nix_format130--- PASS: TestScriptTokenScriptFails (0.00s)131=== CONT TestPathInfoHashCompatibility132=== CONT TestSetClientTLS133=== CONT TestGetStorePathHash134=== RUN TestGetStorePathHash/valid_store_path135=== PAUSE TestUploadMultipart_SupersededByPeer/exists136=== RUN TestUploadMultipart_SupersededByPeer/missing137=== PAUSE TestUploadMultipart_SupersededByPeer/missing138=== RUN TestRateLimiterFeedback/429_enables_limiter139=== PAUSE TestRateLimiterFeedback/429_enables_limiter140=== RUN TestRateLimiterFeedback/503_enables_limiter141=== PAUSE TestRateLimiterFeedback/503_enables_limiter142=== PAUSE TestGetStorePathHash/valid_store_path143=== RUN TestGetStorePathHash/basename_without_hyphen_should_error144=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error1452026/10/01 07:36:34 WARN Rate limiter enabled after throttle name=server-test rate=5146=== CONT TestFilterOversizedClosures147=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter148=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter149=== PAUSE TestEncodeNixBase32/empty_input150=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths151=== PAUSE TestParsePathInfoJSON/Nix_format152=== CONT TestConvertHashToNix32153=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter154--- PASS: TestFileTokenMissing (0.00s)155=== CONT TestPathInfoCACompatibility156=== CONT TestPartSizeForNAR157=== RUN TestPartSizeForNAR/zero_stays_at_minimum158=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error159=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter1602026/10/01 07:36:34 WARN Rate limiter enabled after throttle name=server-test rate=5161=== CONT TestClientSignaturesByStorePath162=== RUN TestSetClientTLSErrors/missing_cert_file1632026/10/01 07:36:34 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:35671164=== CONT TestStreamPushBatchesUnderLoad165=== CONT TestUploadMultipart_PartsInParallel166=== RUN TestFilterOversizedClosures/no_limit_keeps_everything167=== CONT TestCaseHackSuffix168=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths169=== RUN TestParsePathInfoJSON/Lix_format170=== RUN TestConvertHashToNix32/SRI_format_to_Nix32171=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)172--- PASS: TestScriptTokenBadJSON (0.00s)173--- PASS: TestStaticToken (0.00s)174--- PASS: TestEncodeNixBase32WithRealHash (0.00s)175=== RUN TestPathInfoCACompatibility/null_ca_field176=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum177=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error1782026/10/01 07:36:34 WARN Rate limiter backed off name=server-test rate=51792026/10/01 07:36:34 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:35671180=== CONT TestStreamPushGivesUpOnDeadServer181=== CONT TestStreamPushIsolatesFailures182=== CONT TestRegisterUploadedObjectReusesConnections183=== CONT TestStreamPushReportsEveryPath184=== PAUSE TestSetClientTLSErrors/missing_cert_file1852026/10/01 07:36:34 ERROR Upload failed error="connection refused" count=20186=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything1872026/10/01 07:36:34 ERROR Server seems unavailable, giving up on batch untried=17188=== CONT TestStreamPushReportsSignatures1892026/10/01 07:36:34 ERROR Upload failed error="bad path" count=3190=== PAUSE TestParsePathInfoJSON/Lix_format191=== RUN TestParsePathInfoJSON/empty_input192=== PAUSE TestParsePathInfoJSON/empty_input193=== RUN TestParsePathInfoJSON/whitespace_only194=== CONT TestShellSplitErrors195=== CONT TestStreamPushRequestLine196=== CONT TestUploadMultipart_SupersededByPeer/exists197=== CONT TestUploadMultipart_SupersededByPeer/missing198=== CONT TestEncodeNixBase32/test_string_hash199=== CONT TestEncodeNixBase32/empty_input2002026/10/01 07:36:34 ERROR Upload failed error=boom count=1201=== CONT TestRateLimiterFeedback/429_enables_limiter202=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2032026/10/01 07:36:34 ERROR Upload failed error=boom count=1204=== PAUSE TestParsePathInfoJSON/whitespace_only205=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter206=== RUN TestParsePathInfoJSON/invalid_JSON207=== PAUSE TestParsePathInfoJSON/invalid_JSON208--- PASS: TestFileTokenEmpty (0.00s)209--- PASS: TestFileTokenReadsAndCaches (0.00s)210--- PASS: TestDoServerRequestAttachesToken (0.01s)211=== CONT TestRateLimiterFeedback/503_enables_limiter212=== PAUSE TestPathInfoCACompatibility/null_ca_field213=== RUN TestPartSizeForNAR/small_stays_at_minimum214=== RUN TestSetClientTLS/rejects_connection_without_client_cert215=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error216=== RUN TestSetClientTLSErrors/missing_key_file217=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped218=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32219=== RUN TestConvertHashToNix32/already_Nix32_format220=== PAUSE TestConvertHashToNix32/already_Nix32_format221=== RUN TestConvertHashToNix32/invalid_format222=== PAUSE TestConvertHashToNix32/invalid_format223=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)224=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon225=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon226=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI227=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI228=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512229=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512230--- PASS: TestScriptTokenEmptyToken (0.01s)231--- PASS: TestClientSignaturesByStorePath (0.00s)232--- PASS: TestResolveStorePath (0.00s)233--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)234--- PASS: TestStreamPushReportsEveryPath (0.00s)235=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2362026/10/01 07:36:34 WARN Rate limiter enabled after throttle name=server-test rate=5237=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert2382026/10/01 07:36:34 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:41703239=== CONT TestParsePathInfoJSON/Nix_format2402026/10/01 07:36:34 WARN Rate limiter backed off name=server-test rate=5241=== CONT TestParsePathInfoJSON/invalid_JSON242=== CONT TestParsePathInfoJSON/empty_input243=== CONT TestParsePathInfoJSON/Lix_format244=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2452026/10/01 07:36:34 WARN Rate limiter enabled after throttle name=server-test rate=5246=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon247=== CONT TestConvertHashToNix32/invalid_format2482026/10/01 07:36:34 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:46499249=== CONT TestConvertHashToNix32/already_Nix32_format250=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA251=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA252=== RUN TestSetClientTLS/preserves_debug_logging_transport253=== PAUSE TestSetClientTLS/preserves_debug_logging_transport254=== CONT TestSetClientTLS/rejects_connection_without_client_cert255=== CONT TestSetClientTLS/preserves_debug_logging_transport2562026/10/01 07:36:34 WARN Rate limiter backed off name=server-test rate=5257=== CONT TestParsePathInfoJSON/whitespace_only258=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)259=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== RUN TestFilterOversizedClosures/all_closures_skipped261=== PAUSE TestFilterOversizedClosures/all_closures_skipped262=== CONT TestFilterOversizedClosures/no_limit_keeps_everything263=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error264=== CONT TestGetStorePathHash/valid_store_path265=== CONT TestFilterOversizedClosures/all_closures_skipped2662026/10/01 07:36:34 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=50267=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2682026/10/01 07:36:34 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=2000269=== RUN TestPathInfoCACompatibility/old_string_format_-_text270=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text271=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive272=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive273=== RUN TestPathInfoCACompatibility/new_structured_format_-_text274=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text275=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method276=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method277=== CONT TestPathInfoCACompatibility/null_ca_field278=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error279=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error280=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method281=== CONT TestGetStorePathHash/basename_without_hyphen_should_error282=== CONT TestPathInfoCACompatibility/new_structured_format_-_text283=== PAUSE TestSetClientTLSErrors/missing_key_file284=== PAUSE TestPartSizeForNAR/small_stays_at_minimum285=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum286=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum287=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts288=== CONT TestConvertHashToNix32/SRI_format_to_Nix32289=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths290--- PASS: TestShellSplitErrors (0.00s)291--- PASS: TestStreamPushIsolatesFailures (0.00s)292=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512293=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA294=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive295=== CONT TestPathInfoCACompatibility/old_string_format_-_text296=== RUN TestSetClientTLSErrors/missing_ca_file297=== PAUSE TestSetClientTLSErrors/missing_ca_file298=== RUN TestSetClientTLSErrors/invalid_ca_file299=== PAUSE TestSetClientTLSErrors/invalid_ca_file300=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts301=== RUN TestPartSizeForNAR/1_TiB302=== PAUSE TestPartSizeForNAR/1_TiB303--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.07s)304--- PASS: TestDumpPathSingleFile (0.08s)305=== CONT TestSetClientTLSErrors/missing_cert_file306--- PASS: TestEncodeNixBase32 (0.00s)307 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)308 --- PASS: TestEncodeNixBase32/empty_input (0.00s)309--- PASS: TestStreamPushGivesUpOnDeadServer (0.07s)310--- PASS: TestStreamPushReportsSignatures (0.00s)311=== CONT TestSetClientTLSErrors/invalid_ca_file312--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)313 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)314 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)315--- PASS: TestParsePathInfoJSON (0.08s)316 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)317 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)318 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)319 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)320 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)321--- PASS: TestRateLimiterFeedback (0.00s)322 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)323 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)324 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)325 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)326=== CONT TestSetClientTLSErrors/missing_ca_file327--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.09s)328=== CONT TestSetClientTLSErrors/missing_key_file329=== RUN TestPartSizeForNAR/5_TiB_S3_max_object330=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object331=== RUN TestPartSizeForNAR/capped_at_5_GiB332=== PAUSE TestPartSizeForNAR/capped_at_5_GiB333=== CONT TestPartSizeForNAR/zero_stays_at_minimum334--- PASS: TestFilterOversizedClosures (0.08s)335 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)336 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)337 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)338=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts339=== CONT TestPartSizeForNAR/5_TiB_S3_max_object340=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum341=== CONT TestPartSizeForNAR/small_stays_at_minimum342--- PASS: TestGetStorePathHash (0.08s)343 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)344 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)345 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)346 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)347--- PASS: TestConvertHashToNix32 (0.07s)348 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)349 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)350 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)351--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)352 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)353 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)354=== CONT TestPartSizeForNAR/1_TiB355=== CONT TestPartSizeForNAR/capped_at_5_GiB356--- PASS: TestPathInfoCACompatibility (0.08s)357 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)358 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)359 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)360 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)361 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)362--- PASS: TestPathInfoHashCompatibility (0.08s)363 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)364 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)365 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)366 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)367--- PASS: TestScriptTokenCachesUntilRefresh (0.09s)368--- PASS: TestSetClientTLSErrors (0.09s)369 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)370 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)371 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)372 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)373--- PASS: TestPartSizeForNAR (0.08s)374 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)376 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)377 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)378 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)379 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)380 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)3812026/10/01 07:36:34 http: TLS handshake error from 127.0.0.1:36486: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.08s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)386--- PASS: TestStreamPushRequestLine (0.02s)387--- PASS: TestCaseHackSuffix (0.10s)388--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)389--- PASS: TestDumpPathWriterError (0.12s)390--- PASS: TestStreamPushBatchesUnderLoad (0.12s)391--- PASS: TestDumpPathMatchesNix (0.17s)392--- PASS: TestUploadMultipart_PartsInParallel (0.69s)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/postgres2950197690/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/postgres2950197690/data -l logfile start422423/build/postgres2950197690:5432 - no response4242026-10-01 07:36:36.642 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 07:36:36.642 UTC [128] LOG: listening on Unix socket "/build/postgres2950197690/.s.PGSQL.5432"4262026-10-01 07:36:36.647 UTC [135] LOG: database system was shut down at 2026-10-01 07:36:36 UTC4272026-10-01 07:36:36.651 UTC [128] LOG: database system is ready to accept connections428/build/postgres2950197690:5432 - accepting connections429{"timestamp":"2026-10-01T07:36:36.94758559Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"276c6fd1-04f8-4615-aa7c-c6490b9ce0c5","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(389)"}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 TestResolveDBConnectionString467=== PAUSE TestResolveDBConnectionString468=== RUN TestLeadElectsOneAndHandsOver469=== PAUSE TestLeadElectsOneAndHandsOver470=== RUN TestLeadIncumbentWinsAfterRestart4712026-10-01 07:36:37.143 UTC [561] ERROR: relation "goose_db_version" does not exist at character 364722026-10-01 07:36:37.143 UTC [561] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4732026/10/01 07:36:37 OK 20241026095416_initial_model.sql (6.87ms)4742026/10/01 07:36:37 OK 20251210153512_drop_unused_gin_index.sql (927.33µs)4752026/10/01 07:36:37 OK 20251218171726_add_pins.sql (2ms)4762026/10/01 07:36:37 OK 20260628120000_add_object_size_and_stats.sql (1.87ms)4772026/10/01 07:36:37 OK 20260905000000_add_claims.sql (2.26ms)4782026/10/01 07:36:37 OK 20260920000000_drop_claims.sql (1.41ms)4792026/10/01 07:36:37 OK 20260923120000_add_pushes.sql (1.4ms)4802026/10/01 07:36:37 goose: successfully migrated database to version: 202609231200004812026/10/01 07:36:37 OK 1_commit_pending_closure.sql (1.47ms)4822026/10/01 07:36:37 OK 2_object_stats_trigger.sql (744.53µs)4832026/10/01 07:36:37 OK 3_commit_push.sql (667.83µs)4842026/10/01 07:36:37 goose: up to current file version: 34852026/10/01 07:36:37 INFO lead: acquired remote=192.0.2.1:12344862026/10/01 07:36:37 INFO lead: released remote=192.0.2.1:12344872026/10/01 07:36:37 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 07:36:37 INFO lead: released remote=192.0.2.1:1234489--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)490=== RUN TestLeadEndsOnShutdown491=== PAUSE TestLeadEndsOnShutdown492=== RUN TestGCAdvisoryLockBlocksConcurrentRun4932026-10-01 07:36:37.907 UTC [571] ERROR: relation "goose_db_version" does not exist at character 364942026-10-01 07:36:37.907 UTC [571] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4952026/10/01 07:36:37 OK 20241026095416_initial_model.sql (6.7ms)4962026/10/01 07:36:37 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)4972026/10/01 07:36:37 OK 20251218171726_add_pins.sql (2.44ms)4982026/10/01 07:36:37 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)4992026/10/01 07:36:37 OK 20260905000000_add_claims.sql (2.41ms)5002026/10/01 07:36:37 OK 20260920000000_drop_claims.sql (1.39ms)5012026/10/01 07:36:37 OK 20260923120000_add_pushes.sql (1ms)5022026/10/01 07:36:37 goose: successfully migrated database to version: 202609231200005032026/10/01 07:36:37 OK 1_commit_pending_closure.sql (1.34ms)5042026/10/01 07:36:37 OK 2_object_stats_trigger.sql (630.05µs)5052026/10/01 07:36:37 OK 3_commit_push.sql (659.26µs)5062026/10/01 07:36:37 goose: up to current file version: 3507--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)508=== RUN TestGCBugBareHashReferences509=== PAUSE TestGCBugBareHashReferences510=== RUN TestGCMetrics511=== PAUSE TestGCMetrics512=== RUN TestPushDedupSurvivesConcurrentGC513=== PAUSE TestPushDedupSurvivesConcurrentGC514=== RUN TestDeduplicatedObjectsRecordedAsPending515=== PAUSE TestDeduplicatedObjectsRecordedAsPending516=== RUN TestGCSweepSkipsPendingObjects517=== PAUSE TestGCSweepSkipsPendingObjects518=== RUN TestTombstonedObjectOfferedWithoutWaiting519=== PAUSE TestTombstonedObjectOfferedWithoutWaiting520=== RUN TestGCSweepDeliversEachKeyOnce521=== PAUSE TestGCSweepDeliversEachKeyOnce522=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== RUN TestGCTaskStore_StartNew525=== PAUSE TestGCTaskStore_StartNew526=== RUN TestGCTaskStore_DeduplicateSameParams527=== PAUSE TestGCTaskStore_DeduplicateSameParams528=== RUN TestGCTaskStore_ConflictDifferentParams529=== PAUSE TestGCTaskStore_ConflictDifferentParams530=== RUN TestGCTaskStore_GetEmpty531=== PAUSE TestGCTaskStore_GetEmpty532=== RUN TestGCTaskStore_GetReturnsLatest533=== PAUSE TestGCTaskStore_GetReturnsLatest534=== RUN TestGCTaskStore_CompletedAllowsNewTask535=== PAUSE TestGCTaskStore_CompletedAllowsNewTask536=== RUN TestGCTaskStore_PhaseUpdates537=== PAUSE TestGCTaskStore_PhaseUpdates538=== RUN TestGCTaskStore_Fail539=== PAUSE TestGCTaskStore_Fail540=== RUN TestGracefulShutdownDrainsInflight541=== PAUSE TestGracefulShutdownDrainsInflight542=== RUN TestService_healthCheckHandler543=== PAUSE TestService_healthCheckHandler544=== RUN TestService_readinessHandler545=== PAUSE TestService_readinessHandler546=== RUN TestGenerateLandingPage547=== PAUSE TestGenerateLandingPage548=== RUN TestCacheConfigHandlerMaxNarSize549=== PAUSE TestCacheConfigHandlerMaxNarSize550=== RUN TestCreatePendingClosureRejectsOversizedNAR551=== PAUSE TestCreatePendingClosureRejectsOversizedNAR552=== RUN TestNARDeduplicationMetadataUploadBug553=== PAUSE TestNARDeduplicationMetadataUploadBug554=== RUN TestMetricsInventory555=== PAUSE TestMetricsInventory556=== RUN TestService_NativeMTLS557=== PAUSE TestService_NativeMTLS558=== RUN TestServerTLSConfig559=== PAUSE TestServerTLSConfig560=== RUN TestMultipartCleanup561=== PAUSE TestMultipartCleanup562=== RUN TestObjectStatsTrigger563=== PAUSE TestObjectStatsTrigger564=== RUN TestOrphanedObjectsGC565=== PAUSE TestOrphanedObjectsGC566=== RUN TestOrphanedObjectsGCStressTest567=== PAUSE TestOrphanedObjectsGCStressTest568=== RUN TestResurrectedObjectNotDeleted569=== PAUSE TestResurrectedObjectNotDeleted570=== RUN TestCreatePin_ReservedPins571=== PAUSE TestCreatePin_ReservedPins572=== RUN TestParseSingleRange573=== PAUSE TestParseSingleRange574=== RUN TestProxyHeadersOnlyTrustedOnSocket575=== PAUSE TestProxyHeadersOnlyTrustedOnSocket576=== RUN TestIsValidCachePath577=== PAUSE TestIsValidCachePath578=== RUN TestReadProxyNarinfo579=== PAUSE TestReadProxyNarinfo580=== RUN TestReadProxyNarinfoAlreadyDecompressed581=== PAUSE TestReadProxyNarinfoAlreadyDecompressed582=== RUN TestReadProxyNarStreaming583=== PAUSE TestReadProxyNarStreaming584=== RUN TestReadProxy404585=== PAUSE TestReadProxy404586=== RUN TestReadProxyInvalidPath587=== PAUSE TestReadProxyInvalidPath588=== RUN TestReadProxyHead589=== PAUSE TestReadProxyHead590=== RUN TestReadProxyConditionalGet591=== PAUSE TestReadProxyConditionalGet592=== RUN TestReadProxyRootRedirectsToIndexHTML593=== PAUSE TestReadProxyRootRedirectsToIndexHTML594=== RUN TestReadProxyDisabled595=== PAUSE TestReadProxyDisabled596=== RUN TestReadRedirectNar597=== PAUSE TestReadRedirectNar598=== RUN TestReadRedirectKeepsNarinfoProxied599=== PAUSE TestReadRedirectKeepsNarinfoProxied600=== RUN TestReadProxyRangeRequest601=== PAUSE TestReadProxyRangeRequest602=== RUN TestReadRedirectUsesPublicS3URL603=== PAUSE TestReadRedirectUsesPublicS3URL604=== RUN TestPush_OverlappingRootsStoreOneRowPerKey605=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey606=== RUN TestPush_CompleteCommitsEveryRoot607=== PAUSE TestPush_CompleteCommitsEveryRoot608=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit609=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit610=== RUN TestPush_RejectsBadRequests611=== PAUSE TestPush_RejectsBadRequests612=== RUN TestPush_SignsNarinfosOfItsPendingObjects613=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects614=== RUN TestRedundantMultipartUpload615=== PAUSE TestRedundantMultipartUpload616=== RUN TestCompleteMultipartUpload_ErrorButObjectExists617=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists618=== RUN TestCompletedNarNotReofferedAcrossClosures619=== PAUSE TestCompletedNarNotReofferedAcrossClosures620=== RUN TestPresignedUploadRegisteredBeforeCommit621=== PAUSE TestPresignedUploadRegisteredBeforeCommit622=== RUN TestService_Rustfstest623=== PAUSE TestService_Rustfstest624=== RUN TestParseSize625=== PAUSE TestParseSize626=== RUN TestSkippedUploadsHandler627=== PAUSE TestSkippedUploadsHandler628=== RUN TestSystemdListenerNotActivated629--- PASS: TestSystemdListenerNotActivated (0.00s)630=== RUN TestWatchdogBeatsWhenHealthy631--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)632=== RUN TestWatchdogSkipsWhenUnhealthy6332026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6342026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6352026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6362026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6372026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6382026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:36:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"643--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)644=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle645=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle646=== RUN TestProxyWriteTimeout647=== PAUSE TestProxyWriteTimeout648=== RUN TestIsValidUploadKey649=== PAUSE TestIsValidUploadKey650=== RUN TestUploadHandlersRejectInvalidKeys651=== PAUSE TestUploadHandlersRejectInvalidKeys652=== RUN TestUploadHandlersRejectOversizedBody653=== PAUSE TestUploadHandlersRejectOversizedBody654=== RUN TestService_cleanupPendingClosuresHandler655=== PAUSE TestService_cleanupPendingClosuresHandler656=== RUN TestService_createPendingClosureHandler657=== PAUSE TestService_createPendingClosureHandler658=== RUN TestService_verifyS3Integrity659=== PAUSE TestService_verifyS3Integrity660=== RUN TestCompleteMultipartUnregistered661=== PAUSE TestCompleteMultipartUnregistered662=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT663=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT664=== CONT TestService_AuthMiddleware665=== CONT TestService_cleanupPendingClosuresHandler666=== CONT TestNARDeduplicationMetadataUploadBug667=== CONT TestUploadHandlersRejectOversizedBody668=== CONT TestUploadHandlersRejectInvalidKeys669=== CONT TestIsValidUploadKey670=== CONT TestProxyWriteTimeout671=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== CONT TestSkippedUploadsHandler673=== CONT TestParseSize674=== CONT TestService_Rustfstest675=== CONT TestPresignedUploadRegisteredBeforeCommit676=== CONT TestCompletedNarNotReofferedAcrossClosures677=== CONT TestCompleteMultipartUpload_ErrorButObjectExists6782026/10/01 07:36:38 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000679=== CONT TestRedundantMultipartUpload680=== CONT TestPush_SignsNarinfosOfItsPendingObjects681=== CONT TestPush_RejectsBadRequests682=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit683=== CONT TestPush_CompleteCommitsEveryRoot684=== CONT TestPush_OverlappingRootsStoreOneRowPerKey685=== CONT TestReadRedirectUsesPublicS3URL686=== CONT TestReadProxyRangeRequest687=== CONT TestReadRedirectKeepsNarinfoProxied688=== CONT TestReadRedirectNar689=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info690=== RUN TestIsValidUploadKey/narinfo691=== RUN TestProxyWriteTimeout/narinfo692--- PASS: TestParseSize (0.00s)693=== CONT TestReadProxyDisabled694--- PASS: TestSkippedUploadsHandler (0.02s)695=== CONT TestReadProxyRootRedirectsToIndexHTML696=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info697=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal698=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal699=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key700=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key701=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key702=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key703=== PAUSE TestIsValidUploadKey/narinfo704=== RUN TestIsValidUploadKey/nar_zst705=== CONT TestReadProxyConditionalGet706=== PAUSE TestProxyWriteTimeout/narinfo707=== PAUSE TestIsValidUploadKey/nar_zst708=== RUN TestProxyWriteTimeout/1_GiB_nar709=== RUN TestIsValidUploadKey/nar_xz710=== PAUSE TestIsValidUploadKey/nar_xz711=== RUN TestIsValidUploadKey/nar_plain712=== PAUSE TestIsValidUploadKey/nar_plain713=== RUN TestIsValidUploadKey/listing714=== PAUSE TestIsValidUploadKey/listing715=== RUN TestIsValidUploadKey/build_log716=== PAUSE TestIsValidUploadKey/build_log717=== RUN TestIsValidUploadKey/build_log_home-manager_file718=== PAUSE TestIsValidUploadKey/build_log_home-manager_file719=== RUN TestIsValidUploadKey/build_log_plus_in_name720=== PAUSE TestIsValidUploadKey/build_log_plus_in_name721=== PAUSE TestProxyWriteTimeout/1_GiB_nar722=== RUN TestIsValidUploadKey/build_log_question_mark723=== PAUSE TestIsValidUploadKey/build_log_question_mark724=== RUN TestIsValidUploadKey/build_log_equals725=== PAUSE TestIsValidUploadKey/build_log_equals726=== RUN TestIsValidUploadKey/realisation727=== PAUSE TestIsValidUploadKey/realisation728=== RUN TestIsValidUploadKey/realisation_plus_in_output729=== PAUSE TestIsValidUploadKey/realisation_plus_in_output730=== RUN TestIsValidUploadKey/nix-cache-info731=== PAUSE TestIsValidUploadKey/nix-cache-info732=== RUN TestIsValidUploadKey/index.html733=== PAUSE TestIsValidUploadKey/index.html734=== RUN TestIsValidUploadKey/narinfo_key,_nar_type735=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type736=== RUN TestProxyWriteTimeout/10_GiB_nar737=== RUN TestIsValidUploadKey/nar_key,_narinfo_type738=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type739=== RUN TestIsValidUploadKey/listing_key,_narinfo_type740=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type741=== RUN TestIsValidUploadKey/traversal742=== PAUSE TestIsValidUploadKey/traversal743=== RUN TestIsValidUploadKey/traversal_nar744=== PAUSE TestIsValidUploadKey/traversal_nar745=== RUN TestIsValidUploadKey/absolute746=== PAUSE TestIsValidUploadKey/absolute747=== PAUSE TestProxyWriteTimeout/10_GiB_nar748=== RUN TestProxyWriteTimeout/unknown_size749=== PAUSE TestProxyWriteTimeout/unknown_size750=== RUN TestIsValidUploadKey/empty_key751=== CONT TestReadProxyHead752=== PAUSE TestIsValidUploadKey/empty_key753=== RUN TestIsValidUploadKey/unknown_type754=== PAUSE TestIsValidUploadKey/unknown_type755=== CONT TestReadProxyInvalidPath756=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure757=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure758=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart759=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart760=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts761=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts762=== CONT TestReadProxy4047632026-10-01 07:36:38.418 UTC [638] ERROR: relation "goose_db_version" does not exist at character 367642026-10-01 07:36:38.418 UTC [638] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026-10-01 07:36:38.488 UTC [639] ERROR: relation "goose_db_version" does not exist at character 367662026-10-01 07:36:38.488 UTC [639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7672026-10-01 07:36:38.495 UTC [640] ERROR: relation "goose_db_version" does not exist at character 367682026-10-01 07:36:38.495 UTC [640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026-10-01 07:36:38.497 UTC [642] ERROR: relation "goose_db_version" does not exist at character 367702026-10-01 07:36:38.497 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7712026-10-01 07:36:38.497 UTC [641] ERROR: relation "goose_db_version" does not exist at character 367722026-10-01 07:36:38.497 UTC [641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7732026/10/01 07:36:38 OK 20241026095416_initial_model.sql (15.25ms)7742026/10/01 07:36:38 OK 20241026095416_initial_model.sql (36.16ms)7752026-10-01 07:36:38.528 UTC [643] ERROR: relation "goose_db_version" does not exist at character 367762026-10-01 07:36:38.528 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7772026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3.86ms)7782026-10-01 07:36:38.532 UTC [644] ERROR: relation "goose_db_version" does not exist at character 367792026-10-01 07:36:38.532 UTC [644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7802026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (4.57ms)7812026-10-01 07:36:38.534 UTC [648] ERROR: relation "goose_db_version" does not exist at character 367822026-10-01 07:36:38.534 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7832026/10/01 07:36:38 OK 20241026095416_initial_model.sql (17.34ms)7842026/10/01 07:36:38 OK 20251218171726_add_pins.sql (6.2ms)7852026/10/01 07:36:38 OK 20241026095416_initial_model.sql (19.9ms)7862026/10/01 07:36:38 OK 20241026095416_initial_model.sql (20.11ms)7872026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3ms)7882026/10/01 07:36:38 OK 20251218171726_add_pins.sql (8.7ms)7892026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3.35ms)7902026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (4.02ms)7912026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (6.58ms)7922026-10-01 07:36:38.545 UTC [649] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 07:36:38.545 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026/10/01 07:36:38 OK 20260905000000_add_claims.sql (14.54ms)7952026/10/01 07:36:38 OK 20251218171726_add_pins.sql (15.98ms)7962026/10/01 07:36:38 OK 20251218171726_add_pins.sql (17.44ms)7972026/10/01 07:36:38 OK 20251218171726_add_pins.sql (16.03ms)7982026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (17.41ms)7992026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.26ms)8002026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (7.3ms)8012026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (6.4ms)8022026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008032026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (9.76ms)8042026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (9.68ms)8052026/10/01 07:36:38 OK 20260905000000_add_claims.sql (10.57ms)8062026/10/01 07:36:38 OK 20241026095416_initial_model.sql (30.93ms)8072026/10/01 07:36:38 OK 20260905000000_add_claims.sql (5.43ms)8082026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.92ms)8092026/10/01 07:36:38 OK 20241026095416_initial_model.sql (30.01ms)8102026/10/01 07:36:38 OK 20260905000000_add_claims.sql (5.12ms)8112026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3.72ms)8122026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.48ms)8132026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (4.37ms)8142026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (6.24ms)8152026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (4.08ms)8162026/10/01 07:36:38 OK 20260905000000_add_claims.sql (9.18ms)8172026/10/01 07:36:38 OK 3_commit_push.sql (2.89ms)8182026/10/01 07:36:38 goose: up to current file version: 38192026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (4.51ms)8202026/10/01 07:36:38 OK 20241026095416_initial_model.sql (24.15ms)8212026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (4.4ms)8222026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008232026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (3.15ms)8242026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008252026/10/01 07:36:38 OK 20251218171726_add_pins.sql (7.58ms)8262026-10-01 07:36:38.583 UTC [650] ERROR: relation "goose_db_version" does not exist at character 368272026-10-01 07:36:38.583 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (6.65ms)8292026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008302026-10-01 07:36:38.584 UTC [651] ERROR: relation "goose_db_version" does not exist at character 368312026-10-01 07:36:38.584 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8322026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (6.52ms)8332026/10/01 07:36:38 OK 1_commit_pending_closure.sql (4.13ms)8342026/10/01 07:36:38 OK 20251218171726_add_pins.sql (8.18ms)8352026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (5.87ms)8362026/10/01 07:36:38 OK 1_commit_pending_closure.sql (4.41ms)8372026-10-01 07:36:38.588 UTC [652] ERROR: relation "goose_db_version" does not exist at character 368382026-10-01 07:36:38.588 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8392026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.99ms)8402026/10/01 07:36:38 OK 1_commit_pending_closure.sql (6.05ms)8412026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (5.13ms)8422026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008432026/10/01 07:36:38 OK 2_object_stats_trigger.sql (3.15ms)8442026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (7.56ms)8452026/10/01 07:36:38 OK 3_commit_push.sql (12.37ms)8462026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (15.35ms)8472026/10/01 07:36:38 goose: up to current file version: 38482026-10-01 07:36:38.601 UTC [653] ERROR: relation "goose_db_version" does not exist at character 368492026-10-01 07:36:38.601 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8502026/10/01 07:36:38 OK 20241026095416_initial_model.sql (29.21ms)8512026/10/01 07:36:38 OK 20251218171726_add_pins.sql (15.24ms)8522026/10/01 07:36:38 OK 3_commit_push.sql (14ms)8532026/10/01 07:36:38 OK 2_object_stats_trigger.sql (14.41ms)8542026/10/01 07:36:38 OK 1_commit_pending_closure.sql (14.13ms)8552026/10/01 07:36:38 OK 20260905000000_add_claims.sql (13.96ms)8562026/10/01 07:36:38 goose: up to current file version: 38572026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.93ms)8582026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (4.67ms)8592026/10/01 07:36:38 OK 3_commit_push.sql (2.72ms)8602026/10/01 07:36:38 goose: up to current file version: 38612026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (5.66ms)8622026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.68ms)8632026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.3ms)8642026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (4.92ms)8652026/10/01 07:36:38 OK 3_commit_push.sql (2.62ms)8662026/10/01 07:36:38 goose: up to current file version: 38672026/10/01 07:36:38 OK 20251218171726_add_pins.sql (5.71ms)8682026/10/01 07:36:38 OK 20260905000000_add_claims.sql (6.03ms)8692026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (4.22ms)8702026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008712026-10-01 07:36:38.614 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368722026-10-01 07:36:38.614 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8732026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (5.31ms)8742026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008752026/10/01 07:36:38 OK 20241026095416_initial_model.sql (11.36ms)8762026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.23ms)8772026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.44ms)8782026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (5.59ms)8792026-10-01 07:36:38.618 UTC [659] ERROR: relation "goose_db_version" does not exist at character 368802026-10-01 07:36:38.618 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8812026-10-01 07:36:38.618 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368822026-10-01 07:36:38.618 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8832026-10-01 07:36:38.619 UTC [658] ERROR: relation "goose_db_version" does not exist at character 368842026-10-01 07:36:38.619 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8852026/10/01 07:36:38 OK 20241026095416_initial_model.sql (13.03ms)8862026/10/01 07:36:38 OK 20241026095416_initial_model.sql (12.89ms)8872026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.44ms)8882026-10-01 07:36:38.620 UTC [660] ERROR: relation "goose_db_version" does not exist at character 368892026-10-01 07:36:38.620 UTC [660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8902026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200008912026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3.13ms)8922026/10/01 07:36:38 OK 1_commit_pending_closure.sql (4.63ms)8932026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.44ms)8942026/10/01 07:36:38 OK 20260905000000_add_claims.sql (2.92ms)8952026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)8962026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)8972026/10/01 07:36:38 OK 3_commit_push.sql (1.24ms)8982026/10/01 07:36:38 goose: up to current file version: 38992026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.91ms)9002026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.06ms)9012026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.09ms)9022026-10-01 07:36:38.624 UTC [661] ERROR: relation "goose_db_version" does not exist at character 369032026-10-01 07:36:38.624 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9042026/10/01 07:36:38 OK 3_commit_push.sql (1.87ms)9052026/10/01 07:36:38 goose: up to current file version: 39062026/10/01 07:36:38 INFO Received cleanup request method=DELETE path=/api/pending_closures9072026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.94ms)9082026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200009092026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.84ms)9102026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.99ms)9112026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.05ms)9122026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.09ms)9132026/10/01 07:36:38 OK 20241026095416_initial_model.sql (11.45ms)9142026/10/01 07:36:38 OK 3_commit_push.sql (2.24ms)9152026/10/01 07:36:38 goose: up to current file version: 39162026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.94ms)9172026/10/01 07:36:38 INFO Aborted multipart uploads count=09182026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.54ms)9192026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)9202026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)9212026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.1ms)9222026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)9232026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures9242026/10/01 07:36:38 OK 3_commit_push.sql (1.03ms)9252026/10/01 07:36:38 goose: up to current file version: 39262026-10-01 07:36:38.632 UTC [662] ERROR: relation "goose_db_version" does not exist at character 369272026-10-01 07:36:38.632 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9282026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.97ms)9292026/10/01 07:36:38 OK 20241026095416_initial_model.sql (10.99ms)9302026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.2ms)9312026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.26ms)9322026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.25ms)9332026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)9342026-10-01 07:36:38.636 UTC [663] ERROR: relation "goose_db_version" does not exist at character 369352026-10-01 07:36:38.636 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9362026/10/01 07:36:38 OK 20241026095416_initial_model.sql (9.63ms)9372026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.71ms)9382026-10-01 07:36:38.637 UTC [665] ERROR: relation "goose_db_version" does not exist at character 369392026-10-01 07:36:38.637 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9402026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.57ms)9412026-10-01 07:36:38.638 UTC [667] ERROR: relation "goose_db_version" does not exist at character 369422026-10-01 07:36:38.638 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9432026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.26ms)9442026-10-01 07:36:38.638 UTC [666] ERROR: relation "goose_db_version" does not exist at character 369452026-10-01 07:36:38.638 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9462026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)9472026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)9482026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.22ms)9492026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200009502026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.4ms)9512026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.02ms)9522026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200009532026/10/01 07:36:38 OK 20241026095416_initial_model.sql (11.51ms)9542026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (3.37ms)9552026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200009562026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.39ms)9572026/10/01 07:36:38 OK 20241026095416_initial_model.sql (12.07ms)9582026/10/01 07:36:38 OK 20241026095416_initial_model.sql (11.59ms)9592026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.65ms)9602026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.54ms)9612026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)9622026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)9632026/10/01 07:36:38 OK 20241026095416_initial_model.sql (10.93ms)9642026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.59ms)9652026/10/01 07:36:38 INFO Received cleanup request method=DELETE path=/api/pending_closures9662026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.49ms)9672026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)9682026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.57ms)9692026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)9702026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.38ms)9712026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.65ms)9722026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)9732026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.03ms)9742026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200009752026/10/01 07:36:38 OK 3_commit_push.sql (1.14ms)9762026/10/01 07:36:38 goose: up to current file version: 39772026/10/01 07:36:38 INFO Aborted multipart uploads count=19782026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.49ms)9792026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.91ms)9802026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.56ms)9812026/10/01 07:36:38 OK 3_commit_push.sql (1.59ms)9822026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.08ms)983=== NAME TestNARDeduplicationMetadataUploadBug9842026/10/01 07:36:38 goose: up to current file version: 3985 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3833453256/001/store/7i2crfs9f9awjjc0fgmih84z9bs11105-file1.txt9862026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.64ms)9872026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.2ms)9882026/10/01 07:36:38 OK 3_commit_push.sql (2.58ms)9892026/10/01 07:36:38 goose: up to current file version: 3990--- PASS: TestService_Rustfstest (0.45s)991=== CONT TestReadProxyNarStreaming9922026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.71ms)9932026/10/01 07:36:38 OK 20241026095416_initial_model.sql (9.92ms)9942026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.35ms)9952026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.03ms)9962026/10/01 07:36:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9972026-10-01 07:36:38.651 UTC [640] ERROR: Closure does not exist: id=19982026-10-01 07:36:38.651 UTC [640] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE9992026-10-01 07:36:38.651 UTC [640] STATEMENT: -- name: CommitPendingClosure :exec1000 SELECT commit_pending_closure($1::bigint)1001 1002--- PASS: TestService_cleanupPendingClosuresHandler (0.45s)1003=== CONT TestReadProxyNarinfoAlreadyDecompressed10042026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.81ms)10052026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.32ms)10062026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)10072026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)10082026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.32ms)10092026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)10102026/10/01 07:36:38 OK 3_commit_push.sql (1.63ms)10112026/10/01 07:36:38 goose: up to current file version: 310122026/10/01 07:36:38 OK 20241026095416_initial_model.sql (9.31ms)10132026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)10142026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)10152026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.94ms)10162026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010172026/10/01 07:36:38 OK 20241026095416_initial_model.sql (10.05ms)10182026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (3.08ms)10192026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010202026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.7ms)10212026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)10222026/10/01 07:36:38 OK 20241026095416_initial_model.sql (10.99ms)10232026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.69ms)10242026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)10252026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.48ms)10262026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.84ms)10272026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.44ms)10282026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.67ms)10292026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.56ms)10302026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)10312026/10/01 07:36:38 OK 20241026095416_initial_model.sql (14.14ms)10322026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.15ms)10332026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.33ms)10342026/10/01 07:36:38 OK 20251218171726_add_pins.sql (2.83ms)10352026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (3.07ms)10362026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.86ms)10372026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (2.69ms)10382026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.97ms)10392026/10/01 07:36:38 OK 20251218171726_add_pins.sql (2.49ms)10402026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.11ms)10412026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.41ms)10422026/10/01 07:36:38 OK 3_commit_push.sql (868.11µs)10432026/10/01 07:36:38 goose: up to current file version: 310442026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.44ms)10452026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010462026/10/01 07:36:38 OK 3_commit_push.sql (1.54ms)10472026/10/01 07:36:38 goose: up to current file version: 310482026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.07ms)10492026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010502026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.06ms)10512026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.97ms)10522026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010532026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.81ms)10542026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010552026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.98ms)10562026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)10572026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.64ms)10582026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)10592026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.82ms)10602026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.08ms)10612026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.99ms)10622026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.93ms)10632026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.7ms)10642026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.84ms)10652026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.75ms)10662026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.92ms)10672026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.35ms)10682026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.41ms)10692026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)10702026/10/01 07:36:38 OK 3_commit_push.sql (1.08ms)10712026/10/01 07:36:38 goose: up to current file version: 310722026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.31ms)10732026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.32ms)10742026/10/01 07:36:38 OK 3_commit_push.sql (1.2ms)10752026/10/01 07:36:38 goose: up to current file version: 310762026/10/01 07:36:38 OK 3_commit_push.sql (829.82µs)10772026/10/01 07:36:38 goose: up to current file version: 310782026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.66ms)10792026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010802026/10/01 07:36:38 OK 20260905000000_add_claims.sql (2.39ms)10812026/10/01 07:36:38 OK 3_commit_push.sql (793.16µs)10822026/10/01 07:36:38 goose: up to current file version: 310832026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.94ms)10842026/10/01 07:36:38 OK 20260905000000_add_claims.sql (2.55ms)10852026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.05ms)10862026/10/01 07:36:38 OK 1_commit_pending_closure.sql (1.7ms)10872026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.78ms)10882026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.48ms)10892026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010902026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.03ms)10912026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.71ms)10922026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.83ms)10932026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010942026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.26ms)10952026/10/01 07:36:38 OK 3_commit_push.sql (1.73ms)10962026/10/01 07:36:38 goose: up to current file version: 310972026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.62ms)10982026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000010992026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.49ms)11002026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000011012026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.15ms)11022026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.31ms)11032026/10/01 07:36:38 OK 1_commit_pending_closure.sql (3.01ms)11042026/10/01 07:36:38 OK 3_commit_push.sql (1.87ms)11052026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.79ms)11062026/10/01 07:36:38 goose: up to current file version: 311072026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.98ms)11082026/10/01 07:36:38 OK 2_object_stats_trigger.sql (969.32µs)11092026/10/01 07:36:38 OK 3_commit_push.sql (583.66µs)11102026/10/01 07:36:38 goose: up to current file version: 311112026/10/01 07:36:38 OK 3_commit_push.sql (594.16µs)11122026/10/01 07:36:38 goose: up to current file version: 311132026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.02ms)11142026/10/01 07:36:38 OK 3_commit_push.sql (651.48µs)11152026/10/01 07:36:38 goose: up to current file version: 311162026/10/01 07:36:38 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1117--- PASS: TestService_AuthMiddleware (0.48s)1118=== CONT TestReadProxyNarinfo11192026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures11202026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures11212026/10/01 07:36:38 INFO Received push request method=POST path=/api/pushes11222026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures11232026/10/01 07:36:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11242026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures11252026/10/01 07:36:38 INFO Uploading 7i2crfs9f9awjjc0fgmih84z9bs11105-file1.txt (160B)11262026-10-01 07:36:38.753 UTC [725] ERROR: relation "goose_db_version" does not exist at character 3611272026-10-01 07:36:38.753 UTC [725] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11282026-10-01 07:36:38.754 UTC [726] ERROR: relation "goose_db_version" does not exist at character 3611292026-10-01 07:36:38.754 UTC [726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11302026/10/01 07:36:38 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11312026/10/01 07:36:38 WARN Failed to register uploaded object key=7i2crfs9f9awjjc0fgmih84z9bs11105.ls error="server returned 404: 404 page not found\n"11322026/10/01 07:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11332026/10/01 07:36:38 INFO Signed narinfos id=1 count=111342026/10/01 07:36:38 INFO Uploading 1 narinfos11352026/10/01 07:36:38 INFO Received complete push request method=POST path=/api/pushes/1/complete11362026/10/01 07:36:38 WARN Failed to register uploaded object key=7i2crfs9f9awjjc0fgmih84z9bs11105.narinfo error="server returned 404: 404 page not found\n"11372026/10/01 07:36:38 OK 20241026095416_initial_model.sql (7.87ms)11382026/10/01 07:36:38 OK 20241026095416_initial_model.sql (7.94ms)11392026/10/01 07:36:38 INFO Upload complete. (66ms)11402026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)11412026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)11422026/10/01 07:36:38 OK 20251218171726_add_pins.sql (2.61ms)1143=== NAME TestNARDeduplicationMetadataUploadBug1144 metadata_upload_test.go:54: Retrieved narinfo from S3:1145 StorePath: /build/TestNARDeduplicationMetadataUploadBug3833453256/001/store/7i2crfs9f9awjjc0fgmih84z9bs11105-file1.txt1146 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1147 Compression: zstd1148 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1149 NarSize: 1601150 References: 1151 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11522026-10-01 07:36:38.772 UTC [728] ERROR: relation "goose_db_version" does not exist at character 3611532026-10-01 07:36:38.772 UTC [728] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11542026/10/01 07:36:38 OK 20251218171726_add_pins.sql (3.69ms)11552026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures11562026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (2.43ms)1157 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1158 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1159 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11602026/10/01 07:36:38 OK 20260905000000_add_claims.sql (2.64ms)11612026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.22ms)11622026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.82ms)11632026/10/01 07:36:38 OK 20260905000000_add_claims.sql (2.37ms)11642026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.75ms)11652026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000011662026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.78ms)11672026/10/01 07:36:38 OK 1_commit_pending_closure.sql (1.73ms)11682026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.33ms)11692026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000011702026/10/01 07:36:38 OK 2_object_stats_trigger.sql (755.37µs)11712026/10/01 07:36:38 OK 3_commit_push.sql (668.13µs)11722026/10/01 07:36:38 goose: up to current file version: 311732026/10/01 07:36:38 OK 1_commit_pending_closure.sql (1.44ms)11742026/10/01 07:36:38 OK 20241026095416_initial_model.sql (7.23ms)11752026/10/01 07:36:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11762026/10/01 07:36:38 OK 2_object_stats_trigger.sql (770.27µs)11772026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)11782026/10/01 07:36:38 OK 3_commit_push.sql (645.6µs)11792026/10/01 07:36:38 goose: up to current file version: 311802026/10/01 07:36:38 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWZlM2FjZTItZmRiNi00OTdlLTgwYTItMjI2NjBjZmFkMGRjLjllM2NmZmI3LTMxZjEtNDI5NS05YjZiLWVkMjhhYmJlZGIzN3gxNzkwODQwMTk4NzYxMzc0NjA011812026/10/01 07:36:38 OK 20251218171726_add_pins.sql (2.05ms)11822026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (2.14ms)11832026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.68ms)11842026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures11852026/10/01 07:36:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWZlM2FjZTItZmRiNi00OTdlLTgwYTItMjI2NjBjZmFkMGRjLjllM2NmZmI3LTMxZjEtNDI5NS05YjZiLWVkMjhhYmJlZGIzN3gxNzkwODQwMTk4NzYxMzc0NjA0 parts=11186--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.59s)1187=== CONT TestIsValidCachePath1188=== RUN TestIsValidCachePath/narinfo1189=== PAUSE TestIsValidCachePath/narinfo1190=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1191=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1192=== RUN TestIsValidCachePath/nar_zst11932026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (1.5ms)1194=== PAUSE TestIsValidCachePath/nar_zst1195=== RUN TestIsValidCachePath/nar_xz1196=== PAUSE TestIsValidCachePath/nar_xz1197=== RUN TestIsValidCachePath/nar_bz21198=== PAUSE TestIsValidCachePath/nar_bz21199=== RUN TestIsValidCachePath/nar_uncompressed1200=== PAUSE TestIsValidCachePath/nar_uncompressed1201=== RUN TestIsValidCachePath/ls1202=== PAUSE TestIsValidCachePath/ls1203=== RUN TestIsValidCachePath/log1204=== PAUSE TestIsValidCachePath/log1205=== RUN TestIsValidCachePath/realisation1206=== PAUSE TestIsValidCachePath/realisation1207=== RUN TestIsValidCachePath/nix-cache-info1208=== PAUSE TestIsValidCachePath/nix-cache-info1209=== RUN TestIsValidCachePath/index.html1210=== PAUSE TestIsValidCachePath/index.html12112026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.06ms)1212=== RUN TestIsValidCachePath/traversal_parent12132026/10/01 07:36:38 goose: successfully migrated database to version: 202609231200001214=== PAUSE TestIsValidCachePath/traversal_parent1215=== RUN TestIsValidCachePath/traversal_in_middle1216=== PAUSE TestIsValidCachePath/traversal_in_middle1217=== RUN TestIsValidCachePath/invalid_char_e1218=== PAUSE TestIsValidCachePath/invalid_char_e1219=== RUN TestIsValidCachePath/invalid_char_u1220=== PAUSE TestIsValidCachePath/invalid_char_u1221=== RUN TestIsValidCachePath/random_path1222=== PAUSE TestIsValidCachePath/random_path1223=== RUN TestIsValidCachePath/empty1224=== PAUSE TestIsValidCachePath/empty1225=== RUN TestIsValidCachePath/leading_slash1226=== PAUSE TestIsValidCachePath/leading_slash1227=== RUN TestIsValidCachePath/wrong_extension1228=== PAUSE TestIsValidCachePath/wrong_extension1229=== RUN TestIsValidCachePath/short_hash1230=== PAUSE TestIsValidCachePath/short_hash1231=== CONT TestProxyHeadersOnlyTrustedOnSocket12322026/10/01 07:36:38 OK 1_commit_pending_closure.sql (1.53ms)12332026/10/01 07:36:38 OK 2_object_stats_trigger.sql (1.05ms)12342026/10/01 07:36:38 OK 3_commit_push.sql (652.76µs)12352026/10/01 07:36:38 goose: up to current file version: 31236=== NAME TestNARDeduplicationMetadataUploadBug1237 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3833453256/001/store/5iqwf4xvgd2xv9k26avjwln61pc8iwns-file2.txt12382026/10/01 07:36:38 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12392026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures1240--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.61s)12412026/10/01 07:36:38 INFO Received push request method=POST path=/api/pushes1242=== CONT TestParseSingleRange1243=== RUN TestParseSingleRange/none1244=== PAUSE TestParseSingleRange/none1245=== RUN TestParseSingleRange/unknown_unit1246=== PAUSE TestParseSingleRange/unknown_unit1247=== RUN TestParseSingleRange/multi-range_ignored1248=== PAUSE TestParseSingleRange/multi-range_ignored1249=== RUN TestParseSingleRange/malformed_no_dash1250=== PAUSE TestParseSingleRange/malformed_no_dash1251=== RUN TestParseSingleRange/malformed_both_empty1252=== PAUSE TestParseSingleRange/malformed_both_empty1253=== RUN TestParseSingleRange/malformed_end_before_start1254=== PAUSE TestParseSingleRange/malformed_end_before_start1255=== RUN TestParseSingleRange/closed1256=== PAUSE TestParseSingleRange/closed1257=== RUN TestParseSingleRange/open-ended1258=== PAUSE TestParseSingleRange/open-ended1259=== RUN TestParseSingleRange/end_clamped_to_size1260=== PAUSE TestParseSingleRange/end_clamped_to_size1261=== RUN TestParseSingleRange/suffix1262=== PAUSE TestParseSingleRange/suffix1263=== RUN TestParseSingleRange/suffix_exceeds_size1264=== PAUSE TestParseSingleRange/suffix_exceeds_size1265=== RUN TestParseSingleRange/single_byte1266=== PAUSE TestParseSingleRange/single_byte1267=== RUN TestParseSingleRange/start_past_EOF1268=== PAUSE TestParseSingleRange/start_past_EOF1269=== RUN TestParseSingleRange/start_far_past_EOF1270=== PAUSE TestParseSingleRange/start_far_past_EOF1271=== CONT TestCreatePin_ReservedPins12722026/10/01 07:36:38 INFO Received complete push request method=POST path=/api/pushes/1/complete12732026/10/01 07:36:38 INFO Received push request method=POST path=/api/pushes1274--- PASS: TestPush_CompleteCommitsEveryRoot (0.63s)1275=== CONT TestResurrectedObjectNotDeleted12762026/10/01 07:36:38 INFO Received complete push request method=POST path=/api/pushes/1/complete12772026/10/01 07:36:38 INFO Received push request method=POST path=/api/pushes12782026/10/01 07:36:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12792026/10/01 07:36:38 INFO Received push request method=POST path=/api/pushes12802026/10/01 07:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12812026/10/01 07:36:38 INFO Signed narinfos id=1 count=11282--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.66s)1283=== CONT TestOrphanedObjectsGCStressTest12842026/10/01 07:36:38 INFO Received push request method=POST path=/api/pushes12852026-10-01 07:36:38.888 UTC [793] ERROR: relation "goose_db_version" does not exist at character 3612862026-10-01 07:36:38.888 UTC [793] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12872026/10/01 07:36:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12882026/10/01 07:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12892026/10/01 07:36:38 WARN Failed to register uploaded object key=5iqwf4xvgd2xv9k26avjwln61pc8iwns.ls error="server returned 404: 404 page not found\n"12902026/10/01 07:36:38 INFO Signed narinfos id=2 count=112912026/10/01 07:36:38 INFO Uploading 1 narinfos1292--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.68s)1293=== CONT TestOrphanedObjectsGC12942026/10/01 07:36:38 INFO Received complete push request method=POST path=/api/pushes/2/complete12952026/10/01 07:36:38 WARN Failed to register uploaded object key=5iqwf4xvgd2xv9k26avjwln61pc8iwns.narinfo error="server returned 404: 404 page not found\n"12962026/10/01 07:36:38 OK 20241026095416_initial_model.sql (19.55ms)12972026/10/01 07:36:38 INFO Upload complete. (62ms)12982026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)1299=== NAME TestNARDeduplicationMetadataUploadBug1300 metadata_upload_test.go:76: Retrieved narinfo from S3:1301 StorePath: /build/TestNARDeduplicationMetadataUploadBug3833453256/001/store/5iqwf4xvgd2xv9k26avjwln61pc8iwns-file2.txt1302 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1303 Compression: zstd1304 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1305 NarSize: 1601306 References: 1307 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13082026/10/01 07:36:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44151/oidc1309 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1310 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1311 {"version":1,"root":{"type":"regular","size":44}}13122026/10/01 07:36:38 OK 20251218171726_add_pins.sql (2.96ms)1313--- PASS: TestNARDeduplicationMetadataUploadBug (0.72s)1314=== CONT TestObjectStatsTrigger13152026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)1316--- PASS: TestReadProxyRangeRequest (0.63s)13172026/10/01 07:36:38 OK 20260905000000_add_claims.sql (3.05ms)1318=== CONT TestMultipartCleanup13192026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.37ms)13202026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (1.81ms)13212026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000013222026-10-01 07:36:38.932 UTC [800] ERROR: relation "goose_db_version" does not exist at character 3613232026-10-01 07:36:38.932 UTC [800] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13242026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.64ms)13252026/10/01 07:36:38 INFO Aborted multipart uploads count=013262026/10/01 07:36:38 OK 2_object_stats_trigger.sql (2.55ms)13272026/10/01 07:36:38 OK 3_commit_push.sql (1.39ms)13282026/10/01 07:36:38 goose: up to current file version: 313292026/10/01 07:36:38 WARN Force mode enabled - objects will be deleted immediately without grace period1330--- PASS: TestReadProxyInvalidPath (0.65s)1331=== CONT TestServerTLSConfig1332=== RUN TestServerTLSConfig/no_client_CA1333=== PAUSE TestServerTLSConfig/no_client_CA1334=== RUN TestServerTLSConfig/missing_CA_file1335=== PAUSE TestServerTLSConfig/missing_CA_file1336=== RUN TestServerTLSConfig/not_a_PEM_file1337=== PAUSE TestServerTLSConfig/not_a_PEM_file1338=== CONT TestService_NativeMTLS13392026/10/01 07:36:38 OK 20241026095416_initial_model.sql (13.34ms)13402026/10/01 07:36:38 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=013412026/10/01 07:36:38 OK 20251210153512_drop_unused_gin_index.sql (3.03ms)13422026/10/01 07:36:38 OK 20251218171726_add_pins.sql (4.62ms)13432026/10/01 07:36:38 INFO Vacuumed table table=pending_closures13442026/10/01 07:36:38 INFO Vacuumed table table=pending_objects1345=== RUN TestPush_RejectsBadRequests/no_roots1346=== PAUSE TestPush_RejectsBadRequests/no_roots1347=== RUN TestPush_RejectsBadRequests/no_objects1348=== PAUSE TestPush_RejectsBadRequests/no_objects1349=== RUN TestPush_RejectsBadRequests/bad_root1350=== PAUSE TestPush_RejectsBadRequests/bad_root1351=== RUN TestPush_RejectsBadRequests/root_not_in_objects1352=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1353=== CONT TestMetricsInventory13542026/10/01 07:36:38 OK 20260628120000_add_object_size_and_stats.sql (5.47ms)13552026/10/01 07:36:38 INFO Vacuumed table table=multipart_uploads13562026/10/01 07:36:38 OK 20260905000000_add_claims.sql (4.36ms)13572026/10/01 07:36:38 INFO Vacuumed table table=closures13582026/10/01 07:36:38 OK 20260920000000_drop_claims.sql (2.92ms)13592026/10/01 07:36:38 INFO Vacuumed table table=objects13602026/10/01 07:36:38 OK 20260923120000_add_pushes.sql (2.49ms)13612026/10/01 07:36:38 goose: successfully migrated database to version: 2026092312000013622026/10/01 07:36:38 INFO Received complete push request method=POST path=/api/pushes/2/complete13632026-10-01 07:36:38.978 UTC [808] ERROR: relation "goose_db_version" does not exist at character 3613642026-10-01 07:36:38.978 UTC [808] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13652026/10/01 07:36:38 OK 1_commit_pending_closure.sql (2.52ms)1366--- PASS: TestReadProxyDisabled (0.77s)1367=== CONT TestGCMetrics1368--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.78s)1369=== CONT TestCreatePendingClosureRejectsOversizedNAR13702026/10/01 07:36:38 INFO Received uploads request method=POST path=/api/pending_closures1371--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1372=== CONT TestCacheConfigHandlerMaxNarSize1373--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1374=== CONT TestGenerateLandingPage1375--- PASS: TestGenerateLandingPage (0.00s)1376=== CONT TestService_readinessHandler13772026/10/01 07:36:38 OK 2_object_stats_trigger.sql (18.49ms)13782026/10/01 07:36:39 OK 3_commit_push.sql (1.86ms)13792026/10/01 07:36:39 goose: up to current file version: 313802026/10/01 07:36:39 OK 20241026095416_initial_model.sql (10.96ms)13812026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)13822026/10/01 07:36:39 INFO Received push request method=POST path=/api/pushes13832026/10/01 07:36:39 OK 20251218171726_add_pins.sql (4.5ms)13842026-10-01 07:36:39.018 UTC [813] ERROR: relation "goose_db_version" does not exist at character 3613852026-10-01 07:36:39.018 UTC [813] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13862026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)13872026/10/01 07:36:39 OK 20260905000000_add_claims.sql (5.74ms)13882026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.78ms)13892026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.74ms)13902026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000013912026/10/01 07:36:39 OK 20241026095416_initial_model.sql (10.27ms)13922026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.42ms)13932026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.47ms)13942026-10-01 07:36:39.038 UTC [814] ERROR: relation "goose_db_version" does not exist at character 3613952026-10-01 07:36:39.038 UTC [814] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13962026/10/01 07:36:39 OK 2_object_stats_trigger.sql (2.24ms)13972026-10-01 07:36:39.044 UTC [817] ERROR: relation "goose_db_version" does not exist at character 3613982026-10-01 07:36:39.044 UTC [817] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13992026/10/01 07:36:39 OK 3_commit_push.sql (10.88ms)14002026/10/01 07:36:39 goose: up to current file version: 314012026/10/01 07:36:39 OK 20251218171726_add_pins.sql (15.34ms)1402--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.82s)1403=== CONT TestService_healthCheckHandler14042026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)1405--- PASS: TestReadRedirectUsesPublicS3URL (0.83s)1406=== CONT TestGracefulShutdownDrainsInflight14072026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.43ms)14082026/10/01 07:36:39 INFO Starting HTTP server address=127.0.0.1:4401914092026/10/01 07:36:39 INFO Shutdown signal received, draining in-flight requests timeout=10s14102026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (4.13ms)14112026/10/01 07:36:39 OK 20241026095416_initial_model.sql (12.86ms)14122026/10/01 07:36:39 OK 20241026095416_initial_model.sql (12.81ms)14132026-10-01 07:36:39.067 UTC [820] ERROR: relation "goose_db_version" does not exist at character 3614142026-10-01 07:36:39.067 UTC [820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14152026-10-01 07:36:39.067 UTC [819] ERROR: relation "goose_db_version" does not exist at character 3614162026-10-01 07:36:39.067 UTC [819] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14172026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)14182026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)14192026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (4.01ms)14202026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000014212026/10/01 07:36:39 OK 20251218171726_add_pins.sql (4.37ms)14222026/10/01 07:36:39 OK 20251218171726_add_pins.sql (4.34ms)14232026/10/01 07:36:39 OK 1_commit_pending_closure.sql (3.27ms)1424--- PASS: TestReadProxyHead (0.78s)1425=== CONT TestGCTaskStore_Fail1426--- PASS: TestGCTaskStore_Fail (0.00s)1427=== CONT TestGCTaskStore_PhaseUpdates1428--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1429=== CONT TestGCTaskStore_CompletedAllowsNewTask1430--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1431=== CONT TestGCTaskStore_GetReturnsLatest1432--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1433=== CONT TestGCTaskStore_GetEmpty1434--- PASS: TestGCTaskStore_GetEmpty (0.00s)1435=== CONT TestGCTaskStore_ConflictDifferentParams1436--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1437=== CONT TestGCTaskStore_DeduplicateSameParams14382026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.9ms)1439--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1440=== CONT TestGCTaskStore_StartNew1441--- PASS: TestGCTaskStore_StartNew (0.00s)1442=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection14432026/10/01 07:36:39 OK 3_commit_push.sql (1.59ms)14442026/10/01 07:36:39 goose: up to current file version: 314452026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.84ms)14462026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.74ms)14472026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.38ms)14482026/10/01 07:36:39 OK 20260905000000_add_claims.sql (4.77ms)14492026/10/01 07:36:39 OK 20241026095416_initial_model.sql (10.74ms)14502026/10/01 07:36:39 OK 20241026095416_initial_model.sql (10.59ms)14512026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.08ms)14522026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)14532026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.05ms)14542026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.29ms)14552026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.17ms)14562026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000014572026-10-01 07:36:39.089 UTC [824] ERROR: relation "goose_db_version" does not exist at character 3614582026-10-01 07:36:39.089 UTC [824] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14592026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.02ms)14602026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000014612026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.65ms)14622026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.93ms)14632026/10/01 07:36:39 OK 20251218171726_add_pins.sql (4.02ms)14642026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.79ms)14652026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.62ms)14662026/10/01 07:36:39 OK 2_object_stats_trigger.sql (2.11ms)14672026/10/01 07:36:39 OK 3_commit_push.sql (2.11ms)14682026/10/01 07:36:39 goose: up to current file version: 314692026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)14702026-10-01 07:36:39.096 UTC [825] ERROR: relation "goose_db_version" does not exist at character 3614712026-10-01 07:36:39.096 UTC [825] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14722026/10/01 07:36:39 OK 3_commit_push.sql (1.87ms)14732026/10/01 07:36:39 goose: up to current file version: 314742026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.87ms)14752026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.68ms)14762026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.82ms)14772026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.9ms)14782026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.77ms)14792026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.41ms)14802026/10/01 07:36:39 goose: successfully migrated database to version: 202609231200001481--- PASS: TestReadRedirectKeepsNarinfoProxied (0.81s)1482=== CONT TestGCSweepDeliversEachKeyOnce14832026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.96ms)14842026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000014852026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.05ms)14862026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.54ms)14872026-10-01 07:36:39.107 UTC [826] ERROR: relation "goose_db_version" does not exist at character 3614882026-10-01 07:36:39.107 UTC [826] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14892026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.38ms)14902026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.28ms)14912026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.89ms)14922026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.81ms)14932026/10/01 07:36:39 OK 20241026095416_initial_model.sql (10.47ms)14942026/10/01 07:36:39 OK 20251218171726_add_pins.sql (5.01ms)14952026/10/01 07:36:39 OK 3_commit_push.sql (2.59ms)14962026/10/01 07:36:39 goose: up to current file version: 314972026/10/01 07:36:39 OK 3_commit_push.sql (3.68ms)14982026/10/01 07:36:39 goose: up to current file version: 314992026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)15002026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)15012026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.04ms)15022026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.3ms)15032026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)15042026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.17ms)15052026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.43ms)15062026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.93ms)1507--- PASS: TestReadProxy404 (0.76s)1508=== CONT TestTombstonedObjectOfferedWithoutWaiting15092026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.34ms)15102026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000015112026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)15122026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.81ms)15132026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.42ms)15142026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.25ms)15152026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.57ms)15162026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.32ms)15172026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000015182026/10/01 07:36:39 OK 3_commit_push.sql (1.31ms)15192026/10/01 07:36:39 goose: up to current file version: 31520--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1521=== CONT TestGCSweepSkipsPendingObjects15222026/10/01 07:36:39 OK 1_commit_pending_closure.sql (10.63ms)15232026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (15.3ms)15242026/10/01 07:36:39 OK 2_object_stats_trigger.sql (5.08ms)15252026/10/01 07:36:39 OK 3_commit_push.sql (1.7ms)15262026/10/01 07:36:39 goose: up to current file version: 315272026/10/01 07:36:39 OK 20260905000000_add_claims.sql (4.07ms)15282026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.61ms)15292026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (5.15ms)15302026/10/01 07:36:39 goose: successfully migrated database to version: 202609231200001531--- PASS: TestReadProxyConditionalGet (0.87s)1532=== CONT TestDeduplicatedObjectsRecordedAsPending15332026-10-01 07:36:39.159 UTC [833] ERROR: relation "goose_db_version" does not exist at character 3615342026-10-01 07:36:39.159 UTC [833] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15352026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.52ms)15362026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.67ms)15372026/10/01 07:36:39 OK 3_commit_push.sql (1.9ms)15382026/10/01 07:36:39 goose: up to current file version: 315392026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.32ms)15402026-10-01 07:36:39.177 UTC [836] ERROR: relation "goose_db_version" does not exist at character 3615412026-10-01 07:36:39.177 UTC [836] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15422026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)15432026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.19ms)15442026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)1545--- PASS: TestReadRedirectNar (0.89s)1546=== CONT TestPushDedupSurvivesConcurrentGC15472026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.97ms)15482026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.33ms)15492026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.37ms)15502026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000015512026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.87ms)15522026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.17ms)15532026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)15542026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.59ms)15552026/10/01 07:36:39 OK 3_commit_push.sql (2.03ms)15562026/10/01 07:36:39 goose: up to current file version: 315572026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.05ms)15582026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.68ms)15592026-10-01 07:36:39.203 UTC [839] ERROR: relation "goose_db_version" does not exist at character 3615602026-10-01 07:36:39.203 UTC [839] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15612026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.18ms)15622026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.83ms)1563--- PASS: TestReadProxyNarStreaming (0.56s)1564=== CONT TestService_verifyS3Integrity15652026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (9.53ms)15662026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000015672026/10/01 07:36:39 OK 20241026095416_initial_model.sql (12.4ms)15682026/10/01 07:36:39 OK 1_commit_pending_closure.sql (6.11ms)15692026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (3.88ms)15702026/10/01 07:36:39 OK 2_object_stats_trigger.sql (2.05ms)15712026/10/01 07:36:39 OK 3_commit_push.sql (1.56ms)15722026/10/01 07:36:39 goose: up to current file version: 315732026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.95ms)15742026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.85ms)15752026-10-01 07:36:39.236 UTC [842] ERROR: relation "goose_db_version" does not exist at character 3615762026-10-01 07:36:39.236 UTC [842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15772026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.37ms)1578--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.59s)1579=== CONT TestClientIntegration15802026/10/01 07:36:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15812026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.48ms)15822026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.02ms)15832026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000015842026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.45ms)15852026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.69ms)15862026-10-01 07:36:39.247 UTC [846] ERROR: relation "goose_db_version" does not exist at character 3615872026-10-01 07:36:39.247 UTC [846] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15882026/10/01 07:36:39 OK 3_commit_push.sql (2.84ms)15892026/10/01 07:36:39 goose: up to current file version: 315902026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.15ms)15912026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2ms)15922026/10/01 07:36:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15932026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.89ms)15942026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)15952026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.47ms)15962026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2ms)15972026-10-01 07:36:39.264 UTC [862] ERROR: relation "goose_db_version" does not exist at character 3615982026-10-01 07:36:39.264 UTC [862] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15992026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.83ms)1600--- PASS: TestReadProxyNarinfo (0.58s)1601=== CONT TestGCBugBareHashReferences16022026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.86ms)16032026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.19ms)16042026/10/01 07:36:39 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MWZlM2FjZTItZmRiNi00OTdlLTgwYTItMjI2NjBjZmFkMGRjLmFhNjg4ZmJlLTBmZGEtNDE0OS05MTQ1LWE5ODBlN2JhMTc5ZHgxNzkwODQwMTk4NzI4MDY4NDU2 parts=1216052026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.91ms)16062026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000016072026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures16082026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (5.28ms)16092026/10/01 07:36:39 OK 1_commit_pending_closure.sql (3.56ms)1610--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.07s)1611=== CONT TestLeadEndsOnShutdown16122026/10/01 07:36:39 OK 2_object_stats_trigger.sql (2.46ms)16132026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.73ms)16142026/10/01 07:36:39 OK 3_commit_push.sql (2.1ms)16152026/10/01 07:36:39 goose: up to current file version: 316162026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.86ms)16172026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (3.29ms)16182026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000016192026/10/01 07:36:39 OK 20241026095416_initial_model.sql (12.4ms)16202026/10/01 07:36:39 OK 1_commit_pending_closure.sql (12.54ms)16212026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (12.68ms)16222026/10/01 07:36:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MWZlM2FjZTItZmRiNi00OTdlLTgwYTItMjI2NjBjZmFkMGRjLmU0MGM0OWZlLTg4MmQtNGMxOS05MGFhLTkxZjlhMDU5Y2Q1OXgxNzkwODQwMTk4NzM4OTE1NTA5 parts=121623--- PASS: TestRedundantMultipartUpload (1.10s)1624=== CONT TestLeadElectsOneAndHandsOver16252026/10/01 07:36:39 OK 2_object_stats_trigger.sql (10.44ms)16262026/10/01 07:36:39 OK 20251218171726_add_pins.sql (10.35ms)16272026-10-01 07:36:39.319 UTC [867] ERROR: relation "goose_db_version" does not exist at character 3616282026-10-01 07:36:39.319 UTC [867] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16292026/10/01 07:36:39 INFO Starting HTTP server address=127.0.0.1:3442316302026/10/01 07:36:39 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket1518138191/001/proxy.sock16312026/10/01 07:36:39 WARN mTLS auth: subject not in bound subjects subject="CN=someone"16322026/10/01 07:36:39 INFO Shutdown signal received, draining in-flight requests timeout=10s1633--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.52s)1634=== CONT TestResolveDBConnectionString1635=== RUN TestResolveDBConnectionString/flag_wins1636=== PAUSE TestResolveDBConnectionString/flag_wins1637=== RUN TestResolveDBConnectionString/file_when_flag_empty1638=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1639=== RUN TestResolveDBConnectionString/missing_file_is_an_error1640=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1641=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1642=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1643=== RUN TestResolveDBConnectionString/nothing_configured1644=== PAUSE TestResolveDBConnectionString/nothing_configured1645=== CONT TestClientFallsBackToClosures16462026/10/01 07:36:39 OK 3_commit_push.sql (20.92ms)16472026/10/01 07:36:39 goose: up to current file version: 316482026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (24.23ms)16492026/10/01 07:36:39 OK 20260905000000_add_claims.sql (5.97ms)16502026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.46ms)16512026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (4.18ms)16522026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)16532026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.98ms)16542026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000016552026-10-01 07:36:39.345 UTC [872] ERROR: relation "goose_db_version" does not exist at character 3616562026-10-01 07:36:39.345 UTC [872] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16572026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.49ms)16582026/10/01 07:36:39 OK 1_commit_pending_closure.sql (3.17ms)16592026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.72ms)16602026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.65ms)16612026/10/01 07:36:39 OK 3_commit_push.sql (2.17ms)16622026/10/01 07:36:39 goose: up to current file version: 316632026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.56ms)16642026-10-01 07:36:39.359 UTC [873] ERROR: relation "goose_db_version" does not exist at character 3616652026-10-01 07:36:39.359 UTC [873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16662026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.14ms)16672026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.24ms)16682026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.62ms)16692026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000016702026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)16712026/10/01 07:36:39 OK 1_commit_pending_closure.sql (3.99ms)16722026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.86ms)16732026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.5ms)16742026/10/01 07:36:39 OK 3_commit_push.sql (1.27ms)16752026/10/01 07:36:39 goose: up to current file version: 316762026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (5.51ms)16772026/10/01 07:36:39 OK 20241026095416_initial_model.sql (10.59ms)16782026/10/01 07:36:39 OK 20260905000000_add_claims.sql (4.45ms)16792026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.44ms)16802026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.96ms)16812026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.95ms)16822026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.81ms)16832026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000016842026/10/01 07:36:39 OK 1_commit_pending_closure.sql (3.26ms)16852026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (5.02ms)16862026-10-01 07:36:39.387 UTC [874] ERROR: relation "goose_db_version" does not exist at character 3616872026-10-01 07:36:39.387 UTC [874] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16882026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.83ms)16892026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.34ms)16902026/10/01 07:36:39 OK 3_commit_push.sql (2.77ms)16912026/10/01 07:36:39 goose: up to current file version: 316922026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.15ms)16932026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.93ms)16942026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000016952026/10/01 07:36:39 OK 1_commit_pending_closure.sql (11.33ms)16962026/10/01 07:36:39 OK 20241026095416_initial_model.sql (16.07ms)16972026/10/01 07:36:39 OK 2_object_stats_trigger.sql (3.68ms)16982026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)16992026/10/01 07:36:39 OK 3_commit_push.sql (1.15ms)17002026/10/01 07:36:39 goose: up to current file version: 31701--- PASS: TestResurrectedObjectNotDeleted (0.57s)1702=== CONT TestClientPushesUseOnePush17032026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.08ms)17042026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)17052026-10-01 07:36:39.420 UTC [875] ERROR: relation "goose_db_version" does not exist at character 3617062026-10-01 07:36:39.420 UTC [875] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17072026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.53ms)17082026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.91ms)17092026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.16ms)17102026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000017112026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.8ms)17122026-10-01 07:36:39.429 UTC [878] ERROR: relation "goose_db_version" does not exist at character 3617132026-10-01 07:36:39.429 UTC [878] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17142026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.27ms)17152026/10/01 07:36:39 OK 3_commit_push.sql (1.28ms)17162026/10/01 07:36:39 goose: up to current file version: 317172026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.5ms)17182026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)17192026-10-01 07:36:39.438 UTC [879] ERROR: relation "goose_db_version" does not exist at character 3617202026-10-01 07:36:39.438 UTC [879] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17212026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.7ms)17222026/10/01 07:36:39 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17232026/10/01 07:36:39 WARN Refused reserved pin name=worker-x86_64-linux17242026/10/01 07:36:39 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17252026/10/01 07:36:39 INFO Received create pin request method=POST path=/api/pins/my-app17262026/10/01 07:36:39 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17272026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)1728--- PASS: TestCreatePin_ReservedPins (0.62s)1729=== CONT TestCompleteMultipartUnregistered17302026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.03ms)17312026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)17322026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.93ms)17332026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.82ms)17342026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.11ms)17352026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)17362026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.94ms)17372026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000017382026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.84ms)17392026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)17402026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.48ms)17412026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.06ms)17422026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.01ms)17432026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.47ms)17442026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.88ms)17452026/10/01 07:36:39 OK 3_commit_push.sql (1.2ms)17462026/10/01 07:36:39 goose: up to current file version: 317472026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.67ms)17482026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000017492026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (2.99ms)17502026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.67ms)17512026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.2ms)17522026/10/01 07:36:39 OK 3_commit_push.sql (2.07ms)17532026/10/01 07:36:39 goose: up to current file version: 317542026/10/01 07:36:39 OK 20260905000000_add_claims.sql (4.11ms)17552026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.95ms)17562026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (4.87ms)17572026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000017582026/10/01 07:36:39 OK 1_commit_pending_closure.sql (7.05ms)17592026/10/01 07:36:39 OK 2_object_stats_trigger.sql (6.96ms)17602026/10/01 07:36:39 OK 3_commit_push.sql (1.45ms)17612026/10/01 07:36:39 goose: up to current file version: 31762--- PASS: TestObjectStatsTrigger (0.57s)1763=== CONT TestPinProtectsFromGC17642026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures17652026-10-01 07:36:39.511 UTC [884] ERROR: relation "goose_db_version" does not exist at character 3617662026-10-01 07:36:39.511 UTC [884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17672026/10/01 07:36:39 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17682026/10/01 07:36:39 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1769--- PASS: TestService_NativeMTLS (0.58s)1770=== CONT TestClientSharedPathCommittedMidPush17712026/10/01 07:36:39 OK 20241026095416_initial_model.sql (27.37ms)17722026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (9.98ms)17732026-10-01 07:36:39.563 UTC [887] ERROR: relation "goose_db_version" does not exist at character 3617742026-10-01 07:36:39.563 UTC [887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17752026/10/01 07:36:39 OK 20251218171726_add_pins.sql (13.68ms)17762026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.5ms)17772026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.09ms)17782026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.44ms)17792026/10/01 07:36:39 OK 20241026095416_initial_model.sql (7.97ms)17802026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.85ms)17812026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000017822026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)17832026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.72ms)17842026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.43ms)17852026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.74ms)17862026/10/01 07:36:39 OK 3_commit_push.sql (709.65µs)17872026/10/01 07:36:39 goose: up to current file version: 317882026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (2.86ms)17892026-10-01 07:36:39.588 UTC [888] ERROR: relation "goose_db_version" does not exist at character 3617902026-10-01 07:36:39.588 UTC [888] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17912026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.11ms)17922026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.08ms)17932026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.68ms)17942026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000017952026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.92ms)17962026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.1ms)17972026/10/01 07:36:39 OK 3_commit_push.sql (1.1ms)17982026/10/01 07:36:39 goose: up to current file version: 31799--- PASS: TestMetricsInventory (0.63s)1800=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT18012026/10/01 07:36:39 INFO Aborted multipart uploads count=018022026/10/01 07:36:39 OK 20241026095416_initial_model.sql (7.65ms)18032026/10/01 07:36:39 WARN Force mode enabled - objects will be deleted immediately without grace period18042026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.63ms)18052026/10/01 07:36:39 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=018062026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.96ms)18072026/10/01 07:36:39 INFO Vacuumed table table=pending_closures18082026/10/01 07:36:39 INFO Vacuumed table table=pending_objects18092026/10/01 07:36:39 INFO Vacuumed table table=multipart_uploads18102026/10/01 07:36:39 INFO Vacuumed table table=closures18112026/10/01 07:36:39 INFO Vacuumed table table=objects18122026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.37ms)18132026/10/01 07:36:39 WARN readiness check failed error="closed pool"1814--- PASS: TestService_readinessHandler (0.61s)1815=== CONT TestClientWithDependencies18162026/10/01 07:36:39 OK 20260905000000_add_claims.sql (4.32ms)18172026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.28ms)18182026/10/01 07:36:39 INFO Received cleanup request method=DELETE path=/api/pending_closures1819--- PASS: TestGCMetrics (0.63s)1820=== CONT TestClientMultipleUploads18212026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.86ms)18222026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000018232026/10/01 07:36:39 INFO Aborted multipart uploads count=118242026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.22ms)18252026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.31ms)18262026/10/01 07:36:39 OK 3_commit_push.sql (1.43ms)18272026/10/01 07:36:39 goose: up to current file version: 31828--- PASS: TestMultipartCleanup (0.70s)1829=== CONT TestService_ReadAuthMiddleware1830--- PASS: TestService_healthCheckHandler (0.58s)1831=== CONT TestService_ReadScope_PublicByDefault18322026-10-01 07:36:39.640 UTC [898] ERROR: relation "goose_db_version" does not exist at character 3618332026-10-01 07:36:39.640 UTC [898] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18342026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.74ms)18352026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (3.12ms)18362026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.89ms)18372026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures18382026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)18392026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.38ms)18402026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (3.49ms)18412026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (16.28ms)18422026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000018432026/10/01 07:36:39 OK 1_commit_pending_closure.sql (3.14ms)18442026/10/01 07:36:39 OK 2_object_stats_trigger.sql (2.42ms)18452026/10/01 07:36:39 OK 3_commit_push.sql (1.87ms)18462026/10/01 07:36:39 goose: up to current file version: 318472026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures18482026-10-01 07:36:39.706 UTC [901] ERROR: relation "goose_db_version" does not exist at character 3618492026-10-01 07:36:39.706 UTC [901] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1850--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.58s)1851=== CONT TestService_RequireScope_OIDC18522026/10/01 07:36:39 INFO Aborted multipart uploads count=018532026/10/01 07:36:39 WARN Force mode enabled - objects will be deleted immediately without grace period18542026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.21ms)1855=== NAME TestOrphanedObjectsGC1856 orphaned_objects_gc_test.go:290: GC Test Summary:1857 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1858 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1859 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1860 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1861 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1862--- PASS: TestOrphanedObjectsGC (0.83s)1863=== CONT TestClientErrorHandling1864=== RUN TestClientErrorHandling/InvalidStorePath1865=== PAUSE TestClientErrorHandling/InvalidStorePath1866=== RUN TestClientErrorHandling/InvalidAuthToken1867=== PAUSE TestClientErrorHandling/InvalidAuthToken1868=== RUN TestClientErrorHandling/ServerNotAvailable1869=== PAUSE TestClientErrorHandling/ServerNotAvailable1870=== CONT TestService_AuthMiddleware_OIDC18712026-10-01 07:36:39.725 UTC [908] ERROR: relation "goose_db_version" does not exist at character 3618722026-10-01 07:36:39.725 UTC [908] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18732026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)18742026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures18752026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.7ms)18762026/10/01 07:36:39 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=018772026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)18782026/10/01 07:36:39 INFO Vacuumed table table=pending_closures18792026-10-01 07:36:39.734 UTC [909] ERROR: relation "goose_db_version" does not exist at character 3618802026-10-01 07:36:39.734 UTC [909] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18812026/10/01 07:36:39 INFO Vacuumed table table=pending_objects18822026/10/01 07:36:39 INFO Vacuumed table table=multipart_uploads18832026/10/01 07:36:39 INFO Vacuumed table table=closures18842026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.16ms)18852026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.71ms)18862026/10/01 07:36:39 INFO Vacuumed table table=objects18872026-10-01 07:36:39.739 UTC [910] ERROR: relation "goose_db_version" does not exist at character 3618882026-10-01 07:36:39.739 UTC [910] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1889--- PASS: TestGCSweepDeliversEachKeyOnce (0.63s)18902026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.88ms)1891=== CONT TestClientCADerivations18922026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.68ms)18932026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000018942026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)18952026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.77ms)18962026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures18972026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.37ms)18982026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.8ms)18992026/10/01 07:36:39 OK 3_commit_push.sql (739.15µs)19002026/10/01 07:36:39 goose: up to current file version: 319012026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (2.91ms)19022026/10/01 07:36:39 INFO Aborted multipart uploads count=019032026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.34ms)19042026/10/01 07:36:39 WARN Force mode enabled - objects will be deleted immediately without grace period19052026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.12ms)1906--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.59s)19072026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)1908=== CONT TestService_createPendingClosureHandler19092026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.11ms)19102026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.75ms)19112026/10/01 07:36:39 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=019122026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.08ms)19132026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)19142026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.95ms)19152026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000019162026/10/01 07:36:39 INFO Vacuumed table table=pending_closures19172026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.67ms)19182026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.04ms)19192026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.28ms)19202026/10/01 07:36:39 OK 2_object_stats_trigger.sql (902.39µs)19212026-10-01 07:36:39.758 UTC [914] ERROR: relation "goose_db_version" does not exist at character 3619222026-10-01 07:36:39.758 UTC [914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19232026/10/01 07:36:39 INFO Vacuumed table table=pending_objects19242026/10/01 07:36:39 INFO Vacuumed table table=multipart_uploads19252026/10/01 07:36:39 INFO Vacuumed table table=closures19262026/10/01 07:36:39 OK 3_commit_push.sql (2.05ms)19272026/10/01 07:36:39 goose: up to current file version: 319282026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.41ms)19292026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.54ms)19302026/10/01 07:36:39 INFO Vacuumed table table=objects19312026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.05ms)19322026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.66ms)19332026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.95ms)19342026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000019352026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.02ms)19362026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.95ms)19372026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.11ms)19382026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000019392026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.42ms)19402026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.69ms)19412026/10/01 07:36:39 OK 3_commit_push.sql (1.4ms)19422026/10/01 07:36:39 goose: up to current file version: 31943--- PASS: TestGCSweepSkipsPendingObjects (0.64s)1944=== CONT TestCacheStatsHandler19452026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.65ms)19462026/10/01 07:36:39 OK 3_commit_push.sql (1.57ms)19472026/10/01 07:36:39 goose: up to current file version: 319482026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.58ms)19492026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures19502026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures19512026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)19522026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.42ms)19532026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.95ms)19542026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.84ms)19552026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.55ms)19562026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.85ms)19572026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000019582026/10/01 07:36:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45061/oidc19592026/10/01 07:36:39 OK 1_commit_pending_closure.sql (10.53ms)19602026/10/01 07:36:39 OK 2_object_stats_trigger.sql (3.19ms)19612026/10/01 07:36:39 OK 3_commit_push.sql (1.1ms)19622026/10/01 07:36:39 goose: up to current file version: 319632026/10/01 07:36:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34425/oidc19642026/10/01 07:36:39 INFO lead: acquired remote=192.0.2.1:123419652026/10/01 07:36:39 INFO lead: released remote=192.0.2.1:12341966--- PASS: TestLeadEndsOnShutdown (0.56s)1967=== CONT TestCacheConfigHandler1968=== RUN TestCacheConfigHandler/full_config,_no_issuer1969=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1970=== RUN TestCacheConfigHandler/no_cache_url_configured1971=== PAUSE TestCacheConfigHandler/no_cache_url_configured1972=== RUN TestCacheConfigHandler/no_signing_keys1973=== PAUSE TestCacheConfigHandler/no_signing_keys1974=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1975=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1976=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1977=== NAME TestClientIntegration1978 client_integration_test.go:286: Created store path: /build/TestClientIntegration833706745/002/store/nim6czxilpfwixlyl24203wbb5xli10c-test-file.txt19792026/10/01 07:36:39 INFO Aborted multipart uploads count=019802026-10-01 07:36:39.849 UTC [944] ERROR: relation "goose_db_version" does not exist at character 3619812026-10-01 07:36:39.849 UTC [944] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19822026/10/01 07:36:39 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=019832026/10/01 07:36:39 INFO lead: acquired remote=192.0.2.1:123419842026/10/01 07:36:39 INFO Vacuumed table table=pending_closures19852026/10/01 07:36:39 INFO Vacuumed table table=pending_objects19862026/10/01 07:36:39 INFO Vacuumed table table=multipart_uploads19872026-10-01 07:36:39.861 UTC [946] ERROR: relation "goose_db_version" does not exist at character 3619882026-10-01 07:36:39.861 UTC [946] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19892026/10/01 07:36:39 INFO Vacuumed table table=closures19902026/10/01 07:36:39 INFO Vacuumed table table=objects19912026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.82ms)19922026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)19932026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.87ms)19942026/10/01 07:36:39 INFO Aborted multipart uploads count=019952026/10/01 07:36:39 WARN Force mode enabled - objects will be deleted immediately without grace period1996--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.80s)19972026/10/01 07:36:39 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=01998=== CONT TestService_AuthMiddleware_MTLSProxyHeader19992026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.38ms)20002026/10/01 07:36:39 INFO Vacuumed table table=pending_closures20012026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.62ms)20022026/10/01 07:36:39 INFO Vacuumed table table=pending_objects20032026/10/01 07:36:39 INFO Vacuumed table table=multipart_uploads20042026-10-01 07:36:39.881 UTC [965] ERROR: relation "goose_db_version" does not exist at character 3620052026-10-01 07:36:39.881 UTC [965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20062026/10/01 07:36:39 OK 20260905000000_add_claims.sql (11.77ms)20072026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (10.51ms)20082026/10/01 07:36:39 INFO Vacuumed table table=closures20092026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.43ms)20102026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (4.19ms)20112026/10/01 07:36:39 INFO Vacuumed table table=objects2012--- PASS: TestPushDedupSurvivesConcurrentGC (0.71s)2013=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20142026/10/01 07:36:39 INFO Received uploads request method=POST path=/2015=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20162026/10/01 07:36:39 INFO Received request for more parts method=POST path=/2017=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20182026/10/01 07:36:39 INFO Received complete multipart upload request method=POST path=/2019=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20202026/10/01 07:36:39 INFO Received uploads request method=POST path=/2021--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)2022 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2023 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2024 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2025 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2026=== CONT TestProxyWriteTimeout/narinfo20272026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.23ms)2028=== CONT TestProxyWriteTimeout/unknown_size20292026/10/01 07:36:39 goose: successfully migrated database to version: 202609231200002030=== CONT TestProxyWriteTimeout/10_GiB_nar2031=== CONT TestProxyWriteTimeout/1_GiB_nar2032--- PASS: TestProxyWriteTimeout (0.09s)2033 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2034 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2035 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2036 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2037=== CONT TestIsValidUploadKey/narinfo2038=== CONT TestIsValidUploadKey/realisation_plus_in_output2039=== CONT TestIsValidUploadKey/unknown_type2040=== CONT TestIsValidUploadKey/empty_key2041=== CONT TestIsValidUploadKey/absolute2042=== CONT TestIsValidUploadKey/traversal_nar2043=== CONT TestIsValidUploadKey/traversal2044=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2045=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2046=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2047=== CONT TestIsValidUploadKey/index.html2048=== CONT TestIsValidUploadKey/nix-cache-info2049=== CONT TestIsValidUploadKey/nar_plain2050=== CONT TestIsValidUploadKey/build_log20512026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.49ms)2052=== CONT TestIsValidUploadKey/listing2053=== CONT TestIsValidUploadKey/build_log_equals2054=== CONT TestIsValidUploadKey/realisation2055=== CONT TestIsValidUploadKey/nar_xz2056=== CONT TestIsValidUploadKey/nar_zst2057=== CONT TestIsValidUploadKey/build_log_question_mark2058=== CONT TestIsValidUploadKey/build_log_plus_in_name2059=== CONT TestIsValidUploadKey/build_log_home-manager_file2060--- PASS: TestIsValidUploadKey (0.10s)2061 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2062 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2063 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2064 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2065 --- PASS: TestIsValidUploadKey/absolute (0.00s)2066 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2067 --- PASS: TestIsValidUploadKey/traversal (0.00s)2068 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2069 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2070 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2071 --- PASS: TestIsValidUploadKey/index.html (0.00s)2072 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2073 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2074 --- PASS: TestIsValidUploadKey/build_log (0.00s)2075 --- PASS: TestIsValidUploadKey/listing (0.00s)2076 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2077 --- PASS: TestIsValidUploadKey/realisation (0.00s)2078 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2079 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2080 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2081 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2082 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2083=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20842026/10/01 07:36:39 INFO Received uploads request method=POST path=/20852026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.12ms)20862026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.3ms)20872026/10/01 07:36:39 OK 20260905000000_add_claims.sql (4.35ms)20882026/10/01 07:36:39 OK 3_commit_push.sql (2.4ms)20892026/10/01 07:36:39 goose: up to current file version: 320902026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.44ms)20912026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (2.71ms)20922026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)20932026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.62ms)20942026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000020952026/10/01 07:36:39 OK 20251218171726_add_pins.sql (3.94ms)20962026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.49ms)20972026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.33ms)20982026/10/01 07:36:39 OK 3_commit_push.sql (2.44ms)20992026/10/01 07:36:39 goose: up to current file version: 321002026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (5.24ms)21012026-10-01 07:36:39.913 UTC [974] ERROR: relation "goose_db_version" does not exist at character 3621022026-10-01 07:36:39.913 UTC [974] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21032026/10/01 07:36:39 OK 20260905000000_add_claims.sql (3.08ms)21042026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.85ms)21052026/10/01 07:36:39 INFO Received push request method=POST path=/api/pushes21062026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (2.48ms)21072026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000021082026/10/01 07:36:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21092026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.31ms)21102026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.6ms)21112026/10/01 07:36:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21122026/10/01 07:36:39 INFO Uploading nim6czxilpfwixlyl24203wbb5xli10c-test-file.txt (152B)21132026/10/01 07:36:39 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst2114--- PASS: TestCompleteMultipartUnregistered (0.48s)2115=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts21162026/10/01 07:36:39 INFO Received request for more parts method=POST path=/21172026/10/01 07:36:39 OK 3_commit_push.sql (1.28ms)21182026/10/01 07:36:39 goose: up to current file version: 321192026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.78ms)21202026/10/01 07:36:39 WARN Failed to register uploaded object key=nim6czxilpfwixlyl24203wbb5xli10c.ls error="server returned 404: 404 page not found\n"21212026/10/01 07:36:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21222026/10/01 07:36:39 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"21232026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)21242026-10-01 07:36:39.929 UTC [1004] ERROR: relation "goose_db_version" does not exist at character 3621252026-10-01 07:36:39.929 UTC [1004] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21262026/10/01 07:36:39 INFO Signed narinfos id=1 count=121272026/10/01 07:36:39 INFO Uploading 1 narinfos21282026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.34ms)21292026/10/01 07:36:39 INFO Received complete push request method=POST path=/api/pushes/1/complete21302026/10/01 07:36:39 WARN Failed to register uploaded object key=nim6czxilpfwixlyl24203wbb5xli10c.narinfo error="server returned 404: 404 page not found\n"21312026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (2.69ms)21322026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.41ms)21332026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.5ms)21342026/10/01 07:36:39 INFO Upload complete. (68ms)21352026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.62ms)21362026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000021372026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.92ms)21382026/10/01 07:36:39 OK 2_object_stats_trigger.sql (955.5µs)21392026-10-01 07:36:39.944 UTC [1022] ERROR: relation "goose_db_version" does not exist at character 3621402026-10-01 07:36:39.944 UTC [1022] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21412026/10/01 07:36:39 OK 20241026095416_initial_model.sql (9.42ms)21422026/10/01 07:36:39 OK 3_commit_push.sql (1.22ms)21432026/10/01 07:36:39 goose: up to current file version: 321442026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)21452026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.39ms)21462026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.8ms)21472026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.74ms)21482026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.88ms)21492026/10/01 07:36:39 OK 20241026095416_initial_model.sql (8.08ms)21502026/10/01 07:36:39 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)21512026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.89ms)21522026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000021532026/10/01 07:36:39 OK 20251218171726_add_pins.sql (2.31ms)21542026/10/01 07:36:39 OK 1_commit_pending_closure.sql (2.21ms)21552026/10/01 07:36:39 OK 2_object_stats_trigger.sql (1.26ms)21562026/10/01 07:36:39 OK 3_commit_push.sql (1.01ms)21572026/10/01 07:36:39 goose: up to current file version: 321582026/10/01 07:36:39 OK 20260628120000_add_object_size_and_stats.sql (3.29ms)21592026/10/01 07:36:39 OK 20260905000000_add_claims.sql (2.62ms)21602026/10/01 07:36:39 OK 20260920000000_drop_claims.sql (1.72ms)2161=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart21622026/10/01 07:36:39 INFO Received complete multipart upload request method=POST path=/21632026/10/01 07:36:39 OK 20260923120000_add_pushes.sql (1.65ms)21642026/10/01 07:36:39 goose: successfully migrated database to version: 2026092312000021652026/10/01 07:36:39 OK 1_commit_pending_closure.sql (1.71ms)21662026/10/01 07:36:39 OK 2_object_stats_trigger.sql (847.12µs)21672026/10/01 07:36:39 OK 3_commit_push.sql (1.23ms)21682026/10/01 07:36:39 goose: up to current file version: 321692026/10/01 07:36:39 INFO Received uploads request method=POST path=/api/pending_closures21702026/10/01 07:36:39 INFO All 1 paths already cached2171=== NAME TestClientIntegration2172 client_integration_test.go:312: Retrieved narinfo from S3:2173 StorePath: /build/TestClientIntegration833706745/002/store/nim6czxilpfwixlyl24203wbb5xli10c-test-file.txt2174 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2175 Compression: zstd2176 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12177 NarSize: 1522178 References: 2179 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12180 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2181 client_integration_test.go:313: Decompressed .ls content (64 bytes):2182 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2183 client_integration_test.go:316: Testing garbage collection...21842026-10-01 07:36:39.987 UTC [1093] ERROR: relation "goose_db_version" does not exist at character 3621852026-10-01 07:36:39.987 UTC [1093] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2186--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.39s)2187=== CONT TestIsValidCachePath/narinfo2188=== CONT TestIsValidCachePath/short_hash2189=== CONT TestIsValidCachePath/wrong_extension2190=== CONT TestIsValidCachePath/leading_slash2191=== CONT TestIsValidCachePath/empty2192=== CONT TestIsValidCachePath/random_path2193=== CONT TestIsValidCachePath/invalid_char_u2194=== CONT TestIsValidCachePath/invalid_char_e2195=== CONT TestIsValidCachePath/traversal_in_middle2196=== CONT TestIsValidCachePath/traversal_parent2197=== CONT TestIsValidCachePath/index.html2198=== CONT TestIsValidCachePath/nix-cache-info2199=== CONT TestIsValidCachePath/realisation2200=== CONT TestIsValidCachePath/log2201=== CONT TestIsValidCachePath/ls2202=== CONT TestIsValidCachePath/nar_uncompressed2203=== CONT TestIsValidCachePath/nar_bz22204=== CONT TestIsValidCachePath/nar_xz2205=== CONT TestIsValidCachePath/nar_zst2206=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2207--- PASS: TestIsValidCachePath (0.00s)2208 --- PASS: TestIsValidCachePath/narinfo (0.00s)2209 --- PASS: TestIsValidCachePath/short_hash (0.00s)2210 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2211 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2212 --- PASS: TestIsValidCachePath/empty (0.00s)2213 --- PASS: TestIsValidCachePath/random_path (0.00s)2214 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2215 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2216 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2217 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2218 --- PASS: TestIsValidCachePath/index.html (0.00s)2219 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2220 --- PASS: TestIsValidCachePath/realisation (0.00s)2221 --- PASS: TestIsValidCachePath/log (0.00s)2222 --- PASS: TestIsValidCachePath/ls (0.00s)2223 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2224 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2225 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2226 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2227 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2228=== CONT TestParseSingleRange/none2229=== CONT TestParseSingleRange/open-ended2230=== CONT TestParseSingleRange/start_far_past_EOF2231=== CONT TestParseSingleRange/start_past_EOF2232=== CONT TestParseSingleRange/single_byte2233=== CONT TestParseSingleRange/suffix_exceeds_size2234=== CONT TestParseSingleRange/suffix2235=== CONT TestParseSingleRange/end_clamped_to_size2236=== CONT TestParseSingleRange/malformed_both_empty2237=== CONT TestParseSingleRange/closed2238=== CONT TestParseSingleRange/malformed_end_before_start2239=== CONT TestParseSingleRange/unknown_unit2240=== CONT TestParseSingleRange/malformed_no_dash2241=== CONT TestParseSingleRange/multi-range_ignored2242--- PASS: TestParseSingleRange (0.00s)2243 --- PASS: TestParseSingleRange/none (0.00s)2244 --- PASS: TestParseSingleRange/open-ended (0.00s)2245 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2246 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2247 --- PASS: TestParseSingleRange/single_byte (0.00s)2248 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2249 --- PASS: TestParseSingleRange/suffix (0.00s)2250 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2251 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2252 --- PASS: TestParseSingleRange/closed (0.00s)2253 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2254 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2255 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2256 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2257=== CONT TestServerTLSConfig/no_client_CA2258=== CONT TestServerTLSConfig/not_a_PEM_file2259=== CONT TestServerTLSConfig/missing_CA_file2260--- PASS: TestServerTLSConfig (0.00s)2261 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2262 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2263 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2264=== CONT TestPush_RejectsBadRequests/no_roots22652026/10/01 07:36:39 INFO Received push request method=POST path=/api/pushes2266=== CONT TestPush_RejectsBadRequests/bad_root22672026/10/01 07:36:39 INFO Received push request method=POST path=/api/pushes2268=== CONT TestPush_RejectsBadRequests/root_not_in_objects22692026/10/01 07:36:39 INFO Received push request method=POST path=/api/pushes2270=== CONT TestPush_RejectsBadRequests/no_objects22712026/10/01 07:36:39 INFO Received push request method=POST path=/api/pushes2272=== CONT TestResolveDBConnectionString/flag_wins2273=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2274=== CONT TestResolveDBConnectionString/nothing_configured2275=== CONT TestResolveDBConnectionString/missing_file_is_an_error2276--- PASS: TestPush_RejectsBadRequests (0.75s)2277 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2278 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2279 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2280 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2281=== CONT TestResolveDBConnectionString/file_when_flag_empty2282=== CONT TestClientErrorHandling/InvalidStorePath2283--- PASS: TestResolveDBConnectionString (0.00s)2284 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2285 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2286 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2287 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2288 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)22892026/10/01 07:36:40 OK 20241026095416_initial_model.sql (8.21ms)22902026/10/01 07:36:40 OK 20251210153512_drop_unused_gin_index.sql (1.17ms)22912026/10/01 07:36:40 INFO lead: released remote=192.0.2.1:123422922026/10/01 07:36:40 OK 20251218171726_add_pins.sql (4.33ms)2293=== CONT TestClientErrorHandling/ServerNotAvailable22942026/10/01 07:36:40 OK 20260628120000_add_object_size_and_stats.sql (4.81ms)22952026/10/01 07:36:40 OK 20260905000000_add_claims.sql (2.41ms)22962026/10/01 07:36:40 OK 20260920000000_drop_claims.sql (1.97ms)22972026/10/01 07:36:40 OK 20260923120000_add_pushes.sql (2.63ms)22982026/10/01 07:36:40 goose: successfully migrated database to version: 2026092312000022992026/10/01 07:36:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures23002026/10/01 07:36:40 INFO Garbage collection started23012026/10/01 07:36:40 OK 1_commit_pending_closure.sql (1.46ms)23022026/10/01 07:36:40 OK 2_object_stats_trigger.sql (654.05µs)23032026/10/01 07:36:40 OK 3_commit_push.sql (871.72µs)23042026/10/01 07:36:40 goose: up to current file version: 323052026/10/01 07:36:40 INFO Aborted multipart uploads count=02306--- PASS: TestService_ReadAuthMiddleware (0.40s)2307=== CONT TestClientErrorHandling/InvalidAuthToken2308=== NAME TestPinProtectsFromGC23092026/10/01 07:36:40 WARN Force mode enabled - objects will be deleted immediately without grace period2310 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2318396334/001/store/nd329ln3hxcpc5b418n8aai354fvma4z-pinned-file.txt2311 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2318396334/001/store/wm4lv2w69514ljqz8w0cnkdrw74k5v2m-unpinned-file.txt2312--- PASS: TestGCBugBareHashReferences (0.78s)2313=== CONT TestCacheConfigHandler/full_config,_no_issuer23142026/10/01 07:36:40 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=02315=== CONT TestCacheConfigHandler/no_signing_keys2316=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2317=== CONT TestCacheConfigHandler/no_cache_url_configured2318--- PASS: TestCacheConfigHandler (0.00s)2319 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2320 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2321 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2322 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)23232026/10/01 07:36:40 INFO Vacuumed table table=pending_closures2324--- PASS: TestService_ReadScope_PublicByDefault (0.42s)23252026/10/01 07:36:40 INFO Vacuumed table table=pending_objects23262026/10/01 07:36:40 INFO Vacuumed table table=multipart_uploads23272026/10/01 07:36:40 INFO lead: acquired remote=192.0.2.1:123423282026/10/01 07:36:40 INFO Vacuumed table table=closures2329=== NAME TestClientMultipleUploads2330 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads412988848/001/store/70152cvj4mpawkksg5s5hc9rjj5gjl00-test-file-0.txt23312026/10/01 07:36:40 INFO Vacuumed table table=objects23322026/10/01 07:36:40 INFO lead: released remote=192.0.2.1:12342333--- PASS: TestLeadElectsOneAndHandsOver (0.76s)23342026/10/01 07:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23352026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures23362026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures23372026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures23382026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures2339=== NAME TestClientMultipleUploads2340 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads412988848/001/store/xx12xwb9fdafh6ja67m9l5lmqv59f3wa-test-file-1.txt23412026-10-01 07:36:40.096 UTC [1398] ERROR: relation "goose_db_version" does not exist at character 3623422026-10-01 07:36:40.096 UTC [1398] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23432026/10/01 07:36:40 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MWZlM2FjZTItZmRiNi00OTdlLTgwYTItMjI2NjBjZmFkMGRjLmNhNTA4NzRlLTdmYzYtNGVmZi05NjQ2LWRmMjNmNmU1MjY2N3gxNzkwODQwMTk5NzgyNDg4OTY0 parts=1023442026/10/01 07:36:40 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/present23452026/10/01 07:36:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23462026/10/01 07:36:40 INFO Completed upload id=123472026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures23482026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures23492026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures2350=== NAME TestClientWithDependencies2351 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2142448754/001/store/z2838hng09hx5x17w5am4h35jg6m0vbd-test-script23522026/10/01 07:36:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23532026/10/01 07:36:40 INFO Uploading f7s201v1nwc3zxmj9ygia798c520bdyc-a (216B)23542026/10/01 07:36:40 INFO Uploading h0s438zv5vhmazkws3l60j6cwg6llv2r-shared-dep (136B)23552026/10/01 07:36:40 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo23562026/10/01 07:36:40 WARN Found objects in DB but missing from S3, will re-upload count=12357--- PASS: TestService_verifyS3Integrity (0.89s)23582026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes23592026/10/01 07:36:40 WARN Failed to register uploaded object key=9zzdc3ivsn27r42aw4nvlnhr51a6czw3.ls error="server returned 404: 404 page not found\n"23602026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23612026/10/01 07:36:40 WARN Failed to register uploaded object key=h0s438zv5vhmazkws3l60j6cwg6llv2r.ls error="server returned 404: 404 page not found\n"23622026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1n9yr1632b8bsny0wrv4nbh271kkpjgi2jgq7apzhsbcmcynjaq8.nar.zst error="server returned 404: 404 page not found\n"23632026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign2364--- PASS: TestCacheStatsHandler (0.34s)23652026/10/01 07:36:40 WARN Failed to register uploaded object key=f7s201v1nwc3zxmj9ygia798c520bdyc.ls error="server returned 404: 404 page not found\n"23662026/10/01 07:36:40 INFO Signed narinfos id=1 count=223672026/10/01 07:36:40 OK 20241026095416_initial_model.sql (8.03ms)23682026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign23692026/10/01 07:36:40 INFO Signed narinfos id=2 count=223702026/10/01 07:36:40 INFO Uploading 4 narinfos23712026/10/01 07:36:40 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)23722026/10/01 07:36:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23732026/10/01 07:36:40 INFO Uploading nd329ln3hxcpc5b418n8aai354fvma4z-pinned-file.txt (128B)23742026/10/01 07:36:40 WARN Failed to register uploaded object key=f7s201v1nwc3zxmj9ygia798c520bdyc.narinfo error="server returned 404: 404 page not found\n"23752026/10/01 07:36:40 OK 20251218171726_add_pins.sql (2.41ms)23762026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes23772026/10/01 07:36:40 WARN Failed to register uploaded object key=9zzdc3ivsn27r42aw4nvlnhr51a6czw3.narinfo error="server returned 404: 404 page not found\n"23782026/10/01 07:36:40 WARN Failed to register uploaded object key=h0s438zv5vhmazkws3l60j6cwg6llv2r.narinfo error="server returned 404: 404 page not found\n"23792026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"23802026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23812026/10/01 07:36:40 WARN Failed to register uploaded object key=nd329ln3hxcpc5b418n8aai354fvma4z.ls error="server returned 404: 404 page not found\n"23822026/10/01 07:36:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23832026/10/01 07:36:40 WARN Failed to register uploaded object key=h0s438zv5vhmazkws3l60j6cwg6llv2r.narinfo error="server returned 404: 404 page not found\n"23842026/10/01 07:36:40 INFO Signed narinfos id=1 count=123852026/10/01 07:36:40 INFO Uploading 1 narinfos23862026/10/01 07:36:40 OK 20260628120000_add_object_size_and_stats.sql (3.1ms)23872026/10/01 07:36:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23882026/10/01 07:36:40 INFO Uploading wchi8kh1jlzydbazv10qw9y0dv9k5d5k-shared-dep (136B)23892026/10/01 07:36:40 WARN Failed to register uploaded object key=nd329ln3hxcpc5b418n8aai354fvma4z.narinfo error="server returned 404: 404 page not found\n"23902026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete23912026/10/01 07:36:40 OK 20260905000000_add_claims.sql (2.29ms)23922026/10/01 07:36:40 INFO Uploading yjn4hr48f1iss7kv6ln7y040c5c6aisv-a (216B)23932026/10/01 07:36:40 OK 20260920000000_drop_claims.sql (1.54ms)23942026/10/01 07:36:40 INFO Completed upload id=123952026/10/01 07:36:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete23962026/10/01 07:36:40 WARN Failed to register uploaded object key=sfjnpnywrm21pvf7w6hh0i3aph4l3gjc.ls error="server returned 404: 404 page not found\n"23972026/10/01 07:36:40 OK 20260923120000_add_pushes.sql (1.05ms)23982026/10/01 07:36:40 goose: successfully migrated database to version: 2026092312000023992026/10/01 07:36:40 INFO Completed upload id=224002026/10/01 07:36:40 INFO Upload complete. (69ms)2401=== RUN TestService_RequireScope_OIDC/builder_may_write24022026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"2403=== PAUSE TestService_RequireScope_OIDC/builder_may_write2404=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2405=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2406=== RUN TestService_RequireScope_OIDC/ops_may_admin2407=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2408=== RUN TestService_RequireScope_OIDC/ops_may_not_write2409=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2410=== RUN TestService_RequireScope_OIDC/reader_may_not_write2411=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2412=== RUN TestService_RequireScope_OIDC/static_token_may_admin24132026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1xpvd3azf0hznl8fkd03rqb1jidsggv0ndkw8kjh96ljfycv7ja5.nar.zst error="server returned 404: 404 page not found\n"2414=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2415=== RUN TestService_RequireScope_OIDC/static_token_may_write2416=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2417=== RUN TestService_RequireScope_OIDC/reader_may_read2418=== PAUSE TestService_RequireScope_OIDC/reader_may_read2419=== RUN TestService_RequireScope_OIDC/writer_implies_read2420=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2421=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2422=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2423=== NAME TestClientFallsBackToClosures24242026/10/01 07:36:40 WARN Failed to register uploaded object key=wchi8kh1jlzydbazv10qw9y0dv9k5d5k.ls error="server returned 404: 404 page not found\n"2425 client_pushes_test.go:112: Retrieved narinfo from S3:24262026/10/01 07:36:40 OK 1_commit_pending_closure.sql (1.53ms)2427 StorePath: /build/TestClientFallsBackToClosures1178886094/001/store/h0s438zv5vhmazkws3l60j6cwg6llv2r-shared-dep2428 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2429 Compression: zstd2430 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y8224312026/10/01 07:36:40 WARN Failed to register uploaded object key=yjn4hr48f1iss7kv6ln7y040c5c6aisv.ls error="server returned 404: 404 page not found\n"2432 NarSize: 13624332026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2434 References: 2435 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2436=== CONT TestService_RequireScope_OIDC/builder_may_write24372026/10/01 07:36:40 INFO Upload complete. (56ms)2438=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read24392026/10/01 07:36:40 OK 2_object_stats_trigger.sql (533.59µs)2440=== CONT TestService_RequireScope_OIDC/reader_may_not_write24412026/10/01 07:36:40 INFO Signed narinfos id=1 count=32442=== CONT TestService_RequireScope_OIDC/writer_implies_read2443=== CONT TestService_RequireScope_OIDC/reader_may_read24442026/10/01 07:36:40 INFO Uploading 3 narinfos2445=== CONT TestService_RequireScope_OIDC/ops_may_admin2446=== CONT TestService_RequireScope_OIDC/static_token_may_write2447=== CONT TestService_RequireScope_OIDC/static_token_may_admin2448=== CONT TestService_RequireScope_OIDC/ops_may_not_write2449=== CONT TestService_RequireScope_OIDC/builder_may_not_admin24502026/10/01 07:36:40 OK 3_commit_push.sql (525.75µs)24512026/10/01 07:36:40 goose: up to current file version: 32452--- PASS: TestService_RequireScope_OIDC (0.41s)2453 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2454 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2455 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2456 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2457 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2458 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2459 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2460 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2461 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2462 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2463=== NAME TestClientFallsBackToClosures2464 client_pushes_test.go:112: Retrieved narinfo from S3:2465 StorePath: /build/TestClientFallsBackToClosures1178886094/001/store/f7s201v1nwc3zxmj9ygia798c520bdyc-a2466 URL: nar/1n9yr1632b8bsny0wrv4nbh271kkpjgi2jgq7apzhsbcmcynjaq8.nar.zst2467 Compression: zstd2468 NarHash: sha256:1n9yr1632b8bsny0wrv4nbh271kkpjgi2jgq7apzhsbcmcynjaq82469 NarSize: 2162470 References: /build/TestClientFallsBackToClosures1178886094/001/store/h0s438zv5vhmazkws3l60j6cwg6llv2r-shared-dep2471 CA: text:sha256:13wm4y6n2gvy4bjqc0i4nh3hwc1l7hryxlm65vk43z7p881iwpam24722026/10/01 07:36:40 WARN Failed to register uploaded object key=yjn4hr48f1iss7kv6ln7y040c5c6aisv.narinfo error="server returned 404: 404 page not found\n"24732026/10/01 07:36:40 WARN Failed to register uploaded object key=sfjnpnywrm21pvf7w6hh0i3aph4l3gjc.narinfo error="server returned 404: 404 page not found\n"2474 client_pushes_test.go:112: Retrieved narinfo from S3:24752026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete2476 StorePath: /build/TestClientFallsBackToClosures1178886094/001/store/9zzdc3ivsn27r42aw4nvlnhr51a6czw3-b2477 URL: nar/1n9yr1632b8bsny0wrv4nbh271kkpjgi2jgq7apzhsbcmcynjaq8.nar.zst24782026/10/01 07:36:40 WARN Failed to register uploaded object key=wchi8kh1jlzydbazv10qw9y0dv9k5d5k.narinfo error="server returned 404: 404 page not found\n"2479 Compression: zstd2480 NarHash: sha256:1n9yr1632b8bsny0wrv4nbh271kkpjgi2jgq7apzhsbcmcynjaq82481 NarSize: 2162482 References: /build/TestClientFallsBackToClosures1178886094/001/store/h0s438zv5vhmazkws3l60j6cwg6llv2r-shared-dep2483 CA: text:sha256:13wm4y6n2gvy4bjqc0i4nh3hwc1l7hryxlm65vk43z7p881iwpam24842026-10-01 07:36:40.130 UTC [1474] ERROR: relation "goose_db_version" does not exist at character 3624852026-10-01 07:36:40.130 UTC [1474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2486=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2487=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2488=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2489=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2490=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2491=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2492=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2493=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2494=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2495=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected24962026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes2497=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured24982026/10/01 07:36:40 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]2499=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2500--- PASS: TestClientFallsBackToClosures (0.81s)25012026/10/01 07:36:40 INFO Upload complete. (60ms)25022026/10/01 07:36:40 WARN Authentication failed token_preview=eyJhbGciOi...J_AUe9wm2A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2503--- PASS: TestService_AuthMiddleware_OIDC (0.41s)2504 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2505 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2506 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2507 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2508=== NAME TestClientPushesUseOnePush2509 client_pushes_test.go:97: Retrieved narinfo from S3:2510 StorePath: /build/TestClientPushesUseOnePush2980956852/001/store/wchi8kh1jlzydbazv10qw9y0dv9k5d5k-shared-dep2511 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2512 Compression: zstd2513 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822514 NarSize: 1362515 References: 2516 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n25172026/10/01 07:36:40 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)25182026/10/01 07:36:40 INFO Uploading fbzl2crll18z8s1y20y2d8x3vsa6mkm8-top (224B)2519 client_pushes_test.go:97: Retrieved narinfo from S3:25202026/10/01 07:36:40 INFO Uploading nv5w3r1achbra5drja9w54zcwl4rmmdj-shared-dep (136B)2521 StorePath: /build/TestClientPushesUseOnePush2980956852/001/store/yjn4hr48f1iss7kv6ln7y040c5c6aisv-a2522 URL: nar/1xpvd3azf0hznl8fkd03rqb1jidsggv0ndkw8kjh96ljfycv7ja5.nar.zst2523 Compression: zstd2524 NarHash: sha256:1xpvd3azf0hznl8fkd03rqb1jidsggv0ndkw8kjh96ljfycv7ja52525 NarSize: 2162526 References: /build/TestClientPushesUseOnePush2980956852/001/store/wchi8kh1jlzydbazv10qw9y0dv9k5d5k-shared-dep2527 CA: text:sha256:0mzmgvhknxhc89sr5nwi6rki8ad3rnv1s71ymdlzmjdvskxil5na2528=== NAME TestClientMultipleUploads2529 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads412988848/001/store/0dz2z1042fzmcsb18g4p3mflqaibad45-test-file-2.txt2530=== NAME TestClientWithDependencies2531 client_integration_test.go:615: Found 1 dependencies (including self)2532=== NAME TestClientPushesUseOnePush2533 client_pushes_test.go:97: Retrieved narinfo from S3:2534 StorePath: /build/TestClientPushesUseOnePush2980956852/001/store/sfjnpnywrm21pvf7w6hh0i3aph4l3gjc-b2535 URL: nar/1xpvd3azf0hznl8fkd03rqb1jidsggv0ndkw8kjh96ljfycv7ja5.nar.zst2536 Compression: zstd2537 NarHash: sha256:1xpvd3azf0hznl8fkd03rqb1jidsggv0ndkw8kjh96ljfycv7ja52538 NarSize: 2162539 References: /build/TestClientPushesUseOnePush2980956852/001/store/wchi8kh1jlzydbazv10qw9y0dv9k5d5k-shared-dep2540 CA: text:sha256:0mzmgvhknxhc89sr5nwi6rki8ad3rnv1s71ymdlzmjdvskxil5na25412026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/0m1aw364zy8vwfgzz4vcix9cq86ib07274ma38qfxi00kagqbhvm.nar.zst error="server returned 404: 404 page not found\n"25422026/10/01 07:36:40 WARN Failed to register uploaded object key=fbzl2crll18z8s1y20y2d8x3vsa6mkm8.ls error="server returned 404: 404 page not found\n"25432026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"25442026/10/01 07:36:40 OK 20241026095416_initial_model.sql (7.09ms)25452026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25462026/10/01 07:36:40 WARN Failed to register uploaded object key=nv5w3r1achbra5drja9w54zcwl4rmmdj.ls error="server returned 404: 404 page not found\n"25472026/10/01 07:36:40 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)25482026/10/01 07:36:40 INFO Signed narinfos id=1 count=225492026/10/01 07:36:40 INFO Uploading 2 narinfos25502026/10/01 07:36:40 OK 20251218171726_add_pins.sql (2.55ms)25512026/10/01 07:36:40 WARN Failed to register uploaded object key=fbzl2crll18z8s1y20y2d8x3vsa6mkm8.narinfo error="server returned 404: 404 page not found\n"25522026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete25532026/10/01 07:36:40 WARN Failed to register uploaded object key=nv5w3r1achbra5drja9w54zcwl4rmmdj.narinfo error="server returned 404: 404 page not found\n"2554--- PASS: TestClientPushesUseOnePush (0.73s)25552026/10/01 07:36:40 OK 20260628120000_add_object_size_and_stats.sql (2.35ms)25562026/10/01 07:36:40 OK 20260905000000_add_claims.sql (2.19ms)25572026/10/01 07:36:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"25582026/10/01 07:36:40 WARN mTLS auth: bound subjects configured but subject DN unavailable25592026/10/01 07:36:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2560--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.32s)25612026/10/01 07:36:40 OK 20260920000000_drop_claims.sql (1.45ms)25622026/10/01 07:36:40 INFO Upload complete. (65ms)2563=== NAME TestClientSharedPathCommittedMidPush25642026/10/01 07:36:40 OK 20260923120000_add_pushes.sql (1.07ms)2565 client_integration_test.go:680: Retrieved narinfo from S3:25662026/10/01 07:36:40 goose: successfully migrated database to version: 202609231200002567 StorePath: /build/TestClientSharedPathCommittedMidPush212210855/001/store/nv5w3r1achbra5drja9w54zcwl4rmmdj-shared-dep2568 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2569 Compression: zstd2570 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822571 NarSize: 1362572 References: 2573 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n25742026/10/01 07:36:40 OK 1_commit_pending_closure.sql (1.41ms)2575 client_integration_test.go:680: Retrieved narinfo from S3:25762026/10/01 07:36:40 OK 2_object_stats_trigger.sql (805.65µs)2577 StorePath: /build/TestClientSharedPathCommittedMidPush212210855/001/store/fbzl2crll18z8s1y20y2d8x3vsa6mkm8-top2578 URL: nar/0m1aw364zy8vwfgzz4vcix9cq86ib07274ma38qfxi00kagqbhvm.nar.zst2579 Compression: zstd2580 NarHash: sha256:0m1aw364zy8vwfgzz4vcix9cq86ib07274ma38qfxi00kagqbhvm2581 NarSize: 2242582 References: /build/TestClientSharedPathCommittedMidPush212210855/001/store/nv5w3r1achbra5drja9w54zcwl4rmmdj-shared-dep2583 CA: text:sha256:1szq5wiicbhzpg3jydn8igk1ffnbkf85j424dayqws6nqc86lzp625842026/10/01 07:36:40 OK 3_commit_push.sql (539.54µs)25852026/10/01 07:36:40 goose: up to current file version: 32586--- PASS: TestClientSharedPathCommittedMidPush (0.64s)2587--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.29s)2588=== NAME TestClientCADerivations2589 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3208065622/001/store/4x73zq6pgv3c7g0djmqm3sa4mq6m5j26-ca-test25902026/10/01 07:36:40 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=203.382374ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2591 client_ca_test.go:139: Found 1 dependencies (including self)25922026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes25932026/10/01 07:36:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25942026/10/01 07:36:40 INFO Uploading wm4lv2w69514ljqz8w0cnkdrw74k5v2m-unpinned-file.txt (128B)25952026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes25962026/10/01 07:36:40 WARN Failed to register uploaded object key=wm4lv2w69514ljqz8w0cnkdrw74k5v2m.ls error="server returned 404: 404 page not found\n"25972026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign25982026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"25992026/10/01 07:36:40 INFO Signed narinfos id=2 count=126002026/10/01 07:36:40 INFO Uploading 1 narinfos26012026/10/01 07:36:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26022026/10/01 07:36:40 INFO Uploading z2838hng09hx5x17w5am4h35jg6m0vbd-test-script (136B)26032026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/2/complete26042026/10/01 07:36:40 WARN Failed to register uploaded object key=wm4lv2w69514ljqz8w0cnkdrw74k5v2m.narinfo error="server returned 404: 404 page not found\n"26052026/10/01 07:36:40 INFO Upload complete. (53ms)26062026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes26072026/10/01 07:36:40 WARN Failed to register uploaded object key=log/4f5d7n374kz0hvcfw29qw52cnj4n7w4j-test-script.drv error="server returned 404: 404 page not found\n"26082026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"26092026/10/01 07:36:40 WARN Failed to register uploaded object key=z2838hng09hx5x17w5am4h35jg6m0vbd.ls error="server returned 404: 404 page not found\n"26102026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26112026/10/01 07:36:40 INFO Signed narinfos id=1 count=126122026/10/01 07:36:40 INFO Uploading 1 narinfos26132026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete26142026/10/01 07:36:40 WARN Failed to register uploaded object key=z2838hng09hx5x17w5am4h35jg6m0vbd.narinfo error="server returned 404: 404 page not found\n"26152026/10/01 07:36:40 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)26162026/10/01 07:36:40 INFO Uploading 0dz2z1042fzmcsb18g4p3mflqaibad45-test-file-2.txt (160B)26172026/10/01 07:36:40 INFO Uploading xx12xwb9fdafh6ja67m9l5lmqv59f3wa-test-file-1.txt (160B)26182026/10/01 07:36:40 INFO Uploading 70152cvj4mpawkksg5s5hc9rjj5gjl00-test-file-0.txt (160B)26192026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"26202026/10/01 07:36:40 WARN Failed to register uploaded object key=xx12xwb9fdafh6ja67m9l5lmqv59f3wa.ls error="server returned 404: 404 page not found\n"26212026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"26222026/10/01 07:36:40 WARN Failed to register uploaded object key=70152cvj4mpawkksg5s5hc9rjj5gjl00.ls error="server returned 404: 404 page not found\n"26232026/10/01 07:36:40 INFO Upload complete. (54ms)26242026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"26252026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26262026/10/01 07:36:40 WARN Failed to register uploaded object key=0dz2z1042fzmcsb18g4p3mflqaibad45.ls error="server returned 404: 404 page not found\n"26272026/10/01 07:36:40 INFO Signed narinfos id=1 count=326282026/10/01 07:36:40 INFO Uploading 3 narinfos2629=== NAME TestClientWithDependencies2630 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2142448754/001/store) requires matching store prefix26312026/10/01 07:36:40 WARN Failed to register uploaded object key=xx12xwb9fdafh6ja67m9l5lmqv59f3wa.narinfo error="server returned 404: 404 page not found\n"26322026/10/01 07:36:40 WARN Failed to register uploaded object key=70152cvj4mpawkksg5s5hc9rjj5gjl00.narinfo error="server returned 404: 404 page not found\n"26332026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete2634--- PASS: TestClientWithDependencies (0.62s)26352026/10/01 07:36:40 WARN Failed to register uploaded object key=0dz2z1042fzmcsb18g4p3mflqaibad45.narinfo error="server returned 404: 404 page not found\n"26362026/10/01 07:36:40 INFO Upload complete. (75ms)2637=== NAME TestClientMultipleUploads2638 client_integration_test.go:369: Uploaded 3 paths in 111.109696ms2639--- PASS: TestClientMultipleUploads (0.64s)26402026/10/01 07:36:40 INFO Received create pin request method=POST path=/api/pins/myapp26412026/10/01 07:36:40 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2318396334/001/store/nd329ln3hxcpc5b418n8aai354fvma4z-pinned-file.txt narinfo_key=nd329ln3hxcpc5b418n8aai354fvma4z.narinfo26422026/10/01 07:36:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures26432026/10/01 07:36:40 INFO Garbage collection started26442026/10/01 07:36:40 INFO Aborted multipart uploads count=026452026/10/01 07:36:40 WARN Force mode enabled - objects will be deleted immediately without grace period26462026/10/01 07:36:40 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=026472026/10/01 07:36:40 INFO Vacuumed table table=pending_closures26482026/10/01 07:36:40 INFO Vacuumed table table=pending_objects26492026/10/01 07:36:40 INFO Vacuumed table table=multipart_uploads26502026/10/01 07:36:40 INFO Vacuumed table table=closures26512026/10/01 07:36:40 INFO Vacuumed table table=objects26522026/10/01 07:36:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"26532026/10/01 07:36:40 INFO Received push request method=POST path=/api/pushes26542026/10/01 07:36:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26552026/10/01 07:36:40 INFO Uploading 4x73zq6pgv3c7g0djmqm3sa4mq6m5j26-ca-test (144B)26562026/10/01 07:36:40 WARN Failed to register uploaded object key=4x73zq6pgv3c7g0djmqm3sa4mq6m5j26.ls error="server returned 404: 404 page not found\n"26572026/10/01 07:36:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"26582026/10/01 07:36:40 WARN Failed to register uploaded object key=log/frf2q9spfxq48f0i5i1vyknmvgvvlcxz-ca-test.drv error="server returned 404: 404 page not found\n"26592026/10/01 07:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26602026/10/01 07:36:40 INFO Signed narinfos id=1 count=126612026/10/01 07:36:40 INFO Uploading 1 narinfos26622026/10/01 07:36:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"26632026/10/01 07:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete26642026/10/01 07:36:40 WARN Failed to register uploaded object key=4x73zq6pgv3c7g0djmqm3sa4mq6m5j26.narinfo error="server returned 404: 404 page not found\n"26652026/10/01 07:36:40 INFO Upload complete. (96ms)2666=== NAME TestClientCADerivations2667 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3208065622/001/store/4x73zq6pgv3c7g0djmqm3sa4mq6m5j26-ca-test2668 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2669 Compression: zstd2670 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2671 NarSize: 1442672 References: 2673 Deriver: /build/TestClientCADerivations3208065622/001/store/frf2q9spfxq48f0i5i1vyknmvgvvlcxz-ca-test.drv2674 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2675 client_ca_test.go:185: Checking for realisation files in S3...2676 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2677 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache26782026/10/01 07:36:40 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=373.127589ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2679--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2680 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2681 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2682 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.61s)26832026/10/01 07:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2684=== NAME TestClientCADerivations2685 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2686 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2687 error: binary cache 's3://bucket63?endpoint=http://localhost:45685®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3208065622/001/store'2688 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12689--- PASS: TestClientCADerivations (0.78s)26902026/10/01 07:36:40 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MWZlM2FjZTItZmRiNi00OTdlLTgwYTItMjI2NjBjZmFkMGRjLjVhMThkYmY1LTcyNDMtNGQ0NS05ZDU3LWUwZmM5ZjIxNmRhM3gxNzkwODQwMjAwMDkwODcxMzMz parts=1026912026/10/01 07:36:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete26922026/10/01 07:36:40 INFO Completed upload id=126932026/10/01 07:36:40 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000026942026/10/01 07:36:40 INFO Received uploads request method=POST path=/api/pending_closures26952026/10/01 07:36:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures26962026/10/01 07:36:40 INFO Aborted multipart uploads count=026972026/10/01 07:36:40 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=026982026/10/01 07:36:40 INFO Vacuumed table table=pending_closures26992026/10/01 07:36:40 INFO Vacuumed table table=pending_objects27002026/10/01 07:36:40 INFO Vacuumed table table=multipart_uploads27012026/10/01 07:36:40 INFO Vacuumed table table=closures27022026/10/01 07:36:40 INFO Vacuumed table table=objects27032026/10/01 07:36:40 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002704--- PASS: TestService_createPendingClosureHandler (0.82s)2705=== NAME TestOrphanedObjectsGCStressTest2706 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2707 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion27082026/10/01 07:36:40 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=776.194691ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2709 orphaned_objects_gc_test.go:509: Stress test completed successfully:2710 orphaned_objects_gc_test.go:510: - Active objects preserved: 202711 orphaned_objects_gc_test.go:511: - Objects deleted: 2102712 orphaned_objects_gc_test.go:512: - Total GC'd: 2102713--- PASS: TestOrphanedObjectsGCStressTest (2.02s)27142026/10/01 07:36:41 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.755149513s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27152026/10/01 07:36:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02716=== NAME TestClientIntegration2717 client_integration_test.go:323: Objects in database after GC:2718 client_integration_test.go:323: Successfully deleted all objects with GC --force2719--- PASS: TestClientIntegration (2.79s)27202026/10/01 07:36:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02721=== NAME TestPinProtectsFromGC2722 client_integration_test.go:794: Pin successfully protected closure from garbage collection2723--- PASS: TestPinProtectsFromGC (2.80s)27242026/10/01 07:36:43 WARN Rate limiter enabled after throttle name=s3-test rate=527252026/10/01 07:36:43 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2726=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2727 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102728 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002729--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.92s)27302026/10/01 07:36:43 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-config27312026/10/01 07:36:43 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.100503ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27322026/10/01 07:36:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.96721ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27332026/10/01 07:36:44 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=835.416779ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27342026/10/01 07:36:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.614385609s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27352026/10/01 07:36:46 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"27362026/10/01 07:36:46 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-config27372026/10/01 07:36:46 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.884525ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27382026/10/01 07:36:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=426.552376ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27392026/10/01 07:36:47 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=874.21909ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27402026/10/01 07:36:48 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.670255916s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27412026/10/01 07:36:49 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_closures27422026/10/01 07:36:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=205.189509ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27432026/10/01 07:36:50 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=365.146844ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27442026/10/01 07:36:50 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=794.800153ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27452026/10/01 07:36:51 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.713410747s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2746--- PASS: TestClientErrorHandling (0.00s)2747 --- PASS: TestClientErrorHandling/InvalidStorePath (0.22s)2748 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.32s)2749 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.97s)2750PASS2751{"timestamp":"2026-10-01T07:36:52.9796522Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51190","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(396)"}27522026-10-01 07:36:53.357 UTC [128] LOG: received smart shutdown request27532026-10-01 07:36:53.361 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 127542026-10-01 07:36:53.374 UTC [133] LOG: shutting down27552026-10-01 07:36:53.375 UTC [133] LOG: checkpoint starting: shutdown immediate27562026-10-01 07:36:54.108 UTC [133] LOG: checkpoint complete: wrote 10393 buffers (63.4%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 20 recycled; write=0.316 s, sync=0.380 s, total=0.734 s; sync files=23917, longest=0.009 s, average=0.001 s; distance=325410 kB, estimate=325410 kB; lsn=0/1552E5B8, redo lsn=0/1552E5B827572026-10-01 07:36:54.187 UTC [128] LOG: database system is shut down2758Running OIDC tests...2759=== RUN TestAudienceForIssuer2760=== PAUSE TestAudienceForIssuer2761=== RUN TestGlobMatch2762=== PAUSE TestGlobMatch2763=== RUN TestValidateToken_ValidToken2764=== PAUSE TestValidateToken_ValidToken2765=== RUN TestValidateToken_WrongAudience2766=== PAUSE TestValidateToken_WrongAudience2767=== RUN TestValidateToken_Expired2768=== PAUSE TestValidateToken_Expired2769=== RUN TestValidateToken_BoundClaimsMismatch2770=== PAUSE TestValidateToken_BoundClaimsMismatch2771=== RUN TestValidateToken_BoundSubjectMismatch2772=== PAUSE TestValidateToken_BoundSubjectMismatch2773=== RUN TestValidateToken_MultipleProviders2774=== PAUSE TestValidateToken_MultipleProviders2775=== RUN TestValidateToken_NoMatchingProvider2776=== PAUSE TestValidateToken_NoMatchingProvider2777=== RUN TestValidateToken_KubernetesServiceAccount2778=== PAUSE TestValidateToken_KubernetesServiceAccount2779=== RUN TestNewValidator_KubernetesRequiresCA2780=== PAUSE TestNewValidator_KubernetesRequiresCA2781=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2782=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2783=== RUN TestPins_ReservedForMatchingRule2784=== PAUSE TestPins_ReservedForMatchingRule2785=== RUN TestPins_TopLevelShorthand2786=== PAUSE TestPins_TopLevelShorthand2787=== RUN TestPins_ConfigValidation2788=== PAUSE TestPins_ConfigValidation2789=== RUN TestScopes_LegacyProviderDefaultsToWrite2790=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2791=== RUN TestScopes_Rules2792=== PAUSE TestScopes_Rules2793=== RUN TestScopes_ConfigValidation2794=== PAUSE TestScopes_ConfigValidation2795=== CONT TestAudienceForIssuer2796=== CONT TestValidateToken_KubernetesServiceAccount2797=== CONT TestValidateToken_BoundClaimsMismatch2798=== CONT TestValidateToken_BoundSubjectMismatch2799=== CONT TestValidateToken_NoMatchingProvider2800=== CONT TestValidateToken_WrongAudience2801=== CONT TestValidateToken_Expired2802=== CONT TestPins_ConfigValidation2803=== CONT TestScopes_ConfigValidation2804=== CONT TestScopes_Rules2805=== CONT TestScopes_LegacyProviderDefaultsToWrite2806=== CONT TestValidateToken_ValidToken2807=== CONT TestPins_ReservedForMatchingRule2808=== CONT TestPins_TopLevelShorthand2809=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2810=== CONT TestGlobMatch2811=== RUN TestGlobMatch/foo_foo2812=== PAUSE TestGlobMatch/foo_foo2813=== RUN TestGlobMatch/foo_bar2814=== PAUSE TestGlobMatch/foo_bar2815=== RUN TestGlobMatch/*_2816=== PAUSE TestGlobMatch/*_2817=== RUN TestGlobMatch/*_anything2818=== PAUSE TestGlobMatch/*_anything2819=== RUN TestGlobMatch/foo*_foo2820=== CONT TestNewValidator_KubernetesRequiresCA2821--- PASS: TestAudienceForIssuer (0.00s)2822=== CONT TestValidateToken_MultipleProviders2823=== PAUSE TestGlobMatch/foo*_foo2824=== RUN TestGlobMatch/foo*_foobar2825=== PAUSE TestGlobMatch/foo*_foobar2826--- PASS: TestPins_ConfigValidation (0.00s)2827--- PASS: TestScopes_ConfigValidation (0.00s)2828=== RUN TestGlobMatch/foo*_bar2829=== PAUSE TestGlobMatch/foo*_bar2830=== RUN TestGlobMatch/*bar_bar2831=== PAUSE TestGlobMatch/*bar_bar2832=== RUN TestGlobMatch/*bar_foobar2833=== PAUSE TestGlobMatch/*bar_foobar2834=== RUN TestGlobMatch/*bar_foo2835=== PAUSE TestGlobMatch/*bar_foo2836=== RUN TestGlobMatch/foo*bar_foobar2837=== PAUSE TestGlobMatch/foo*bar_foobar2838=== RUN TestGlobMatch/foo*bar_foo123bar2839=== PAUSE TestGlobMatch/foo*bar_foo123bar2840=== RUN TestGlobMatch/foo*bar_foobarbaz2841=== PAUSE TestGlobMatch/foo*bar_foobarbaz2842=== RUN TestGlobMatch/*/*_foo/bar2843=== PAUSE TestGlobMatch/*/*_foo/bar2844=== RUN TestGlobMatch/*/*_foo2845=== PAUSE TestGlobMatch/*/*_foo2846=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2847=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2848=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02849=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02850=== RUN TestGlobMatch/refs/*/main_refs/heads/main2851=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2852=== RUN TestGlobMatch/fo?_foo2853=== PAUSE TestGlobMatch/fo?_foo2854=== RUN TestGlobMatch/fo?_fo2855=== PAUSE TestGlobMatch/fo?_fo2856=== RUN TestGlobMatch/fo?_fooo2857=== PAUSE TestGlobMatch/fo?_fooo2858=== RUN TestGlobMatch/?oo_foo2859=== PAUSE TestGlobMatch/?oo_foo2860=== RUN TestGlobMatch/?oo_boo2861=== PAUSE TestGlobMatch/?oo_boo2862=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2863=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2864=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2865=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2866=== CONT TestGlobMatch/foo_foo2867=== CONT TestGlobMatch/*/*_foo/bar2868=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2869=== CONT TestGlobMatch/*/*_foo2870=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2871=== CONT TestGlobMatch/foo*bar_foobarbaz2872=== CONT TestGlobMatch/foo*bar_foo123bar2873=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2874=== CONT TestGlobMatch/*bar_foo2875=== CONT TestGlobMatch/*bar_foobar2876=== CONT TestGlobMatch/foo*_foo2877=== CONT TestGlobMatch/foo*_bar2878=== CONT TestGlobMatch/foo*_foobar2879=== CONT TestGlobMatch/*_2880=== CONT TestGlobMatch/*_anything2881=== CONT TestGlobMatch/foo_bar2882=== CONT TestGlobMatch/?oo_boo2883=== CONT TestGlobMatch/?oo_foo2884=== CONT TestGlobMatch/fo?_fooo2885=== CONT TestGlobMatch/fo?_fo2886=== CONT TestGlobMatch/fo?_foo2887=== CONT TestGlobMatch/refs/*/main_refs/heads/main2888=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02889=== CONT TestGlobMatch/*bar_bar2890=== CONT TestGlobMatch/foo*bar_foobar2891--- PASS: TestGlobMatch (0.01s)2892 --- PASS: TestGlobMatch/foo_foo (0.00s)2893 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2894 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2895 --- PASS: TestGlobMatch/*/*_foo (0.00s)2896 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2897 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2898 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2899 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2900 --- PASS: TestGlobMatch/*bar_foo (0.00s)2901 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2902 --- PASS: TestGlobMatch/foo*_foo (0.00s)2903 --- PASS: TestGlobMatch/foo*_bar (0.00s)2904 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2905 --- PASS: TestGlobMatch/*_ (0.00s)2906 --- PASS: TestGlobMatch/*_anything (0.00s)2907 --- PASS: TestGlobMatch/foo_bar (0.00s)2908 --- PASS: TestGlobMatch/?oo_boo (0.00s)2909 --- PASS: TestGlobMatch/?oo_foo (0.00s)2910 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2911 --- PASS: TestGlobMatch/fo?_fo (0.00s)2912 --- PASS: TestGlobMatch/fo?_foo (0.00s)2913 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2914 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2915 --- PASS: TestGlobMatch/*bar_bar (0.00s)2916 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)29172026/10/01 07:36:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45297/oidc29182026/10/01 07:36:55 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232919--- PASS: TestScopes_Rules (0.02s)29202026/10/01 07:36:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38529/oidc2921--- PASS: TestValidateToken_BoundClaimsMismatch (0.02s)2922--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)29232026/10/01 07:36:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33005/oidc2924--- PASS: TestValidateToken_WrongAudience (0.03s)29252026/10/01 07:36:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41197/oidc2926--- PASS: TestPins_TopLevelShorthand (0.05s)29272026/10/01 07:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37377/oidc2928--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)29292026/10/01 07:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46229/oidc2930--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)29312026/10/01 07:36:56 http: TLS handshake error from 127.0.0.1:59626: remote error: tls: bad certificate2932--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)29332026/10/01 07:36:56 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:3619729342026/10/01 07:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46071/oidc2935--- PASS: TestPins_ReservedForMatchingRule (0.15s)2936--- PASS: TestValidateToken_KubernetesServiceAccount (0.16s)29372026/10/01 07:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46635/oidc2938--- PASS: TestValidateToken_Expired (0.16s)29392026/10/01 07:36:56 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45887/oidc29402026/10/01 07:36:56 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:45603/oidc2941--- PASS: TestValidateToken_MultipleProviders (0.20s)29422026/10/01 07:36:56 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:44427/oidc2943--- PASS: TestValidateToken_NoMatchingProvider (0.22s)29442026/10/01 07:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46757/oidc2945--- PASS: TestValidateToken_ValidToken (0.24s)2946PASS2947Running hook tests...2948=== RUN TestSendPathsEmpty2949=== PAUSE TestSendPathsEmpty2950=== RUN TestQueueEnqueueAndFetch2951=== PAUSE TestQueueEnqueueAndFetch2952=== RUN TestQueueDeduplication2953=== PAUSE TestQueueDeduplication2954=== RUN TestQueueRemove2955=== PAUSE TestQueueRemove2956=== RUN TestQueueFetchBatchLimit2957=== PAUSE TestQueueFetchBatchLimit2958=== RUN TestQueueRetryMovesToBack2959=== PAUSE TestQueueRetryMovesToBack2960=== RUN TestQueueFetchRemoveLifecycle2961=== PAUSE TestQueueFetchRemoveLifecycle2962=== RUN TestQueueConcurrentWriters2963=== PAUSE TestQueueConcurrentWriters2964=== RUN TestQueueRemoveLargeClosure2965=== PAUSE TestQueueRemoveLargeClosure2966=== RUN TestServerClientIntegration2967=== PAUSE TestServerClientIntegration2968=== RUN TestServerQueueError2969=== PAUSE TestServerQueueError2970=== RUN TestGetListenerSocketActivation2971 server_test.go:210: === RUN TestGetListenerSocketActivation2972 --- PASS: TestGetListenerSocketActivation (0.00s)2973 PASS2974 2975--- PASS: TestGetListenerSocketActivation (0.01s)2976=== RUN TestDrainIsolatesPoisonPath2977=== PAUSE TestDrainIsolatesPoisonPath2978=== RUN TestRunNotBlockedByPoisonHead2979=== PAUSE TestRunNotBlockedByPoisonHead2980=== RUN TestDrainGivesUpWhenServerDown2981=== PAUSE TestDrainGivesUpWhenServerDown2982=== RUN TestFailedPathPrunedByLaterClosure2983=== PAUSE TestFailedPathPrunedByLaterClosure2984=== RUN TestWorkerUploadsAndRemoves2985=== PAUSE TestWorkerUploadsAndRemoves2986=== RUN TestWorkerSkipsGCdPaths2987=== PAUSE TestWorkerSkipsGCdPaths2988=== RUN TestWorkerPrunesClosureDeps2989=== PAUSE TestWorkerPrunesClosureDeps2990=== RUN TestDrainTimeout2991=== PAUSE TestDrainTimeout2992=== CONT TestSendPathsEmpty2993=== CONT TestServerQueueError2994=== CONT TestRunNotBlockedByPoisonHead2995=== CONT TestWorkerUploadsAndRemoves2996=== CONT TestDrainTimeout2997=== CONT TestWorkerPrunesClosureDeps2998--- PASS: TestSendPathsEmpty (0.00s)2999=== CONT TestWorkerSkipsGCdPaths3000=== CONT TestServerClientIntegration3001=== CONT TestQueueRemoveLargeClosure3002=== CONT TestQueueConcurrentWriters30032026/10/01 07:36:56 ERROR Failed to queue paths error="permission denied" count=13004=== CONT TestDrainGivesUpWhenServerDown3005=== CONT TestQueueFetchRemoveLifecycle3006--- PASS: TestServerQueueError (0.01s)3007=== CONT TestQueueRetryMovesToBack3008=== CONT TestQueueFetchBatchLimit3009=== CONT TestQueueRemove3010=== CONT TestFailedPathPrunedByLaterClosure3011=== CONT TestQueueDeduplication3012=== CONT TestQueueEnqueueAndFetch3013=== CONT TestDrainIsolatesPoisonPath3014--- PASS: TestServerClientIntegration (0.01s)30152026/10/01 07:36:56 INFO Upload queue status pending=230162026/10/01 07:36:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2610734781/002/nonexistent30172026/10/01 07:36:56 INFO Uploading batch count=130182026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=130192026/10/01 07:36:56 INFO Upload queue status pending=330202026/10/01 07:36:56 INFO Upload queue status pending=230212026/10/01 07:36:56 INFO Upload queue status pending=230222026/10/01 07:36:56 INFO Uploading batch count=130232026/10/01 07:36:56 INFO Uploading batch count=230242026/10/01 07:36:56 INFO Uploading batch count=130252026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=130262026/10/01 07:36:56 INFO Uploading batch count=230272026/10/01 07:36:56 INFO Uploading batch count=130282026/10/01 07:36:56 INFO Uploading batch count=230292026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=230302026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown735921595/002/a30312026/10/01 07:36:56 INFO Uploading batch count=13032--- PASS: TestQueueEnqueueAndFetch (0.02s)3033--- PASS: TestQueueDeduplication (0.02s)30342026/10/01 07:36:56 INFO Uploading batch count=430352026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=430362026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown735921595/002/b3037--- PASS: TestQueueRetryMovesToBack (0.02s)3038--- PASS: TestQueueFetchRemoveLifecycle (0.02s)30392026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath354105466/002/bbb30402026/10/01 07:36:56 INFO Uploading batch count=130412026/10/01 07:36:56 INFO Uploading batch count=230422026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=230432026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown735921595/002/c3044--- PASS: TestQueueFetchBatchLimit (0.02s)3045--- PASS: TestQueueRemove (0.02s)30462026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown735921595/002/d30472026/10/01 07:36:56 INFO Uploading batch count=130482026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=130492026/10/01 07:36:56 INFO Uploading batch count=230502026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=230512026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown735921595/002/e3052--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)30532026/10/01 07:36:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown735921595/002/f30542026/10/01 07:36:56 INFO Uploading batch count=130552026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=130562026/10/01 07:36:56 ERROR Drain finished with paths left in queue remaining=1030572026/10/01 07:36:56 INFO Uploading batch count=130582026/10/01 07:36:56 ERROR Upload failed error="upload failed" count=130592026/10/01 07:36:56 ERROR Drain finished with paths left in queue remaining=13060--- PASS: TestDrainGivesUpWhenServerDown (0.03s)3061--- PASS: TestDrainIsolatesPoisonPath (0.03s)3062--- PASS: TestWorkerSkipsGCdPaths (0.04s)3063--- PASS: TestWorkerPrunesClosureDeps (0.04s)3064--- PASS: TestWorkerUploadsAndRemoves (0.04s)3065--- PASS: TestQueueRemoveLargeClosure (0.08s)30662026/10/01 07:36:56 ERROR Upload failed error="context deadline exceeded" count=230672026/10/01 07:36:56 ERROR Drain finished with paths left in queue remaining=43068--- PASS: TestDrainTimeout (0.22s)3069--- PASS: TestQueueConcurrentWriters (0.28s)30702026/10/01 07:36:57 INFO Uploading batch count=130712026/10/01 07:36:57 INFO Uploading batch count=130722026/10/01 07:36:57 INFO Uploading batch count=130732026/10/01 07:36:57 ERROR Upload failed error="upload failed" count=130742026/10/01 07:36:57 INFO Uploading batch count=130752026/10/01 07:36:57 ERROR Upload failed error="upload failed" count=130762026/10/01 07:36:57 INFO Uploading batch count=130772026/10/01 07:36:57 ERROR Upload failed error="upload failed" count=130782026/10/01 07:36:57 INFO Uploading batch count=130792026/10/01 07:36:57 ERROR Upload failed error="upload failed" count=130802026/10/01 07:36:57 ERROR Drain finished with paths left in queue remaining=13081--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3082PASS