niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #278
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestFileTokenMissing97=== CONT TestDoWithRetry_BodyReplayedViaGetBody98=== CONT TestStreamPushRequestLine99=== CONT TestFileTokenReadsAndCaches100--- PASS: TestFileTokenMissing (0.00s)101=== CONT TestEncodeNixBase32102=== RUN TestEncodeNixBase32/test_string_hash103=== PAUSE TestEncodeNixBase32/test_string_hash104=== CONT TestPathInfoHashCompatibility105=== CONT TestStaticToken106--- PASS: TestStaticToken (0.00s)107=== CONT TestSetClientTLSErrors108=== CONT TestResolveStorePath109=== CONT TestSetClientTLSDoesNotMutateDefaultTransport110=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess111=== CONT TestSetClientTLS112=== CONT TestRateLimiterFeedback113=== CONT TestClientSignaturesByStorePath114=== CONT TestPathInfoCACompatibility115=== CONT TestParsePathInfoJSONMultiplePaths116=== CONT TestStreamPushReportsSignatures117=== CONT TestParsePathInfoJSON118=== RUN TestParsePathInfoJSON/Nix_format119=== PAUSE TestParsePathInfoJSON/Nix_format120=== CONT TestScriptTokenEmptyToken121=== CONT TestScriptTokenScriptFails122=== CONT TestScriptTokenBadJSON123=== CONT TestDumpPathMatchesNix124=== CONT TestScriptTokenEmptyCommand125=== CONT TestGetStorePathHash126=== RUN TestEncodeNixBase32/empty_input127=== CONT TestDumpPathWriterError128=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1292026/09/29 08:18:10 ERROR Upload failed error=boom count=1130=== CONT TestConvertHashToNix321312026/09/29 08:18:10 WARN Rate limiter enabled after throttle name=server-test rate=51322026/09/29 08:18:10 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:41873133=== CONT TestEncodeNixBase32WithRealHash134=== CONT TestScriptTokenNoExpiryRerunsEveryCall1352026/09/29 08:18:10 ERROR Upload failed error=boom count=1136=== RUN TestConvertHashToNix32/SRI_format_to_Nix32137=== CONT TestUploadMultipart_PartsInParallel138=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix321392026/09/29 08:18:10 WARN Rate limiter enabled after throttle name=server-test rate=5140=== RUN TestRateLimiterFeedback/429_enables_limiter141=== RUN TestConvertHashToNix32/already_Nix32_format142--- PASS: TestFileTokenReadsAndCaches (0.00s)143=== RUN TestPathInfoCACompatibility/null_ca_field144--- PASS: TestScriptTokenEmptyCommand (0.00s)145--- PASS: TestDoServerRequestAttachesToken (0.00s)146=== PAUSE TestEncodeNixBase32/empty_input147=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)148=== CONT TestFileTokenEmpty1492026/09/29 08:18:10 WARN Rate limiter backed off name=server-test rate=51502026/09/29 08:18:10 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:41873151=== CONT TestPartSizeForNAR152=== RUN TestPartSizeForNAR/zero_stays_at_minimum153=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum154=== CONT TestDumpPathSingleFile155=== PAUSE TestRateLimiterFeedback/429_enables_limiter156=== PAUSE TestPathInfoCACompatibility/null_ca_field157=== RUN TestRateLimiterFeedback/503_enables_limiter158=== RUN TestPathInfoCACompatibility/old_string_format_-_text159=== RUN TestParsePathInfoJSON/Lix_format160=== RUN TestSetClientTLSErrors/missing_cert_file161--- PASS: TestEncodeNixBase32WithRealHash (0.00s)162--- PASS: TestClientSignaturesByStorePath (0.00s)163--- PASS: TestResolveStorePath (0.00s)164--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)165=== PAUSE TestParsePathInfoJSON/Lix_format166=== PAUSE TestConvertHashToNix32/already_Nix32_format167=== CONT TestStreamPushBatchesUnderLoad168=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon169=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths170=== RUN TestPartSizeForNAR/small_stays_at_minimum171=== PAUSE TestRateLimiterFeedback/503_enables_limiter172=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text173=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter174=== PAUSE TestSetClientTLSErrors/missing_cert_file175=== RUN TestGetStorePathHash/valid_store_path176--- PASS: TestStreamPushReportsSignatures (0.00s)177=== CONT TestScriptTokenCachesUntilRefresh178=== CONT TestUploadMultipart_SupersededByPeer179=== RUN TestParsePathInfoJSON/empty_input180=== RUN TestConvertHashToNix32/invalid_format181=== CONT TestStreamPushGivesUpOnDeadServer182=== CONT TestCaseHackSuffix183--- PASS: TestScriptTokenScriptFails (0.01s)184--- PASS: TestFileTokenEmpty (0.00s)185--- PASS: TestScriptTokenEmptyToken (0.01s)186--- PASS: TestScriptTokenBadJSON (0.01s)187=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon188=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths189=== RUN TestSetClientTLSErrors/missing_key_file190=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths191=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths192=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter193=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter194=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter195=== PAUSE TestSetClientTLSErrors/missing_key_file196=== RUN TestSetClientTLSErrors/missing_ca_file197=== PAUSE TestSetClientTLSErrors/missing_ca_file198=== PAUSE TestConvertHashToNix32/invalid_format1992026/09/29 08:18:10 ERROR Upload failed error="connection refused" count=20200=== RUN TestSetClientTLSErrors/invalid_ca_file2012026/09/29 08:18:10 ERROR Server seems unavailable, giving up on batch untried=17202=== PAUSE TestPartSizeForNAR/small_stays_at_minimum203=== RUN TestUploadMultipart_SupersededByPeer/exists204=== PAUSE TestGetStorePathHash/valid_store_path205=== RUN TestGetStorePathHash/basename_without_hyphen_should_error206=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error207=== CONT TestStreamPushIsolatesFailures208=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI209=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI210=== CONT TestShellSplitErrors211=== CONT TestEncodeNixBase32/empty_input2122026/09/29 08:18:10 ERROR Upload failed error="bad path" count=3213=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths214=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive215=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive216=== RUN TestPathInfoCACompatibility/new_structured_format_-_text217=== CONT TestFilterOversizedClosures218=== RUN TestFilterOversizedClosures/no_limit_keeps_everything219=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything220--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.05s)221--- PASS: TestStreamPushGivesUpOnDeadServer (0.04s)222--- PASS: TestDumpPathSingleFile (0.05s)223--- PASS: TestShellSplitErrors (0.00s)224=== CONT TestShellSplit225=== RUN TestSetClientTLS/rejects_connection_without_client_cert226=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter227=== CONT TestStreamPushReportsEveryPath228=== PAUSE TestSetClientTLSErrors/invalid_ca_file229=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum230=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter231=== CONT TestRateLimiterFeedback/503_enables_limiter232=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum233=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error234=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error235=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error236=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error237=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts238=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts239=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512240=== CONT TestEncodeNixBase32/test_string_hash241=== CONT TestRateLimiterFeedback/429_enables_limiter242=== CONT TestConvertHashToNix32/invalid_format243=== CONT TestConvertHashToNix32/already_Nix32_format244=== CONT TestSetClientTLSErrors/missing_cert_file245=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text2462026/09/29 08:18:10 WARN Rate limiter enabled after throttle name=server-test rate=5247=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2482026/09/29 08:18:10 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:33839249=== CONT TestSetClientTLSErrors/missing_ca_file250=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2512026/09/29 08:18:10 WARN Rate limiter backed off name=server-test rate=5252--- PASS: TestStreamPushIsolatesFailures (0.00s)253=== PAUSE TestParsePathInfoJSON/empty_input254=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert255=== PAUSE TestUploadMultipart_SupersededByPeer/exists256=== RUN TestParsePathInfoJSON/whitespace_only257=== RUN TestUploadMultipart_SupersededByPeer/missing258=== PAUSE TestParsePathInfoJSON/whitespace_only259=== CONT TestRegisterUploadedObjectReusesConnections260=== PAUSE TestUploadMultipart_SupersededByPeer/missing261=== CONT TestConvertHashToNix32/SRI_format_to_Nix32262=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error2632026/09/29 08:18:10 WARN Rate limiter enabled after throttle name=server-test rate=5264=== CONT TestUploadMultipart_SupersededByPeer/exists2652026/09/29 08:18:10 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:39063266=== CONT TestGetStorePathHash/basename_without_hyphen_should_error2672026/09/29 08:18:10 WARN Rate limiter backed off name=server-test rate=5268=== CONT TestUploadMultipart_SupersededByPeer/missing269=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512270=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)271=== RUN TestPartSizeForNAR/1_TiB272=== PAUSE TestPartSizeForNAR/1_TiB273=== RUN TestPartSizeForNAR/5_TiB_S3_max_object274=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object275=== RUN TestPartSizeForNAR/capped_at_5_GiB276=== PAUSE TestPartSizeForNAR/capped_at_5_GiB277=== CONT TestPartSizeForNAR/zero_stays_at_minimum278=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI280=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon281=== CONT TestSetClientTLSErrors/invalid_ca_file282=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method283=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method284=== CONT TestPathInfoCACompatibility/null_ca_field285=== CONT TestPartSizeForNAR/capped_at_5_GiB286=== CONT TestPartSizeForNAR/5_TiB_S3_max_object287=== CONT TestPartSizeForNAR/1_TiB288=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts289=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum290=== CONT TestPartSizeForNAR/small_stays_at_minimum291=== CONT TestPathInfoCACompatibility/new_structured_format_-_text292=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive293=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped294=== RUN TestFilterOversizedClosures/all_closures_skipped295=== PAUSE TestFilterOversizedClosures/all_closures_skipped296=== CONT TestFilterOversizedClosures/no_limit_keeps_everything297=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method298=== CONT TestFilterOversizedClosures/all_closures_skipped2992026/09/29 08:18:10 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50300--- PASS: TestShellSplit (0.00s)301--- PASS: TestStreamPushReportsEveryPath (0.00s)302--- PASS: TestEncodeNixBase32 (0.01s)303 --- PASS: TestEncodeNixBase32/empty_input (0.00s)304 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)305=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3062026/09/29 08:18:10 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=2000307--- PASS: TestParsePathInfoJSONMultiplePaths (0.05s)308 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)309 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)310=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA311=== CONT TestGetStorePathHash/valid_store_path312=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error313=== RUN TestParsePathInfoJSON/invalid_JSON314=== CONT TestPathInfoCACompatibility/old_string_format_-_text315=== CONT TestSetClientTLSErrors/missing_key_file316--- PASS: TestConvertHashToNix32 (0.05s)317 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)318 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)319 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)320=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA321=== RUN TestSetClientTLS/preserves_debug_logging_transport322=== PAUSE TestSetClientTLS/preserves_debug_logging_transport323=== CONT TestSetClientTLS/rejects_connection_without_client_cert324=== PAUSE TestParsePathInfoJSON/invalid_JSON325=== CONT TestParsePathInfoJSON/Nix_format326--- PASS: TestRateLimiterFeedback (0.05s)327 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)328 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)329 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)330 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)331--- PASS: TestPathInfoHashCompatibility (0.06s)332 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)333 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)334 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)335 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)336--- PASS: TestFilterOversizedClosures (0.00s)337 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)338 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)339 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)340--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)341=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA342=== CONT TestParsePathInfoJSON/invalid_JSON343=== CONT TestParsePathInfoJSON/whitespace_only344=== CONT TestParsePathInfoJSON/empty_input345=== CONT TestParsePathInfoJSON/Lix_format346=== CONT TestSetClientTLS/preserves_debug_logging_transport347--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)348 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)349 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)350--- PASS: TestPartSizeForNAR (0.05s)351 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)352 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)353 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)354 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)355 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)356 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)357 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)358--- PASS: TestPathInfoCACompatibility (0.05s)359 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)360 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)361 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)362 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)363 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)364--- PASS: TestSetClientTLSErrors (0.05s)365 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)366 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)367 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)368 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)369--- PASS: TestGetStorePathHash (0.05s)370 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)371 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)372 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)373 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)374--- PASS: TestParsePathInfoJSON (0.06s)375 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)376 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)377 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)378 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)379 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)380--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)381--- PASS: TestStreamPushRequestLine (0.08s)3822026/09/29 08:18:10 http: TLS handshake error from 127.0.0.1:44906: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.06s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)385 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)387--- PASS: TestCaseHackSuffix (0.03s)388--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)389--- PASS: TestDumpPathWriterError (0.10s)390--- PASS: TestDumpPathMatchesNix (0.13s)391--- PASS: TestStreamPushBatchesUnderLoad (0.15s)392--- PASS: TestUploadMultipart_PartsInParallel (0.67s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)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/postgres3538896693/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/postgres3538896693/data -l logfile start422423/build/postgres3538896693:5432 - no response4242026-09-29 08:18:12.648 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-09-29 08:18:12.648 UTC [128] LOG: listening on Unix socket "/build/postgres3538896693/.s.PGSQL.5432"4262026-09-29 08:18:12.653 UTC [135] LOG: database system was shut down at 2026-09-29 08:18:12 UTC4272026-09-29 08:18:12.656 UTC [128] LOG: database system is ready to accept connections428/build/postgres3538896693:5432 - accepting connections429{"timestamp":"2026-09-29T08:18:12.948407671Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a32cba6b-eb90-4ae6-b0e2-b07d74ce7389","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(386)"}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-09-29 08:18:13.141 UTC [564] ERROR: relation "goose_db_version" does not exist at character 364722026-09-29 08:18:13.141 UTC [564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4732026/09/29 08:18:13 OK 20241026095416_initial_model.sql (6.81ms)4742026/09/29 08:18:13 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)4752026/09/29 08:18:13 OK 20251218171726_add_pins.sql (2.12ms)4762026/09/29 08:18:13 OK 20260628120000_add_object_size_and_stats.sql (1.9ms)4772026/09/29 08:18:13 OK 20260905000000_add_claims.sql (2.31ms)4782026/09/29 08:18:13 OK 20260920000000_drop_claims.sql (1.45ms)4792026/09/29 08:18:13 OK 20260923120000_add_pushes.sql (1.08ms)4802026/09/29 08:18:13 goose: successfully migrated database to version: 202609231200004812026/09/29 08:18:13 OK 1_commit_pending_closure.sql (1.36ms)4822026/09/29 08:18:13 OK 2_object_stats_trigger.sql (762.73µs)4832026/09/29 08:18:13 OK 3_commit_push.sql (572.75µs)4842026/09/29 08:18:13 goose: up to current file version: 34852026/09/29 08:18:13 INFO lead: acquired remote=192.0.2.1:12344862026/09/29 08:18:13 INFO lead: released remote=192.0.2.1:12344872026/09/29 08:18:13 INFO lead: acquired remote=192.0.2.1:12344882026/09/29 08:18:13 INFO lead: released remote=192.0.2.1:1234489--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)490=== RUN TestLeadEndsOnShutdown491=== PAUSE TestLeadEndsOnShutdown492=== RUN TestGCAdvisoryLockBlocksConcurrentRun4932026-09-29 08:18:13.903 UTC [574] ERROR: relation "goose_db_version" does not exist at character 364942026-09-29 08:18:13.903 UTC [574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4952026/09/29 08:18:13 OK 20241026095416_initial_model.sql (6.16ms)4962026/09/29 08:18:13 OK 20251210153512_drop_unused_gin_index.sql (1.3ms)4972026/09/29 08:18:13 OK 20251218171726_add_pins.sql (2.16ms)4982026/09/29 08:18:13 OK 20260628120000_add_object_size_and_stats.sql (2.53ms)4992026/09/29 08:18:13 OK 20260905000000_add_claims.sql (2.01ms)5002026/09/29 08:18:13 OK 20260920000000_drop_claims.sql (1.39ms)5012026/09/29 08:18:13 OK 20260923120000_add_pushes.sql (997.81µs)5022026/09/29 08:18:13 goose: successfully migrated database to version: 202609231200005032026/09/29 08:18:13 OK 1_commit_pending_closure.sql (1.35ms)5042026/09/29 08:18:13 OK 2_object_stats_trigger.sql (679µs)5052026/09/29 08:18:13 OK 3_commit_push.sql (601.63µs)5062026/09/29 08:18:13 goose: up to current file version: 3507--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)508=== RUN TestGCBugBareHashReferences509=== PAUSE TestGCBugBareHashReferences510=== RUN TestGCMetrics511=== PAUSE TestGCMetrics512=== RUN TestGCTaskStore_StartNew513=== PAUSE TestGCTaskStore_StartNew514=== RUN TestGCTaskStore_DeduplicateSameParams515=== PAUSE TestGCTaskStore_DeduplicateSameParams516=== RUN TestGCTaskStore_ConflictDifferentParams517=== PAUSE TestGCTaskStore_ConflictDifferentParams518=== RUN TestGCTaskStore_GetEmpty519=== PAUSE TestGCTaskStore_GetEmpty520=== RUN TestGCTaskStore_GetReturnsLatest521=== PAUSE TestGCTaskStore_GetReturnsLatest522=== RUN TestGCTaskStore_CompletedAllowsNewTask523=== PAUSE TestGCTaskStore_CompletedAllowsNewTask524=== RUN TestGCTaskStore_PhaseUpdates525=== PAUSE TestGCTaskStore_PhaseUpdates526=== RUN TestGCTaskStore_Fail527=== PAUSE TestGCTaskStore_Fail528=== RUN TestGracefulShutdownDrainsInflight529=== PAUSE TestGracefulShutdownDrainsInflight530=== RUN TestService_healthCheckHandler531=== PAUSE TestService_healthCheckHandler532=== RUN TestService_readinessHandler533=== PAUSE TestService_readinessHandler534=== RUN TestGenerateLandingPage535=== PAUSE TestGenerateLandingPage536=== RUN TestCacheConfigHandlerMaxNarSize537=== PAUSE TestCacheConfigHandlerMaxNarSize538=== RUN TestCreatePendingClosureRejectsOversizedNAR539=== PAUSE TestCreatePendingClosureRejectsOversizedNAR540=== RUN TestNARDeduplicationMetadataUploadBug541=== PAUSE TestNARDeduplicationMetadataUploadBug542=== RUN TestMetricsInventory543=== PAUSE TestMetricsInventory544=== RUN TestService_NativeMTLS545=== PAUSE TestService_NativeMTLS546=== RUN TestServerTLSConfig547=== PAUSE TestServerTLSConfig548=== RUN TestMultipartCleanup549=== PAUSE TestMultipartCleanup550=== RUN TestObjectStatsTrigger551=== PAUSE TestObjectStatsTrigger552=== RUN TestOrphanedObjectsGC553=== PAUSE TestOrphanedObjectsGC554=== RUN TestOrphanedObjectsGCStressTest555=== PAUSE TestOrphanedObjectsGCStressTest556=== RUN TestResurrectedObjectNotDeleted557=== PAUSE TestResurrectedObjectNotDeleted558=== RUN TestCreatePin_ReservedPins559=== PAUSE TestCreatePin_ReservedPins560=== RUN TestParseSingleRange561=== PAUSE TestParseSingleRange562=== RUN TestProxyHeadersOnlyTrustedOnSocket563=== PAUSE TestProxyHeadersOnlyTrustedOnSocket564=== RUN TestIsValidCachePath565=== PAUSE TestIsValidCachePath566=== RUN TestReadProxyNarinfo567=== PAUSE TestReadProxyNarinfo568=== RUN TestReadProxyNarinfoAlreadyDecompressed569=== PAUSE TestReadProxyNarinfoAlreadyDecompressed570=== RUN TestReadProxyNarStreaming571=== PAUSE TestReadProxyNarStreaming572=== RUN TestReadProxy404573=== PAUSE TestReadProxy404574=== RUN TestReadProxyInvalidPath575=== PAUSE TestReadProxyInvalidPath576=== RUN TestReadProxyHead577=== PAUSE TestReadProxyHead578=== RUN TestReadProxyConditionalGet579=== PAUSE TestReadProxyConditionalGet580=== RUN TestReadProxyRootRedirectsToIndexHTML581=== PAUSE TestReadProxyRootRedirectsToIndexHTML582=== RUN TestReadProxyDisabled583=== PAUSE TestReadProxyDisabled584=== RUN TestReadRedirectNar585=== PAUSE TestReadRedirectNar586=== RUN TestReadRedirectKeepsNarinfoProxied587=== PAUSE TestReadRedirectKeepsNarinfoProxied588=== RUN TestReadProxyRangeRequest589=== PAUSE TestReadProxyRangeRequest590=== RUN TestReadRedirectUsesPublicS3URL591=== PAUSE TestReadRedirectUsesPublicS3URL592=== RUN TestPush_OverlappingRootsStoreOneRowPerKey593=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey594=== RUN TestPush_CompleteCommitsEveryRoot595=== PAUSE TestPush_CompleteCommitsEveryRoot596=== RUN TestPush_CommitFailsWhenSkippedKeyWasCollected597=== PAUSE TestPush_CommitFailsWhenSkippedKeyWasCollected598=== RUN TestPush_RejectsBadRequests599=== PAUSE TestPush_RejectsBadRequests600=== RUN TestPush_SignsNarinfosOfItsPendingObjects601=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects602=== RUN TestRedundantMultipartUpload603=== PAUSE TestRedundantMultipartUpload604=== RUN TestCompleteMultipartUpload_ErrorButObjectExists605=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists606=== RUN TestCompletedNarNotReofferedAcrossClosures607=== PAUSE TestCompletedNarNotReofferedAcrossClosures608=== RUN TestPresignedUploadRegisteredBeforeCommit609=== PAUSE TestPresignedUploadRegisteredBeforeCommit610=== RUN TestService_Rustfstest611=== PAUSE TestService_Rustfstest612=== RUN TestParseSize613=== PAUSE TestParseSize614=== RUN TestSkippedUploadsHandler615=== PAUSE TestSkippedUploadsHandler616=== RUN TestSystemdListenerNotActivated617--- PASS: TestSystemdListenerNotActivated (0.00s)618=== RUN TestWatchdogBeatsWhenHealthy619--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)620=== RUN TestWatchdogSkipsWhenUnhealthy6212026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6222026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6232026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6242026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6252026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6262026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6272026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6282026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6292026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6302026/09/29 08:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"631--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)632=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle633=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle634=== RUN TestProxyWriteTimeout635=== PAUSE TestProxyWriteTimeout636=== RUN TestIsValidUploadKey637=== PAUSE TestIsValidUploadKey638=== RUN TestUploadHandlersRejectInvalidKeys639=== PAUSE TestUploadHandlersRejectInvalidKeys640=== RUN TestUploadHandlersRejectOversizedBody641=== PAUSE TestUploadHandlersRejectOversizedBody642=== RUN TestService_cleanupPendingClosuresHandler643=== PAUSE TestService_cleanupPendingClosuresHandler644=== RUN TestService_createPendingClosureHandler645=== PAUSE TestService_createPendingClosureHandler646=== RUN TestService_verifyS3Integrity647=== PAUSE TestService_verifyS3Integrity648=== RUN TestCompleteMultipartUnregistered649=== PAUSE TestCompleteMultipartUnregistered650=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT651=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT652=== CONT TestService_AuthMiddleware653=== CONT TestPresignedUploadRegisteredBeforeCommit654=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT655=== CONT TestCompleteMultipartUnregistered656=== CONT TestService_verifyS3Integrity657=== CONT TestService_createPendingClosureHandler658=== CONT TestService_cleanupPendingClosuresHandler659=== CONT TestUploadHandlersRejectOversizedBody660=== CONT TestUploadHandlersRejectInvalidKeys661=== CONT TestIsValidUploadKey662=== RUN TestIsValidUploadKey/narinfo663=== PAUSE TestIsValidUploadKey/narinfo664=== RUN TestIsValidUploadKey/nar_zst665=== PAUSE TestIsValidUploadKey/nar_zst666=== RUN TestIsValidUploadKey/nar_xz667=== PAUSE TestIsValidUploadKey/nar_xz668=== CONT TestProxyWriteTimeout669=== RUN TestProxyWriteTimeout/narinfo670=== PAUSE TestProxyWriteTimeout/narinfo671=== RUN TestProxyWriteTimeout/1_GiB_nar672=== PAUSE TestProxyWriteTimeout/1_GiB_nar673=== RUN TestProxyWriteTimeout/10_GiB_nar674=== PAUSE TestProxyWriteTimeout/10_GiB_nar675=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle676=== RUN TestIsValidUploadKey/nar_plain677=== CONT TestSkippedUploadsHandler678=== CONT TestCacheConfigHandlerMaxNarSize679=== CONT TestParseSize680=== CONT TestService_Rustfstest681=== CONT TestRedundantMultipartUpload682=== CONT TestPush_SignsNarinfosOfItsPendingObjects683=== CONT TestPush_RejectsBadRequests684=== CONT TestPush_CommitFailsWhenSkippedKeyWasCollected685=== CONT TestPush_CompleteCommitsEveryRoot686=== CONT TestPush_OverlappingRootsStoreOneRowPerKey687=== CONT TestReadRedirectUsesPublicS3URL688=== CONT TestCompleteMultipartUpload_ErrorButObjectExists689=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info690=== RUN TestProxyWriteTimeout/unknown_size691--- PASS: TestParseSize (0.00s)692=== CONT TestReadProxyRangeRequest6932026/09/29 08:18:14 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000694=== PAUSE TestIsValidUploadKey/nar_plain695=== RUN TestIsValidUploadKey/listing696=== 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=== CONT TestReadRedirectKeepsNarinfoProxied704--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)705--- PASS: TestSkippedUploadsHandler (0.09s)706=== PAUSE TestProxyWriteTimeout/unknown_size707=== PAUSE TestIsValidUploadKey/listing708=== RUN TestIsValidUploadKey/build_log709=== PAUSE TestIsValidUploadKey/build_log710=== CONT TestReadProxyDisabled711=== CONT TestReadRedirectNar712=== CONT TestReadProxyRootRedirectsToIndexHTML713=== RUN TestIsValidUploadKey/build_log_home-manager_file714=== PAUSE TestIsValidUploadKey/build_log_home-manager_file715=== RUN TestIsValidUploadKey/build_log_plus_in_name716=== PAUSE TestIsValidUploadKey/build_log_plus_in_name717=== RUN TestIsValidUploadKey/build_log_question_mark718=== PAUSE TestIsValidUploadKey/build_log_question_mark719=== RUN TestIsValidUploadKey/build_log_equals720=== PAUSE TestIsValidUploadKey/build_log_equals721=== RUN TestIsValidUploadKey/realisation722=== PAUSE TestIsValidUploadKey/realisation723=== RUN TestIsValidUploadKey/realisation_plus_in_output724=== PAUSE TestIsValidUploadKey/realisation_plus_in_output725=== RUN TestIsValidUploadKey/nix-cache-info726=== PAUSE TestIsValidUploadKey/nix-cache-info727=== RUN TestIsValidUploadKey/index.html728=== PAUSE TestIsValidUploadKey/index.html729=== RUN TestIsValidUploadKey/narinfo_key,_nar_type730=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type731=== RUN TestIsValidUploadKey/nar_key,_narinfo_type732=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type733=== RUN TestIsValidUploadKey/listing_key,_narinfo_type734=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type735=== RUN TestIsValidUploadKey/traversal736=== PAUSE TestIsValidUploadKey/traversal737=== RUN TestIsValidUploadKey/traversal_nar738=== PAUSE TestIsValidUploadKey/traversal_nar739=== RUN TestIsValidUploadKey/absolute740=== PAUSE TestIsValidUploadKey/absolute741=== RUN TestIsValidUploadKey/empty_key742=== PAUSE TestIsValidUploadKey/empty_key743=== RUN TestIsValidUploadKey/unknown_type744=== PAUSE TestIsValidUploadKey/unknown_type745=== CONT TestReadProxyConditionalGet7462026-09-29 08:18:14.351 UTC [639] ERROR: relation "goose_db_version" does not exist at character 367472026-09-29 08:18:14.351 UTC [639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7482026-09-29 08:18:14.354 UTC [640] ERROR: relation "goose_db_version" does not exist at character 367492026-09-29 08:18:14.354 UTC [640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026-09-29 08:18:14.373 UTC [641] ERROR: relation "goose_db_version" does not exist at character 367512026-09-29 08:18:14.373 UTC [641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7522026-09-29 08:18:14.376 UTC [642] ERROR: relation "goose_db_version" does not exist at character 367532026-09-29 08:18:14.376 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC754=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart755=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart756=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts757=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts758=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure759=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure760=== CONT TestReadProxyHead7612026-09-29 08:18:14.383 UTC [643] ERROR: relation "goose_db_version" does not exist at character 367622026-09-29 08:18:14.383 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026-09-29 08:18:14.398 UTC [648] ERROR: relation "goose_db_version" does not exist at character 367642026-09-29 08:18:14.398 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026-09-29 08:18:14.404 UTC [649] ERROR: relation "goose_db_version" does not exist at character 367662026-09-29 08:18:14.404 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7672026/09/29 08:18:14 OK 20241026095416_initial_model.sql (28.11ms)7682026/09/29 08:18:14 OK 20241026095416_initial_model.sql (28.52ms)7692026/09/29 08:18:14 OK 20241026095416_initial_model.sql (26.9ms)7702026/09/29 08:18:14 OK 20241026095416_initial_model.sql (21.93ms)7712026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.5ms)7722026/09/29 08:18:14 OK 20241026095416_initial_model.sql (23.6ms)7732026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (4.77ms)7742026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (4.12ms)7752026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (4.8ms)7762026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.28ms)7772026/09/29 08:18:14 OK 20251218171726_add_pins.sql (4.59ms)7782026/09/29 08:18:14 OK 20251218171726_add_pins.sql (5.62ms)7792026/09/29 08:18:14 OK 20251218171726_add_pins.sql (5.86ms)7802026/09/29 08:18:14 OK 20251218171726_add_pins.sql (8.71ms)7812026/09/29 08:18:14 OK 20251218171726_add_pins.sql (6.19ms)7822026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (6.22ms)7832026/09/29 08:18:14 OK 20241026095416_initial_model.sql (15.98ms)7842026-09-29 08:18:14.432 UTC [651] ERROR: relation "goose_db_version" does not exist at character 367852026-09-29 08:18:14.432 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (6.33ms)7872026-09-29 08:18:14.432 UTC [650] ERROR: relation "goose_db_version" does not exist at character 367882026-09-29 08:18:14.432 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7892026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (6.44ms)7902026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.87ms)7912026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (8.02ms)7922026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (7.52ms)7932026/09/29 08:18:14 OK 20260905000000_add_claims.sql (7.87ms)7942026/09/29 08:18:14 OK 20251218171726_add_pins.sql (6.16ms)7952026/09/29 08:18:14 OK 20260905000000_add_claims.sql (7.84ms)7962026/09/29 08:18:14 OK 20260905000000_add_claims.sql (7.63ms)7972026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.66ms)7982026/09/29 08:18:14 OK 20260905000000_add_claims.sql (7.64ms)7992026/09/29 08:18:14 OK 20260905000000_add_claims.sql (5.8ms)8002026/09/29 08:18:14 OK 20241026095416_initial_model.sql (19.67ms)8012026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.39ms)8022026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.56ms)8032026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (5.75ms)8042026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)8052026-09-29 08:18:14.448 UTC [652] ERROR: relation "goose_db_version" does not exist at character 368062026-09-29 08:18:14.448 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8072026-09-29 08:18:14.455 UTC [653] ERROR: relation "goose_db_version" does not exist at character 368082026-09-29 08:18:14.455 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8092026-09-29 08:18:14.455 UTC [654] ERROR: relation "goose_db_version" does not exist at character 368102026-09-29 08:18:14.455 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8112026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (13.54ms)8122026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008132026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (13.75ms)8142026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (14.29ms)8152026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (15.83ms)8162026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008172026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (16.01ms)8182026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008192026/09/29 08:18:14 OK 20260905000000_add_claims.sql (13.73ms)8202026/09/29 08:18:14 OK 20251218171726_add_pins.sql (13.64ms)8212026/09/29 08:18:14 OK 1_commit_pending_closure.sql (6.37ms)8222026/09/29 08:18:14 OK 1_commit_pending_closure.sql (4.02ms)8232026/09/29 08:18:14 OK 1_commit_pending_closure.sql (3.72ms)8242026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.99ms)8252026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (8.83ms)8262026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008272026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (6.06ms)8282026/09/29 08:18:14 OK 2_object_stats_trigger.sql (3.17ms)8292026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (9.92ms)8302026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008312026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (7.05ms)8322026/09/29 08:18:14 OK 2_object_stats_trigger.sql (3.28ms)8332026/09/29 08:18:14 OK 3_commit_push.sql (3.13ms)8342026/09/29 08:18:14 goose: up to current file version: 38352026/09/29 08:18:14 OK 3_commit_push.sql (3.01ms)8362026/09/29 08:18:14 goose: up to current file version: 38372026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (4.05ms)8382026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008392026/09/29 08:18:14 OK 20241026095416_initial_model.sql (28.56ms)8402026/09/29 08:18:14 OK 3_commit_push.sql (2.84ms)8412026/09/29 08:18:14 goose: up to current file version: 38422026/09/29 08:18:14 OK 1_commit_pending_closure.sql (4.65ms)8432026/09/29 08:18:14 OK 1_commit_pending_closure.sql (6.07ms)8442026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.04ms)8452026/09/29 08:18:14 OK 20241026095416_initial_model.sql (31.93ms)8462026/09/29 08:18:14 OK 2_object_stats_trigger.sql (4.22ms)8472026/09/29 08:18:14 OK 1_commit_pending_closure.sql (4.54ms)8482026/09/29 08:18:14 OK 20260905000000_add_claims.sql (7.66ms)8492026/09/29 08:18:14 OK 2_object_stats_trigger.sql (3.38ms)8502026/09/29 08:18:14 OK 2_object_stats_trigger.sql (3.49ms)8512026/09/29 08:18:14 OK 3_commit_push.sql (3.57ms)8522026/09/29 08:18:14 goose: up to current file version: 38532026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (5.03ms)8542026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (4.25ms)8552026/09/29 08:18:14 OK 3_commit_push.sql (3.31ms)8562026/09/29 08:18:14 goose: up to current file version: 38572026/09/29 08:18:14 OK 3_commit_push.sql (2.98ms)8582026/09/29 08:18:14 goose: up to current file version: 38592026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (3.71ms)8602026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008612026/09/29 08:18:14 OK 20251218171726_add_pins.sql (9.78ms)8622026/09/29 08:18:14 OK 20251218171726_add_pins.sql (5.66ms)8632026/09/29 08:18:14 OK 1_commit_pending_closure.sql (5.76ms)8642026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures8652026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (15.67ms)8662026/09/29 08:18:14 OK 20241026095416_initial_model.sql (31.32ms)8672026/09/29 08:18:14 OK 2_object_stats_trigger.sql (12.97ms)8682026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (17.59ms)8692026/09/29 08:18:14 OK 20241026095416_initial_model.sql (29.22ms)8702026/09/29 08:18:14 OK 20241026095416_initial_model.sql (29.38ms)8712026/09/29 08:18:14 OK 3_commit_push.sql (1.63ms)8722026/09/29 08:18:14 goose: up to current file version: 38732026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (6.06ms)8742026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.97ms)8752026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.08ms)8762026/09/29 08:18:14 OK 20260905000000_add_claims.sql (4.4ms)8772026/09/29 08:18:14 OK 20260905000000_add_claims.sql (9ms)8782026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.23ms)8792026/09/29 08:18:14 OK 20251218171726_add_pins.sql (5.1ms)8802026/09/29 08:18:14 OK 20251218171726_add_pins.sql (5.24ms)8812026-09-29 08:18:14.513 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368822026-09-29 08:18:14.513 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8832026-09-29 08:18:14.513 UTC [658] ERROR: relation "goose_db_version" does not exist at character 368842026-09-29 08:18:14.513 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8852026-09-29 08:18:14.513 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368862026-09-29 08:18:14.513 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8872026/09/29 08:18:14 OK 20251218171726_add_pins.sql (7.93ms)8882026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (3.75ms)8892026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200008902026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (5.61ms)8912026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.39ms)8922026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.65ms)8932026/09/29 08:18:14 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"894--- PASS: TestService_AuthMiddleware (0.33s)895=== CONT TestReadProxyInvalidPath8962026-09-29 08:18:14.519 UTC [660] ERROR: relation "goose_db_version" does not exist at character 368972026-09-29 08:18:14.519 UTC [660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8982026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (3.74ms)8992026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009002026-09-29 08:18:14.519 UTC [659] ERROR: relation "goose_db_version" does not exist at character 369012026-09-29 08:18:14.519 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9022026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.15ms)9032026/09/29 08:18:14 OK 1_commit_pending_closure.sql (4.69ms)9042026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.4ms)9052026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (6.32ms)9062026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.83ms)9072026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.16ms)9082026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.46ms)9092026/09/29 08:18:14 OK 1_commit_pending_closure.sql (4.16ms)9102026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.78ms)9112026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009122026/09/29 08:18:14 OK 3_commit_push.sql (2.9ms)9132026/09/29 08:18:14 goose: up to current file version: 39142026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.61ms)9152026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009162026/09/29 08:18:14 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9172026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures9182026-09-29 08:18:14.525 UTC [661] ERROR: relation "goose_db_version" does not exist at character 369192026-09-29 08:18:14.525 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9202026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.68ms)9212026/09/29 08:18:14 OK 20260905000000_add_claims.sql (4.94ms)9222026-09-29 08:18:14.527 UTC [664] ERROR: relation "goose_db_version" does not exist at character 369232026-09-29 08:18:14.527 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9242026-09-29 08:18:14.527 UTC [663] ERROR: relation "goose_db_version" does not exist at character 369252026-09-29 08:18:14.527 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9262026/09/29 08:18:14 OK 1_commit_pending_closure.sql (3.46ms)927--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.34s)928=== CONT TestReadProxy4049292026/09/29 08:18:14 OK 3_commit_push.sql (2.74ms)9302026/09/29 08:18:14 goose: up to current file version: 39312026/09/29 08:18:14 OK 1_commit_pending_closure.sql (3.66ms)9322026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.82ms)9332026-09-29 08:18:14.530 UTC [666] ERROR: relation "goose_db_version" does not exist at character 369342026-09-29 08:18:14.530 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9352026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.17ms)9362026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.82ms)9372026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.96ms)9382026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.53ms)9392026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.55ms)9402026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)9412026/09/29 08:18:14 OK 3_commit_push.sql (1.61ms)9422026/09/29 08:18:14 goose: up to current file version: 39432026/09/29 08:18:14 OK 3_commit_push.sql (2.58ms)9442026/09/29 08:18:14 goose: up to current file version: 39452026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (3.85ms)9462026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009472026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)9482026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)9492026/09/29 08:18:14 OK 20241026095416_initial_model.sql (9.14ms)9502026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.68ms)9512026-09-29 08:18:14.536 UTC [667] ERROR: relation "goose_db_version" does not exist at character 369522026-09-29 08:18:14.536 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9532026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.13ms)9542026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)9552026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.93ms)9562026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.85ms)9572026-09-29 08:18:14.539 UTC [669] ERROR: relation "goose_db_version" does not exist at character 369582026-09-29 08:18:14.539 UTC [669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9592026/09/29 08:18:14 OK 1_commit_pending_closure.sql (5.12ms)9602026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)9612026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures9622026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.56ms)9632026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.89ms)9642026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)9652026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.74ms)9662026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.54ms)9672026/09/29 08:18:14 OK 20251218171726_add_pins.sql (5.11ms)9682026/09/29 08:18:14 OK 3_commit_push.sql (2.4ms)9692026/09/29 08:18:14 goose: up to current file version: 39702026/09/29 08:18:14 OK 20260905000000_add_claims.sql (4.4ms)9712026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.75ms)9722026/09/29 08:18:14 OK 20260905000000_add_claims.sql (5.1ms)9732026/09/29 08:18:14 OK 20260905000000_add_claims.sql (4.45ms)9742026/09/29 08:18:14 OK 20241026095416_initial_model.sql (13.31ms)9752026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.25ms)9762026/09/29 08:18:14 OK 20241026095416_initial_model.sql (11.13ms)9772026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.58ms)9782026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.6ms)9792026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.26ms)9802026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009812026/09/29 08:18:14 OK 20260905000000_add_claims.sql (4.46ms)9822026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)9832026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)9842026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.73ms)9852026-09-29 08:18:14.552 UTC [671] ERROR: relation "goose_db_version" does not exist at character 369862026-09-29 08:18:14.552 UTC [671] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9872026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.7ms)9882026/09/29 08:18:14 OK 1_commit_pending_closure.sql (3.35ms)9892026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.25ms)9902026/09/29 08:18:14 OK 20241026095416_initial_model.sql (17.91ms)9912026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (3.62ms)9922026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009932026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.82ms)9942026/09/29 08:18:14 goose: successfully migrated database to version: 202609231200009952026/09/29 08:18:14 OK 20241026095416_initial_model.sql (17.68ms)9962026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.74ms)9972026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (4.09ms)9982026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.07ms)999--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.37s)1000=== CONT TestReadProxyNarStreaming10012026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.36ms)10022026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)10032026/09/29 08:18:14 OK 20241026095416_initial_model.sql (11.5ms)10042026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)10052026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.78ms)10062026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.44ms)10072026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010082026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.85ms)10092026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.01ms)10102026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010112026/09/29 08:18:14 OK 3_commit_push.sql (1.64ms)10122026/09/29 08:18:14 goose: up to current file version: 310132026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.46ms)10142026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.96ms)10152026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.97ms)10162026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)10172026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (5.53ms)10182026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.52ms)10192026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.35ms)10202026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)10212026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.18ms)10222026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.28ms)10232026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.42ms)10242026/09/29 08:18:14 OK 3_commit_push.sql (1.72ms)10252026/09/29 08:18:14 goose: up to current file version: 310262026/09/29 08:18:14 OK 3_commit_push.sql (2.26ms)10272026/09/29 08:18:14 goose: up to current file version: 310282026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.11ms)10292026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.4ms)10302026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.55ms)10312026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.86ms)10322026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.75ms)10332026/09/29 08:18:14 OK 3_commit_push.sql (1.84ms)10342026/09/29 08:18:14 goose: up to current file version: 310352026/09/29 08:18:14 OK 3_commit_push.sql (1.91ms)10362026/09/29 08:18:14 goose: up to current file version: 310372026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)10382026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)10392026/09/29 08:18:14 OK 20251218171726_add_pins.sql (4.28ms)10402026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.22ms)10412026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.44ms)10422026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.08ms)10432026/09/29 08:18:14 OK 20260905000000_add_claims.sql (4.11ms)10442026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)10452026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.4ms)10462026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)10472026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.83ms)10482026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010492026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures10502026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures10512026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures10522026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.89ms)10532026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010542026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.7ms)10552026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)10562026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.77ms)10572026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.33ms)10582026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.52ms)10592026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.71ms)10602026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.41ms)10612026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.12ms)10622026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010632026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.45ms)10642026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.71ms)10652026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010662026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.13ms)10672026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.71ms)10682026/09/29 08:18:14 OK 1_commit_pending_closure.sql (1.9ms)10692026/09/29 08:18:14 OK 3_commit_push.sql (1.54ms)10702026/09/29 08:18:14 goose: up to current file version: 310712026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.88ms)10722026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.1ms)10732026/09/29 08:18:14 OK 3_commit_push.sql (1.45ms)10742026/09/29 08:18:14 goose: up to current file version: 310752026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.31ms)10762026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.91ms)10772026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.61ms)10782026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010792026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)10802026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (3ms)10812026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000010822026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.87ms)10832026/09/29 08:18:14 OK 3_commit_push.sql (1.99ms)10842026/09/29 08:18:14 goose: up to current file version: 310852026/09/29 08:18:14 OK 3_commit_push.sql (8.51ms)10862026/09/29 08:18:14 goose: up to current file version: 310872026/09/29 08:18:14 OK 1_commit_pending_closure.sql (12.91ms)10882026/09/29 08:18:14 OK 20260905000000_add_claims.sql (12.72ms)10892026/09/29 08:18:14 OK 1_commit_pending_closure.sql (12.55ms)10902026/09/29 08:18:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10912026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.33ms)10922026/09/29 08:18:14 OK 2_object_stats_trigger.sql (3.22ms)10932026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (3.99ms)10942026/09/29 08:18:14 OK 3_commit_push.sql (1.79ms)10952026/09/29 08:18:14 goose: up to current file version: 310962026/09/29 08:18:14 OK 3_commit_push.sql (2.28ms)10972026/09/29 08:18:14 goose: up to current file version: 310982026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.11ms)10992026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000011002026/09/29 08:18:14 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1101--- PASS: TestCompleteMultipartUnregistered (0.41s)1102=== CONT TestReadProxyNarinfoAlreadyDecompressed11032026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.8ms)11042026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.66ms)11052026/09/29 08:18:14 OK 3_commit_push.sql (4.84ms)11062026/09/29 08:18:14 goose: up to current file version: 311072026/09/29 08:18:14 INFO Received cleanup request method=DELETE path=/api/pending_closures11082026-09-29 08:18:14.626 UTC [677] ERROR: relation "goose_db_version" does not exist at character 3611092026-09-29 08:18:14.626 UTC [677] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11102026-09-29 08:18:14.627 UTC [678] ERROR: relation "goose_db_version" does not exist at character 3611112026-09-29 08:18:14.627 UTC [678] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11122026/09/29 08:18:14 INFO Aborted multipart uploads count=011132026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures11142026/09/29 08:18:14 OK 20241026095416_initial_model.sql (8.62ms)11152026/09/29 08:18:14 OK 20241026095416_initial_model.sql (9.01ms)11162026/09/29 08:18:14 INFO Received cleanup request method=DELETE path=/api/pending_closures11172026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)11182026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)11192026/09/29 08:18:14 INFO Aborted multipart uploads count=111202026/09/29 08:18:14 OK 20251218171726_add_pins.sql (2.54ms)11212026/09/29 08:18:14 OK 20251218171726_add_pins.sql (2.28ms)11222026/09/29 08:18:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11232026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)11242026-09-29 08:18:14.649 UTC [648] ERROR: Closure does not exist: id=111252026-09-29 08:18:14.649 UTC [648] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11262026-09-29 08:18:14.649 UTC [648] STATEMENT: -- name: CommitPendingClosure :exec1127 SELECT commit_pending_closure($1::bigint)1128 1129--- PASS: TestService_cleanupPendingClosuresHandler (0.46s)1130=== CONT TestReadProxyNarinfo11312026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (3.21ms)11322026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures11332026-09-29 08:18:14.652 UTC [679] ERROR: relation "goose_db_version" does not exist at character 3611342026-09-29 08:18:14.652 UTC [679] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11352026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.02ms)11362026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.35ms)11372026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.31ms)11382026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (1.86ms)11392026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (1.73ms)11402026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000011412026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.11ms)11422026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000011432026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.18ms)11442026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.42ms)11452026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.51ms)11462026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.7ms)11472026/09/29 08:18:14 OK 3_commit_push.sql (1.69ms)11482026/09/29 08:18:14 goose: up to current file version: 311492026/09/29 08:18:14 OK 3_commit_push.sql (1.78ms)11502026/09/29 08:18:14 goose: up to current file version: 311512026/09/29 08:18:14 OK 20241026095416_initial_model.sql (8.08ms)11522026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)11532026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.82ms)11542026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (5.56ms)11552026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures11562026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.15ms)11572026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.55ms)11582026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.21ms)11592026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000011602026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.24ms)11612026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.3ms)11622026/09/29 08:18:14 OK 3_commit_push.sql (1.27ms)11632026/09/29 08:18:14 goose: up to current file version: 311642026-09-29 08:18:14.694 UTC [682] ERROR: relation "goose_db_version" does not exist at character 3611652026-09-29 08:18:14.694 UTC [682] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11662026/09/29 08:18:14 INFO Received push request method=POST path=/api/pushes11672026/09/29 08:18:14 OK 20241026095416_initial_model.sql (23.16ms)11682026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (11.81ms)11692026/09/29 08:18:14 OK 20251218171726_add_pins.sql (10.87ms)11702026-09-29 08:18:14.750 UTC [683] ERROR: relation "goose_db_version" does not exist at character 3611712026-09-29 08:18:14.750 UTC [683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11722026/09/29 08:18:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11732026/09/29 08:18:14 INFO Signed narinfos id=1 count=11174--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.57s)1175=== CONT TestIsValidCachePath1176=== RUN TestIsValidCachePath/narinfo1177=== PAUSE TestIsValidCachePath/narinfo1178=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1179=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1180=== RUN TestIsValidCachePath/nar_zst1181=== PAUSE TestIsValidCachePath/nar_zst1182=== RUN TestIsValidCachePath/nar_xz11832026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (11.25ms)1184=== PAUSE TestIsValidCachePath/nar_xz1185=== RUN TestIsValidCachePath/nar_bz21186=== PAUSE TestIsValidCachePath/nar_bz21187=== RUN TestIsValidCachePath/nar_uncompressed1188=== PAUSE TestIsValidCachePath/nar_uncompressed1189=== RUN TestIsValidCachePath/ls1190=== PAUSE TestIsValidCachePath/ls1191=== RUN TestIsValidCachePath/log1192=== PAUSE TestIsValidCachePath/log1193=== RUN TestIsValidCachePath/realisation1194=== PAUSE TestIsValidCachePath/realisation1195=== RUN TestIsValidCachePath/nix-cache-info1196=== PAUSE TestIsValidCachePath/nix-cache-info1197=== RUN TestIsValidCachePath/index.html1198=== PAUSE TestIsValidCachePath/index.html1199=== RUN TestIsValidCachePath/traversal_parent1200=== PAUSE TestIsValidCachePath/traversal_parent1201=== RUN TestIsValidCachePath/traversal_in_middle1202=== PAUSE TestIsValidCachePath/traversal_in_middle1203=== RUN TestIsValidCachePath/invalid_char_e1204=== PAUSE TestIsValidCachePath/invalid_char_e1205=== RUN TestIsValidCachePath/invalid_char_u1206=== PAUSE TestIsValidCachePath/invalid_char_u1207=== RUN TestIsValidCachePath/random_path1208=== PAUSE TestIsValidCachePath/random_path1209=== RUN TestIsValidCachePath/empty1210=== PAUSE TestIsValidCachePath/empty1211=== RUN TestIsValidCachePath/leading_slash1212=== PAUSE TestIsValidCachePath/leading_slash1213=== RUN TestIsValidCachePath/wrong_extension1214=== PAUSE TestIsValidCachePath/wrong_extension1215=== RUN TestIsValidCachePath/short_hash1216=== PAUSE TestIsValidCachePath/short_hash1217=== CONT TestProxyHeadersOnlyTrustedOnSocket12182026/09/29 08:18:14 OK 20260905000000_add_claims.sql (5.35ms)12192026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.15ms)12202026/09/29 08:18:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12212026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.26ms)12222026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000012232026/09/29 08:18:14 OK 20241026095416_initial_model.sql (7.76ms)12242026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.52ms)12252026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)12262026/09/29 08:18:14 OK 2_object_stats_trigger.sql (943.9µs)12272026/09/29 08:18:14 OK 3_commit_push.sql (1.57ms)12282026/09/29 08:18:14 goose: up to current file version: 312292026/09/29 08:18:14 OK 20251218171726_add_pins.sql (2.69ms)1230=== RUN TestPush_RejectsBadRequests/no_roots1231=== PAUSE TestPush_RejectsBadRequests/no_roots1232=== RUN TestPush_RejectsBadRequests/no_objects1233=== PAUSE TestPush_RejectsBadRequests/no_objects1234=== RUN TestPush_RejectsBadRequests/bad_root1235=== PAUSE TestPush_RejectsBadRequests/bad_root1236=== RUN TestPush_RejectsBadRequests/root_not_in_objects1237=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1238=== CONT TestParseSingleRange1239=== RUN TestParseSingleRange/none1240=== PAUSE TestParseSingleRange/none12412026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (2.79ms)1242=== RUN TestParseSingleRange/unknown_unit1243=== PAUSE TestParseSingleRange/unknown_unit1244=== RUN TestParseSingleRange/multi-range_ignored1245=== PAUSE TestParseSingleRange/multi-range_ignored1246=== RUN TestParseSingleRange/malformed_no_dash1247=== PAUSE TestParseSingleRange/malformed_no_dash1248=== RUN TestParseSingleRange/malformed_both_empty1249=== PAUSE TestParseSingleRange/malformed_both_empty1250=== RUN TestParseSingleRange/malformed_end_before_start1251=== PAUSE TestParseSingleRange/malformed_end_before_start1252=== RUN TestParseSingleRange/closed1253=== PAUSE TestParseSingleRange/closed1254=== RUN TestParseSingleRange/open-ended1255=== PAUSE TestParseSingleRange/open-ended1256=== RUN TestParseSingleRange/end_clamped_to_size1257=== PAUSE TestParseSingleRange/end_clamped_to_size1258=== RUN TestParseSingleRange/suffix1259=== PAUSE TestParseSingleRange/suffix1260=== RUN TestParseSingleRange/suffix_exceeds_size1261=== PAUSE TestParseSingleRange/suffix_exceeds_size1262=== RUN TestParseSingleRange/single_byte1263=== PAUSE TestParseSingleRange/single_byte1264=== RUN TestParseSingleRange/start_past_EOF1265=== PAUSE TestParseSingleRange/start_past_EOF1266=== RUN TestParseSingleRange/start_far_past_EOF1267=== PAUSE TestParseSingleRange/start_far_past_EOF1268=== CONT TestCreatePin_ReservedPins12692026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.15ms)12702026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (1.85ms)12712026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (1.8ms)12722026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000012732026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.54ms)12742026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.29ms)12752026/09/29 08:18:14 OK 3_commit_push.sql (1.39ms)12762026/09/29 08:18:14 goose: up to current file version: 31277--- PASS: TestService_Rustfstest (0.61s)1278=== CONT TestResurrectedObjectNotDeleted12792026/09/29 08:18:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37705/oidc1280--- PASS: TestReadProxyRangeRequest (0.65s)1281=== CONT TestOrphanedObjectsGCStressTest12822026-09-29 08:18:14.838 UTC [689] ERROR: relation "goose_db_version" does not exist at character 3612832026-09-29 08:18:14.838 UTC [689] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12842026/09/29 08:18:14 OK 20241026095416_initial_model.sql (8.72ms)12852026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures12862026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)12872026/09/29 08:18:14 OK 20251218171726_add_pins.sql (2.88ms)12882026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (4.74ms)12892026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.07ms)12902026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.81ms)12912026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.59ms)12922026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000012932026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.35ms)12942026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.82ms)12952026/09/29 08:18:14 OK 3_commit_push.sql (1.37ms)12962026/09/29 08:18:14 goose: up to current file version: 312972026/09/29 08:18:14 INFO Received push request method=POST path=/api/pushes12982026-09-29 08:18:14.892 UTC [693] ERROR: relation "goose_db_version" does not exist at character 3612992026-09-29 08:18:14.892 UTC [693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13002026/09/29 08:18:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13012026/09/29 08:18:14 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWJlOWQ1ZTgtZTRkMi00OGEyLWFmM2QtNjViZDVjYjk0ZWYwLmE5ZWU2ZDQxLTU4YTctNGFiMC1hYzkwLWJjZDJjYzE4OTBlNXgxNzkwNjY5ODk0ODY2MjE4NTIw13022026/09/29 08:18:14 OK 20241026095416_initial_model.sql (18.24ms)13032026/09/29 08:18:14 INFO Received complete push request method=POST path=/api/pushes/1/complete1304--- PASS: TestReadRedirectUsesPublicS3URL (0.64s)1305=== CONT TestOrphanedObjectsGC13062026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)13072026/09/29 08:18:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWJlOWQ1ZTgtZTRkMi00OGEyLWFmM2QtNjViZDVjYjk0ZWYwLmE5ZWU2ZDQxLTU4YTctNGFiMC1hYzkwLWJjZDJjYzE4OTBlNXgxNzkwNjY5ODk0ODY2MjE4NTIw parts=11308--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.64s)1309=== CONT TestObjectStatsTrigger13102026/09/29 08:18:14 OK 20251218171726_add_pins.sql (2.54ms)13112026/09/29 08:18:14 INFO Received push request method=POST path=/api/pushes13122026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (2.54ms)13132026/09/29 08:18:14 OK 20260905000000_add_claims.sql (2.04ms)13142026-09-29 08:18:14.927 UTC [698] ERROR: relation "goose_db_version" does not exist at character 3613152026-09-29 08:18:14.927 UTC [698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13162026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (1.55ms)13172026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.97ms)13182026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000013192026/09/29 08:18:14 INFO Received complete push request method=POST path=/api/pushes/2/complete13202026-09-29 08:18:14.934 UTC [695] ERROR: Push object missing: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo13212026-09-29 08:18:14.934 UTC [695] CONTEXT: PL/pgSQL function commit_push(bigint) line 37 at RAISE13222026-09-29 08:18:14.934 UTC [695] STATEMENT: -- name: CommitPush :exec1323 SELECT commit_push($1::bigint)1324 13252026-09-29 08:18:14.934 UTC [701] ERROR: relation "goose_db_version" does not exist at character 3613262026-09-29 08:18:14.934 UTC [701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13272026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.44ms)1328--- PASS: TestPush_CommitFailsWhenSkippedKeyWasCollected (0.66s)1329=== CONT TestMultipartCleanup13302026/09/29 08:18:14 OK 2_object_stats_trigger.sql (1.46ms)13312026/09/29 08:18:14 OK 3_commit_push.sql (1.78ms)13322026/09/29 08:18:14 goose: up to current file version: 31333--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.66s)1334=== CONT TestServerTLSConfig1335=== RUN TestServerTLSConfig/no_client_CA1336=== PAUSE TestServerTLSConfig/no_client_CA1337=== RUN TestServerTLSConfig/missing_CA_file1338=== PAUSE TestServerTLSConfig/missing_CA_file1339=== RUN TestServerTLSConfig/not_a_PEM_file1340=== PAUSE TestServerTLSConfig/not_a_PEM_file1341=== CONT TestService_NativeMTLS13422026/09/29 08:18:14 OK 20241026095416_initial_model.sql (10.34ms)13432026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)13442026/09/29 08:18:14 OK 20241026095416_initial_model.sql (9.51ms)13452026/09/29 08:18:14 OK 20251218171726_add_pins.sql (4.78ms)13462026/09/29 08:18:14 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)13472026/09/29 08:18:14 OK 20251218171726_add_pins.sql (3.09ms)13482026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)13492026/09/29 08:18:14 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)13502026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.42ms)13512026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (2.51ms)13522026/09/29 08:18:14 OK 20260905000000_add_claims.sql (3.72ms)13532026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.64ms)13542026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000013552026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures13562026/09/29 08:18:14 OK 20260920000000_drop_claims.sql (4.21ms)13572026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.91ms)13582026/09/29 08:18:14 OK 20260923120000_add_pushes.sql (2.75ms)13592026/09/29 08:18:14 goose: successfully migrated database to version: 2026092312000013602026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.01ms)13612026/09/29 08:18:14 OK 1_commit_pending_closure.sql (2.38ms)13622026/09/29 08:18:14 OK 3_commit_push.sql (2.66ms)13632026/09/29 08:18:14 goose: up to current file version: 313642026/09/29 08:18:14 OK 2_object_stats_trigger.sql (2.35ms)13652026/09/29 08:18:14 OK 3_commit_push.sql (1.65ms)13662026/09/29 08:18:14 goose: up to current file version: 313672026/09/29 08:18:14 INFO Received uploads request method=POST path=/api/pending_closures1368--- PASS: TestReadRedirectNar (0.72s)1369=== CONT TestMetricsInventory13702026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes13712026-09-29 08:18:15.025 UTC [708] ERROR: relation "goose_db_version" does not exist at character 3613722026-09-29 08:18:15.025 UTC [708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13732026-09-29 08:18:15.027 UTC [709] ERROR: relation "goose_db_version" does not exist at character 3613742026-09-29 08:18:15.027 UTC [709] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13752026-09-29 08:18:15.035 UTC [710] ERROR: relation "goose_db_version" does not exist at character 3613762026-09-29 08:18:15.035 UTC [710] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13772026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.44ms)13782026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)13792026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.38ms)13802026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.24ms)13812026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)13822026-09-29 08:18:15.047 UTC [711] ERROR: relation "goose_db_version" does not exist at character 3613832026-09-29 08:18:15.047 UTC [711] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13842026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.97ms)13852026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)13862026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.9ms)13872026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.76ms)13882026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.38ms)13892026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (4.16ms)1390--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.78s)1391=== CONT TestNARDeduplicationMetadataUploadBug13922026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.43ms)13932026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.08ms)13942026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.6ms)13952026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (1.94ms)13962026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.36ms)13972026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000013982026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.4ms)13992026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.87ms)14002026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000014012026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.11ms)14022026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.64ms)14032026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.35ms)14042026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.11ms)14052026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.91ms)14062026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)14072026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.56ms)14082026/09/29 08:18:15 OK 3_commit_push.sql (1.43ms)1409--- PASS: TestReadRedirectKeepsNarinfoProxied (0.78s)14102026/09/29 08:18:15 goose: up to current file version: 31411=== CONT TestCreatePendingClosureRejectsOversizedNAR14122026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures1413--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1414=== CONT TestResolveDBConnectionString1415=== RUN TestResolveDBConnectionString/flag_wins1416=== PAUSE TestResolveDBConnectionString/flag_wins1417=== RUN TestResolveDBConnectionString/file_when_flag_empty1418=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1419=== RUN TestResolveDBConnectionString/missing_file_is_an_error1420=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1421=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1422=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1423=== RUN TestResolveDBConnectionString/nothing_configured1424=== PAUSE TestResolveDBConnectionString/nothing_configured1425=== CONT TestGCTaskStore_GetEmpty1426--- PASS: TestGCTaskStore_GetEmpty (0.00s)1427=== CONT TestGCTaskStore_ConflictDifferentParams1428--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1429=== CONT TestGCTaskStore_DeduplicateSameParams1430--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1431=== CONT TestGCTaskStore_StartNew1432--- PASS: TestGCTaskStore_StartNew (0.00s)1433=== CONT TestGCMetrics14342026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.29ms)14352026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.8ms)14362026/09/29 08:18:15 OK 3_commit_push.sql (2.07ms)14372026/09/29 08:18:15 goose: up to current file version: 314382026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.04ms)14392026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000014402026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)14412026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.56ms)14422026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.15ms)14432026/09/29 08:18:15 OK 3_commit_push.sql (2.52ms)14442026/09/29 08:18:15 goose: up to current file version: 314452026/09/29 08:18:15 OK 20260905000000_add_claims.sql (7.21ms)14462026/09/29 08:18:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14472026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.67ms)14482026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.46ms)14492026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000014502026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.93ms)14512026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.9ms)14522026/09/29 08:18:15 OK 3_commit_push.sql (2.05ms)14532026/09/29 08:18:15 goose: up to current file version: 31454--- PASS: TestReadProxyConditionalGet (0.81s)1455=== CONT TestGCBugBareHashReferences14562026-09-29 08:18:15.101 UTC [736] ERROR: relation "goose_db_version" does not exist at character 3614572026-09-29 08:18:15.101 UTC [736] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14582026/09/29 08:18:15 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OWJlOWQ1ZTgtZTRkMi00OGEyLWFmM2QtNjViZDVjYjk0ZWYwLmViNWQ3ODJkLWM0YzEtNDA2MC05ZTY4LTNiNzE1Mzk5MWNlOXgxNzkwNjY5ODk0NTgxMzI1OTM3 parts=1014592026/09/29 08:18:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14602026/09/29 08:18:15 INFO Completed upload id=114612026/09/29 08:18:15 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014622026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures14632026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes14642026/09/29 08:18:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures14652026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.96ms)14662026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)14672026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.26ms)14682026/09/29 08:18:15 INFO Aborted multipart uploads count=01469--- PASS: TestReadProxyDisabled (0.86s)1470=== CONT TestLeadEndsOnShutdown14712026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (19.37ms)14722026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.33ms)14732026/09/29 08:18:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=014742026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.03ms)14752026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.74ms)14762026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000014772026/09/29 08:18:15 INFO Vacuumed table table=pending_closures14782026/09/29 08:18:15 INFO Received complete push request method=POST path=/api/pushes/1/complete14792026/09/29 08:18:15 INFO Vacuumed table table=pending_objects14802026-09-29 08:18:15.153 UTC [743] ERROR: relation "goose_db_version" does not exist at character 3614812026-09-29 08:18:15.153 UTC [743] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14822026/09/29 08:18:15 OK 1_commit_pending_closure.sql (3.2ms)14832026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.82ms)14842026/09/29 08:18:15 INFO Vacuumed table table=multipart_uploads14852026/09/29 08:18:15 OK 3_commit_push.sql (1.78ms)14862026/09/29 08:18:15 goose: up to current file version: 314872026/09/29 08:18:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1488--- PASS: TestPush_CompleteCommitsEveryRoot (0.88s)1489=== CONT TestLeadElectsOneAndHandsOver14902026/09/29 08:18:15 INFO Vacuumed table table=closures14912026/09/29 08:18:15 INFO Vacuumed table table=objects14922026-09-29 08:18:15.163 UTC [744] ERROR: relation "goose_db_version" does not exist at character 3614932026-09-29 08:18:15.163 UTC [744] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14942026/09/29 08:18:15 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001495--- PASS: TestService_createPendingClosureHandler (0.98s)1496=== CONT TestCompletedNarNotReofferedAcrossClosures14972026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.55ms)14982026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)14992026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.21ms)1500--- PASS: TestReadProxyHead (0.79s)1501=== CONT TestClientCADerivations15022026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.43ms)15032026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.04ms)15042026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)15052026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.6ms)15062026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.8ms)15072026/09/29 08:18:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OWJlOWQ1ZTgtZTRkMi00OGEyLWFmM2QtNjViZDVjYjk0ZWYwLjg1OGUxNWIzLTk3MGMtNGI2NS05MzFkLTY5OTZjY2Y3N2Q1MngxNzkwNjY5ODk0NjkxMDA4MDcx parts=1015082026/09/29 08:18:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15092026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.7ms)15102026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.72ms)15112026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000015122026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.77ms)15132026/09/29 08:18:15 INFO Completed upload id=115142026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.88ms)15152026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.21ms)15162026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures15172026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.97ms)15182026/09/29 08:18:15 OK 3_commit_push.sql (1.4ms)15192026/09/29 08:18:15 goose: up to current file version: 315202026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures15212026-09-29 08:18:15.194 UTC [751] ERROR: relation "goose_db_version" does not exist at character 3615222026-09-29 08:18:15.194 UTC [751] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15232026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.86ms)15242026/09/29 08:18:15 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15252026/09/29 08:18:15 WARN Found objects in DB but missing from S3, will re-upload count=11526--- PASS: TestReadProxyInvalidPath (0.68s)1527=== CONT TestClientFallsBackToClosures1528--- PASS: TestService_verifyS3Integrity (1.01s)1529=== CONT TestClientPushesUseOnePush15302026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (4.11ms)15312026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000015322026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.29ms)15332026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.61ms)15342026/09/29 08:18:15 OK 3_commit_push.sql (1.49ms)15352026/09/29 08:18:15 goose: up to current file version: 315362026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.45ms)15372026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)15382026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.16ms)1539--- PASS: TestReadProxy404 (0.70s)1540=== CONT TestGCTaskStore_GetReturnsLatest1541--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1542=== CONT TestPinProtectsFromGC15432026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (12.12ms)15442026/09/29 08:18:15 OK 20260905000000_add_claims.sql (7.15ms)15452026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.47ms)15462026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (4.12ms)15472026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000015482026-09-29 08:18:15.245 UTC [758] ERROR: relation "goose_db_version" does not exist at character 3615492026-09-29 08:18:15.245 UTC [758] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15502026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.47ms)15512026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.67ms)15522026/09/29 08:18:15 OK 3_commit_push.sql (1.8ms)15532026/09/29 08:18:15 goose: up to current file version: 31554--- PASS: TestReadProxyNarStreaming (0.71s)1555=== CONT TestClientSharedPathCommittedMidPush15562026/09/29 08:18:15 OK 20241026095416_initial_model.sql (11ms)15572026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)15582026/09/29 08:18:15 OK 20251218171726_add_pins.sql (4.22ms)15592026-09-29 08:18:15.274 UTC [761] ERROR: relation "goose_db_version" does not exist at character 3615602026-09-29 08:18:15.274 UTC [761] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15612026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)15622026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.56ms)15632026-09-29 08:18:15.281 UTC [762] ERROR: relation "goose_db_version" does not exist at character 3615642026-09-29 08:18:15.281 UTC [762] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15652026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.37ms)1566--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.69s)1567=== CONT TestGenerateLandingPage1568--- PASS: TestGenerateLandingPage (0.00s)1569=== CONT TestService_readinessHandler15702026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (10.69ms)15712026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000015722026/09/29 08:18:15 OK 1_commit_pending_closure.sql (4.84ms)15732026/09/29 08:18:15 OK 20241026095416_initial_model.sql (17.26ms)15742026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.63ms)15752026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.89ms)15762026/09/29 08:18:15 OK 3_commit_push.sql (2.09ms)15772026/09/29 08:18:15 goose: up to current file version: 315782026/09/29 08:18:15 OK 20251218171726_add_pins.sql (4.78ms)15792026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.6ms)15802026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)15812026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (4.72ms)15822026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.84ms)15832026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.98ms)15842026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (6.36ms)15852026-09-29 08:18:15.319 UTC [765] ERROR: relation "goose_db_version" does not exist at character 3615862026-09-29 08:18:15.319 UTC [765] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15872026-09-29 08:18:15.319 UTC [766] ERROR: relation "goose_db_version" does not exist at character 3615882026-09-29 08:18:15.319 UTC [766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15892026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (4.14ms)1590--- PASS: TestReadProxyNarinfo (0.67s)1591=== CONT TestClientWithDependencies15922026-09-29 08:18:15.321 UTC [767] ERROR: relation "goose_db_version" does not exist at character 3615932026-09-29 08:18:15.321 UTC [767] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15942026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.96ms)15952026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000015962026/09/29 08:18:15 OK 20260905000000_add_claims.sql (4.52ms)15972026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.92ms)15982026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.9ms)15992026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.52ms)16002026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.05ms)16012026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016022026/09/29 08:18:15 OK 3_commit_push.sql (2.17ms)16032026/09/29 08:18:15 goose: up to current file version: 316042026/09/29 08:18:15 OK 1_commit_pending_closure.sql (3.11ms)16052026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.51ms)16062026/09/29 08:18:15 OK 20241026095416_initial_model.sql (10.26ms)16072026/09/29 08:18:15 OK 3_commit_push.sql (2.81ms)16082026/09/29 08:18:15 goose: up to current file version: 316092026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.48ms)16102026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)16112026-09-29 08:18:15.337 UTC [770] ERROR: relation "goose_db_version" does not exist at character 3616122026-09-29 08:18:15.337 UTC [770] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16132026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.48ms)16142026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.76ms)16152026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.48ms)16162026/09/29 08:18:15 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3696026676/001/proxy.sock16172026/09/29 08:18:15 INFO Starting HTTP server address=127.0.0.1:4302716182026/09/29 08:18:15 OK 20241026095416_initial_model.sql (15.12ms)16192026/09/29 08:18:15 WARN mTLS auth: subject not in bound subjects subject="CN=someone"16202026/09/29 08:18:15 INFO Shutdown signal received, draining in-flight requests timeout=10s1621--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.58s)1622=== CONT TestService_healthCheckHandler16232026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (4.22ms)16242026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)16252026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (3.09ms)16262026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.46ms)16272026/09/29 08:18:15 OK 20260905000000_add_claims.sql (4.2ms)16282026/09/29 08:18:15 OK 20251218171726_add_pins.sql (4.9ms)16292026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.72ms)16302026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.68ms)16312026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.81ms)16322026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016332026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (3.57ms)16342026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016352026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (5.95ms)16362026/09/29 08:18:15 OK 20241026095416_initial_model.sql (11.89ms)16372026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.91ms)16382026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)16392026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.12ms)16402026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.99ms)16412026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.78ms)16422026/09/29 08:18:15 OK 3_commit_push.sql (1.58ms)16432026/09/29 08:18:15 goose: up to current file version: 316442026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.25ms)16452026/09/29 08:18:15 OK 20260905000000_add_claims.sql (4.74ms)16462026/09/29 08:18:15 OK 3_commit_push.sql (1.21ms)16472026/09/29 08:18:15 goose: up to current file version: 316482026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3ms)16492026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)16502026-09-29 08:18:15.374 UTC [773] ERROR: relation "goose_db_version" does not exist at character 3616512026-09-29 08:18:15.374 UTC [773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16522026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (12.07ms)16532026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016542026/09/29 08:18:15 OK 20260905000000_add_claims.sql (14.26ms)16552026/09/29 08:18:15 OK 1_commit_pending_closure.sql (4.13ms)16562026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.29ms)16572026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.97ms)16582026/09/29 08:18:15 OK 3_commit_push.sql (2.05ms)16592026/09/29 08:18:15 goose: up to current file version: 316602026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.42ms)16612026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016622026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.39ms)16632026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.33ms)16642026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.05ms)16652026/09/29 08:18:15 OK 3_commit_push.sql (1.73ms)16662026/09/29 08:18:15 goose: up to current file version: 316672026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.7ms)16682026-09-29 08:18:15.393 UTC [774] ERROR: relation "goose_db_version" does not exist at character 3616692026-09-29 08:18:15.393 UTC [774] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16702026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.65ms)16712026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.72ms)16722026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.94ms)16732026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.22ms)16742026/09/29 08:18:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux16752026/09/29 08:18:15 WARN Refused reserved pin name=worker-x86_64-linux16762026/09/29 08:18:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux16772026/09/29 08:18:15 INFO Received create pin request method=POST path=/api/pins/my-app16782026/09/29 08:18:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux16792026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.31ms)16802026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016812026/09/29 08:18:15 OK 20241026095416_initial_model.sql (7.95ms)1682--- PASS: TestCreatePin_ReservedPins (0.63s)1683=== CONT TestClientMultipleUploads16842026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.6ms)16852026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)16862026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.04ms)16872026/09/29 08:18:15 OK 3_commit_push.sql (872.3µs)16882026/09/29 08:18:15 goose: up to current file version: 316892026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.59ms)16902026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.19ms)16912026-09-29 08:18:15.417 UTC [776] ERROR: relation "goose_db_version" does not exist at character 3616922026-09-29 08:18:15.417 UTC [776] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16932026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.91ms)16942026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.52ms)16952026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (3.24ms)16962026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000016972026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.95ms)16982026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.67ms)1699--- PASS: TestResurrectedObjectNotDeleted (0.63s)17002026/09/29 08:18:15 OK 3_commit_push.sql (2.37ms)1701=== CONT TestGracefulShutdownDrainsInflight17022026/09/29 08:18:15 goose: up to current file version: 317032026/09/29 08:18:15 INFO Starting HTTP server address=127.0.0.1:4409117042026/09/29 08:18:15 INFO Shutdown signal received, draining in-flight requests timeout=10s17052026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.42ms)17062026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (999.88µs)17072026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.86ms)17082026-09-29 08:18:15.439 UTC [778] ERROR: relation "goose_db_version" does not exist at character 3617092026-09-29 08:18:15.439 UTC [778] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17102026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)17112026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.83ms)17122026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (1.89ms)17132026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.92ms)17142026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000017152026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.18ms)17162026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.1ms)17172026/09/29 08:18:15 OK 3_commit_push.sql (1.23ms)17182026/09/29 08:18:15 goose: up to current file version: 317192026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.04ms)17202026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (987.39µs)17212026/09/29 08:18:15 OK 20251218171726_add_pins.sql (1.93ms)17222026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)17232026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.92ms)17242026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.21ms)17252026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.38ms)17262026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000017272026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.01ms)17282026/09/29 08:18:15 OK 2_object_stats_trigger.sql (986.38µs)17292026/09/29 08:18:15 OK 3_commit_push.sql (1.22ms)17302026/09/29 08:18:15 goose: up to current file version: 31731--- PASS: TestObjectStatsTrigger (0.58s)1732=== CONT TestClientIntegration17332026-09-29 08:18:15.498 UTC [779] ERROR: relation "goose_db_version" does not exist at character 3617342026-09-29 08:18:15.498 UTC [779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1735--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1736=== CONT TestGCTaskStore_Fail1737--- PASS: TestGCTaskStore_Fail (0.00s)1738=== CONT TestClientErrorHandling1739=== RUN TestClientErrorHandling/InvalidStorePath1740=== PAUSE TestClientErrorHandling/InvalidStorePath1741=== RUN TestClientErrorHandling/InvalidAuthToken1742=== PAUSE TestClientErrorHandling/InvalidAuthToken1743=== RUN TestClientErrorHandling/ServerNotAvailable1744=== PAUSE TestClientErrorHandling/ServerNotAvailable1745=== CONT TestGCTaskStore_PhaseUpdates1746--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1747=== CONT TestService_RequireScope_OIDC17482026/09/29 08:18:15 OK 20241026095416_initial_model.sql (6.31ms)17492026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures17502026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)17512026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.45ms)17522026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)17532026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.36ms)17542026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.44ms)17552026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (2.08ms)17562026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000017572026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.25ms)17582026/09/29 08:18:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17592026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.67ms)17602026/09/29 08:18:15 OK 3_commit_push.sql (1.07ms)17612026/09/29 08:18:15 goose: up to current file version: 317622026/09/29 08:18:15 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17632026/09/29 08:18:15 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1764--- PASS: TestService_NativeMTLS (0.59s)1765=== CONT TestGCTaskStore_CompletedAllowsNewTask1766--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1767=== CONT TestCacheStatsHandler17682026/09/29 08:18:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OWJlOWQ1ZTgtZTRkMi00OGEyLWFmM2QtNjViZDVjYjk0ZWYwLmZlMjk5MjY1LTY2Y2ItNDBkMS04YzQ1LTA0OTIyNTAzMjc2N3gxNzkwNjY5ODk0OTgyMDc3NDY3 parts=121769--- PASS: TestRedundantMultipartUpload (1.29s)1770=== CONT TestCacheConfigHandler1771=== RUN TestCacheConfigHandler/full_config,_no_issuer1772=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1773=== RUN TestCacheConfigHandler/no_cache_url_configured1774=== PAUSE TestCacheConfigHandler/no_cache_url_configured1775=== RUN TestCacheConfigHandler/no_signing_keys1776=== PAUSE TestCacheConfigHandler/no_signing_keys1777=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1778=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1779=== CONT TestService_ReadScope_PublicByDefault17802026-09-29 08:18:15.580 UTC [786] ERROR: relation "goose_db_version" does not exist at character 3617812026-09-29 08:18:15.580 UTC [786] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1782--- PASS: TestMetricsInventory (0.58s)1783=== CONT TestService_ReadAuthMiddleware17842026/09/29 08:18:15 OK 20241026095416_initial_model.sql (11.74ms)17852026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)17862026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.7ms)17872026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (4.03ms)17882026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.46ms)17892026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.61ms)17902026/09/29 08:18:15 INFO Aborted multipart uploads count=017912026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.79ms)17922026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000017932026/09/29 08:18:15 WARN Force mode enabled - objects will be deleted immediately without grace period17942026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.92ms)17952026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.75ms)17962026/09/29 08:18:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017972026/09/29 08:18:15 OK 3_commit_push.sql (1.37ms)17982026/09/29 08:18:15 goose: up to current file version: 317992026/09/29 08:18:15 INFO Vacuumed table table=pending_closures18002026/09/29 08:18:15 INFO Vacuumed table table=pending_objects18012026/09/29 08:18:15 INFO Received cleanup request method=DELETE path=/api/pending_closures18022026/09/29 08:18:15 INFO Vacuumed table table=multipart_uploads18032026/09/29 08:18:15 INFO Vacuumed table table=closures18042026/09/29 08:18:15 INFO Vacuumed table table=objects18052026/09/29 08:18:15 INFO Aborted multipart uploads count=118062026-09-29 08:18:15.628 UTC [807] ERROR: relation "goose_db_version" does not exist at character 3618072026-09-29 08:18:15.628 UTC [807] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1808--- PASS: TestGCMetrics (0.56s)1809=== CONT TestService_AuthMiddleware_OIDC1810--- PASS: TestMultipartCleanup (0.70s)1811=== NAME TestNARDeduplicationMetadataUploadBug1812 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug806446268/001/store/pkzsja6x3kpmcidb369xh3r558n4r4vq-file1.txt1813=== CONT TestService_AuthMiddleware_MTLSBoundSubjects18142026/09/29 08:18:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39959/oidc18152026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.3ms)18162026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)18172026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.68ms)18182026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)18192026/09/29 08:18:15 INFO lead: acquired remote=192.0.2.1:123418202026/09/29 08:18:15 INFO lead: released remote=192.0.2.1:12341821--- PASS: TestLeadEndsOnShutdown (0.51s)1822=== CONT TestService_AuthMiddleware_MTLSProxyHeader18232026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.44ms)18242026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.2ms)18252026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (3.36ms)18262026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000018272026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.62ms)18282026-09-29 08:18:15.664 UTC [832] ERROR: relation "goose_db_version" does not exist at character 3618292026-09-29 08:18:15.664 UTC [832] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18302026/09/29 08:18:15 OK 2_object_stats_trigger.sql (12.33ms)18312026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures18322026/09/29 08:18:15 OK 3_commit_push.sql (3.59ms)18332026/09/29 08:18:15 goose: up to current file version: 318342026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.55ms)18352026-09-29 08:18:15.690 UTC [834] ERROR: relation "goose_db_version" does not exist at character 3618362026-09-29 08:18:15.690 UTC [834] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18372026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (3.23ms)18382026/09/29 08:18:15 OK 20251218171726_add_pins.sql (4.23ms)18392026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.97ms)18402026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.51ms)18412026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.6ms)18422026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.85ms)18432026/09/29 08:18:15 INFO lead: acquired remote=192.0.2.1:123418442026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.9ms)18452026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000018462026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)18472026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes18482026/09/29 08:18:15 OK 20251218171726_add_pins.sql (13.59ms)18492026/09/29 08:18:15 OK 1_commit_pending_closure.sql (14.53ms)18502026/09/29 08:18:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35385/oidc18512026/09/29 08:18:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18522026/09/29 08:18:15 INFO Uploading pkzsja6x3kpmcidb369xh3r558n4r4vq-file1.txt (160B)18532026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (9.63ms)18542026/09/29 08:18:15 OK 2_object_stats_trigger.sql (9.51ms)18552026/09/29 08:18:15 OK 3_commit_push.sql (2.29ms)18562026/09/29 08:18:15 goose: up to current file version: 318572026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.4ms)18582026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.24ms)18592026/09/29 08:18:15 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18602026/09/29 08:18:15 WARN Failed to register uploaded object key=pkzsja6x3kpmcidb369xh3r558n4r4vq.ls error="server returned 404: 404 page not found\n"18612026/09/29 08:18:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18622026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.98ms)18632026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000018642026/09/29 08:18:15 INFO Signed narinfos id=1 count=118652026/09/29 08:18:15 INFO Uploading 1 narinfos18662026-09-29 08:18:15.743 UTC [855] ERROR: relation "goose_db_version" does not exist at character 3618672026-09-29 08:18:15.743 UTC [855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18682026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.84ms)18692026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.14ms)18702026-09-29 08:18:15.744 UTC [856] ERROR: relation "goose_db_version" does not exist at character 3618712026-09-29 08:18:15.744 UTC [856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18722026/09/29 08:18:15 OK 3_commit_push.sql (990.8µs)18732026/09/29 08:18:15 goose: up to current file version: 318742026/09/29 08:18:15 INFO Received complete push request method=POST path=/api/pushes/1/complete18752026/09/29 08:18:15 WARN Failed to register uploaded object key=pkzsja6x3kpmcidb369xh3r558n4r4vq.narinfo error="server returned 404: 404 page not found\n"18762026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.13ms)18772026/09/29 08:18:15 INFO Upload complete. (84ms)1878=== NAME TestNARDeduplicationMetadataUploadBug1879 metadata_upload_test.go:54: Retrieved narinfo from S3:1880 StorePath: /build/TestNARDeduplicationMetadataUploadBug806446268/001/store/pkzsja6x3kpmcidb369xh3r558n4r4vq-file1.txt1881 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1882 Compression: zstd1883 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf18842026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)1885 NarSize: 1601886 References: 1887 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf18882026/09/29 08:18:15 OK 20241026095416_initial_model.sql (9.73ms)18892026-09-29 08:18:15.761 UTC [857] ERROR: relation "goose_db_version" does not exist at character 3618902026-09-29 08:18:15.761 UTC [857] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18912026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)1892 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1893 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1894 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}18952026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.64ms)18962026/09/29 08:18:15 OK 20251218171726_add_pins.sql (3.35ms)18972026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.53ms)18982026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.95ms)18992026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)19002026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.2ms)19012026/09/29 08:18:15 OK 20260905000000_add_claims.sql (3.19ms)19022026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.77ms)19032026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000019042026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.61ms)19052026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.32ms)19062026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)19072026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (3.59ms)19082026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.19ms)19092026/09/29 08:18:15 OK 3_commit_push.sql (905.53µs)19102026/09/29 08:18:15 goose: up to current file version: 319112026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.72ms)19122026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000019132026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.3ms)19142026/09/29 08:18:15 OK 1_commit_pending_closure.sql (2.42ms)19152026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (3.03ms)19162026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.35ms)19172026/09/29 08:18:15 OK 3_commit_push.sql (1.39ms)19182026/09/29 08:18:15 goose: up to current file version: 319192026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.72ms)19202026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (2.12ms)19212026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.62ms)19222026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000019232026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.89ms)1924=== NAME TestOrphanedObjectsGC1925 orphaned_objects_gc_test.go:290: GC Test Summary:1926 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1927 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1928 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1929 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1930 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1931--- PASS: TestOrphanedObjectsGC (0.87s)1932=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19332026/09/29 08:18:15 INFO Received uploads request method=POST path=/19342026/09/29 08:18:15 OK 2_object_stats_trigger.sql (1.15ms)1935=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19362026/09/29 08:18:15 INFO Received complete multipart upload request method=POST path=/1937=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19382026/09/29 08:18:15 INFO Received request for more parts method=POST path=/1939=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19402026/09/29 08:18:15 INFO Received uploads request method=POST path=/1941--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1942 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1943 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1944 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1945 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1946=== CONT TestProxyWriteTimeout/narinfo1947=== CONT TestProxyWriteTimeout/unknown_size1948=== CONT TestProxyWriteTimeout/10_GiB_nar1949=== CONT TestProxyWriteTimeout/1_GiB_nar1950--- PASS: TestProxyWriteTimeout (0.09s)1951 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1952 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1953 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1954 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1955=== CONT TestIsValidUploadKey/narinfo1956=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1957=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1958=== CONT TestIsValidUploadKey/index.html19592026/09/29 08:18:15 OK 3_commit_push.sql (822.13µs)1960=== CONT TestIsValidUploadKey/nix-cache-info19612026/09/29 08:18:15 goose: up to current file version: 31962=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1963=== CONT TestIsValidUploadKey/realisation_plus_in_output1964=== CONT TestIsValidUploadKey/realisation1965=== CONT TestIsValidUploadKey/build_log_equals1966=== CONT TestIsValidUploadKey/build_log_question_mark1967=== CONT TestIsValidUploadKey/build_log_plus_in_name1968=== CONT TestIsValidUploadKey/build_log_home-manager_file1969=== CONT TestIsValidUploadKey/build_log1970=== CONT TestIsValidUploadKey/listing1971=== CONT TestIsValidUploadKey/nar_plain1972=== CONT TestIsValidUploadKey/nar_xz1973=== CONT TestIsValidUploadKey/nar_zst1974=== CONT TestIsValidUploadKey/unknown_type1975=== CONT TestIsValidUploadKey/traversal_nar1976=== CONT TestIsValidUploadKey/empty_key1977=== CONT TestIsValidUploadKey/traversal1978=== CONT TestIsValidUploadKey/absolute1979--- PASS: TestIsValidUploadKey (0.10s)1980 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1981 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1982 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1983 --- PASS: TestIsValidUploadKey/index.html (0.00s)1984 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1985 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1986 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1987 --- PASS: TestIsValidUploadKey/realisation (0.00s)1988 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1989 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1990 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1991 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1992 --- PASS: TestIsValidUploadKey/build_log (0.00s)1993 --- PASS: TestIsValidUploadKey/listing (0.00s)1994 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1995 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1996 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1997 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1998 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1999 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2000 --- PASS: TestIsValidUploadKey/traversal (0.00s)2001 --- PASS: TestIsValidUploadKey/absolute (0.00s)2002=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20032026/09/29 08:18:15 INFO Received complete multipart upload request method=POST path=/2004=== NAME TestNARDeduplicationMetadataUploadBug2005 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug806446268/001/store/xny1x4npfx635swd0znzqbws8qvgp3jz-file2.txt20062026-09-29 08:18:15.824 UTC [923] ERROR: relation "goose_db_version" does not exist at character 3620072026-09-29 08:18:15.824 UTC [923] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20082026/09/29 08:18:15 OK 20241026095416_initial_model.sql (7.59ms)20092026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (940.1µs)20102026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.11ms)20112026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (2.59ms)20122026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.38ms)20132026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (1.47ms)20142026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.01ms)20152026/09/29 08:18:15 goose: successfully migrated database to version: 2026092312000020162026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.36ms)20172026/09/29 08:18:15 OK 2_object_stats_trigger.sql (657.01µs)20182026/09/29 08:18:15 OK 3_commit_push.sql (700.39µs)20192026/09/29 08:18:15 goose: up to current file version: 32020=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20212026/09/29 08:18:15 INFO Received request for more parts method=POST path=/20222026/09/29 08:18:15 INFO lead: released remote=192.0.2.1:12342023--- PASS: TestGCBugBareHashReferences (0.77s)2024=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20252026/09/29 08:18:15 INFO Received uploads request method=POST path=/20262026/09/29 08:18:15 WARN readiness check failed error="closed pool"2027--- PASS: TestService_readinessHandler (0.58s)2028=== CONT TestIsValidCachePath/narinfo2029=== CONT TestIsValidCachePath/short_hash2030=== CONT TestIsValidCachePath/wrong_extension2031=== CONT TestIsValidCachePath/leading_slash2032=== CONT TestIsValidCachePath/empty2033=== CONT TestIsValidCachePath/random_path2034=== CONT TestIsValidCachePath/invalid_char_u2035=== CONT TestIsValidCachePath/invalid_char_e2036=== CONT TestIsValidCachePath/traversal_in_middle2037=== CONT TestIsValidCachePath/traversal_parent2038=== CONT TestIsValidCachePath/index.html2039=== CONT TestIsValidCachePath/nix-cache-info2040=== CONT TestIsValidCachePath/realisation2041=== CONT TestIsValidCachePath/log2042=== CONT TestIsValidCachePath/ls2043=== CONT TestIsValidCachePath/nar_uncompressed2044=== CONT TestIsValidCachePath/nar_bz22045=== CONT TestIsValidCachePath/nar_xz2046=== CONT TestIsValidCachePath/nar_zst2047=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2048=== CONT TestPush_RejectsBadRequests/no_roots20492026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes2050--- PASS: TestIsValidCachePath (0.00s)2051 --- PASS: TestIsValidCachePath/narinfo (0.00s)2052 --- PASS: TestIsValidCachePath/short_hash (0.00s)2053 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2054 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2055 --- PASS: TestIsValidCachePath/empty (0.00s)2056 --- PASS: TestIsValidCachePath/random_path (0.00s)2057 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2058 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2059 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2060 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2061 --- PASS: TestIsValidCachePath/index.html (0.00s)2062 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2063 --- PASS: TestIsValidCachePath/realisation (0.00s)2064 --- PASS: TestIsValidCachePath/log (0.00s)2065 --- PASS: TestIsValidCachePath/ls (0.00s)2066 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2067 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2068 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2069 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2070 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2071=== CONT TestPush_RejectsBadRequests/bad_root20722026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes2073=== CONT TestPush_RejectsBadRequests/no_objects20742026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes2075=== CONT TestPush_RejectsBadRequests/root_not_in_objects20762026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes2077=== CONT TestParseSingleRange/none2078--- PASS: TestPush_RejectsBadRequests (0.59s)2079 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2080 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2081 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2082 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2083=== CONT TestParseSingleRange/open-ended2084=== CONT TestParseSingleRange/start_far_past_EOF2085=== CONT TestParseSingleRange/start_past_EOF2086=== CONT TestParseSingleRange/single_byte2087=== CONT TestParseSingleRange/suffix_exceeds_size2088=== CONT TestParseSingleRange/suffix2089=== CONT TestParseSingleRange/end_clamped_to_size2090=== CONT TestParseSingleRange/malformed_both_empty2091=== CONT TestParseSingleRange/closed2092=== CONT TestParseSingleRange/malformed_end_before_start2093=== CONT TestParseSingleRange/multi-range_ignored2094=== CONT TestParseSingleRange/malformed_no_dash2095=== CONT TestParseSingleRange/unknown_unit2096--- PASS: TestParseSingleRange (0.00s)2097 --- PASS: TestParseSingleRange/none (0.00s)2098 --- PASS: TestParseSingleRange/open-ended (0.00s)2099 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2100 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2101 --- PASS: TestParseSingleRange/single_byte (0.00s)2102 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2103 --- PASS: TestParseSingleRange/suffix (0.00s)2104 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2105 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2106 --- PASS: TestParseSingleRange/closed (0.00s)2107 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2108 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2109 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2110 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2111=== CONT TestServerTLSConfig/no_client_CA2112=== CONT TestServerTLSConfig/not_a_PEM_file2113=== CONT TestServerTLSConfig/missing_CA_file2114--- PASS: TestServerTLSConfig (0.00s)2115 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2116 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2117 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2118=== CONT TestResolveDBConnectionString/flag_wins2119=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2120=== CONT TestResolveDBConnectionString/nothing_configured2121=== CONT TestResolveDBConnectionString/missing_file_is_an_error2122=== CONT TestResolveDBConnectionString/file_when_flag_empty2123=== CONT TestClientErrorHandling/InvalidStorePath2124--- PASS: TestResolveDBConnectionString (0.00s)2125 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2126 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2127 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2128 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2129 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2130=== NAME TestClientCADerivations2131 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3074083019/001/store/aqlm43x2dbjmg6wmq62v94536gs3vznf-ca-test21322026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes21332026/09/29 08:18:15 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21342026/09/29 08:18:15 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign21352026/09/29 08:18:15 WARN Failed to register uploaded object key=xny1x4npfx635swd0znzqbws8qvgp3jz.ls error="server returned 404: 404 page not found\n"21362026/09/29 08:18:15 INFO Signed narinfos id=2 count=121372026/09/29 08:18:15 INFO Uploading 1 narinfos21382026/09/29 08:18:15 INFO Received complete push request method=POST path=/api/pushes/2/complete21392026/09/29 08:18:15 WARN Failed to register uploaded object key=xny1x4npfx635swd0znzqbws8qvgp3jz.narinfo error="server returned 404: 404 page not found\n"21402026/09/29 08:18:15 INFO Upload complete. (55ms)2141=== NAME TestNARDeduplicationMetadataUploadBug2142 metadata_upload_test.go:76: Retrieved narinfo from S3:2143 StorePath: /build/TestNARDeduplicationMetadataUploadBug806446268/001/store/xny1x4npfx635swd0znzqbws8qvgp3jz-file2.txt2144 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2145 Compression: zstd2146 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2147 NarSize: 1602148 References: 2149 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2150=== CONT TestClientErrorHandling/ServerNotAvailable2151=== NAME TestNARDeduplicationMetadataUploadBug2152 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2153 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2154 {"version":1,"root":{"type":"regular","size":44}}2155=== NAME TestPinProtectsFromGC2156 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC1263123216/001/store/w25k3rwgbg0kanw461f5ap41wbavfnw5-pinned-file.txt2157 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC1263123216/001/store/70algksb93grkvb51f4vw5azla0hi1ws-unpinned-file.txt2158--- PASS: TestNARDeduplicationMetadataUploadBug (0.85s)2159=== CONT TestClientErrorHandling/InvalidAuthToken2160=== NAME TestClientCADerivations2161 client_ca_test.go:139: Found 1 dependencies (including self)21622026/09/29 08:18:15 INFO lead: acquired remote=192.0.2.1:12342163--- PASS: TestService_healthCheckHandler (0.57s)2164=== CONT TestCacheConfigHandler/full_config,_no_issuer2165=== CONT TestCacheConfigHandler/no_signing_keys2166=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2167=== CONT TestCacheConfigHandler/no_cache_url_configured2168--- PASS: TestCacheConfigHandler (0.00s)2169 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2170 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2171 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2172 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)21732026/09/29 08:18:15 INFO lead: released remote=192.0.2.1:12342174--- PASS: TestLeadElectsOneAndHandsOver (0.75s)21752026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures21762026/09/29 08:18:15 INFO Received uploads request method=POST path=/api/pending_closures21772026/09/29 08:18:15 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)21782026/09/29 08:18:15 INFO Uploading lxf9fqyzr8sbv58wj6fifwc4vk7yy9br-b (216B)21792026/09/29 08:18:15 INFO Uploading 7m88lg9dm9fw3kjgg33j64lkppa0cs2l-shared-dep (136B)21802026-09-29 08:18:15.962 UTC [1313] ERROR: relation "goose_db_version" does not exist at character 3621812026-09-29 08:18:15.962 UTC [1313] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21822026/09/29 08:18:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21832026/09/29 08:18:15 WARN Failed to register uploaded object key=jkg235vhyszlwybr7p2936a6zmqvv26m.ls error="server returned 404: 404 page not found\n"21842026/09/29 08:18:15 WARN Failed to register uploaded object key=7m88lg9dm9fw3kjgg33j64lkppa0cs2l.ls error="server returned 404: 404 page not found\n"21852026/09/29 08:18:15 WARN Failed to register uploaded object key=nar/0p2m6v7qar765gcg6ddfd6av3s66blqr19kk6ivj1jdlvpbj0yc0.nar.zst error="server returned 404: 404 page not found\n"21862026/09/29 08:18:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21872026/09/29 08:18:15 WARN Failed to register uploaded object key=lxf9fqyzr8sbv58wj6fifwc4vk7yy9br.ls error="server returned 404: 404 page not found\n"21882026/09/29 08:18:15 INFO Signed narinfos id=1 count=221892026/09/29 08:18:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign21902026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes21912026/09/29 08:18:15 INFO Signed narinfos id=2 count=221922026/09/29 08:18:15 INFO Uploading 4 narinfos21932026/09/29 08:18:15 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/present21942026/09/29 08:18:15 WARN Failed to register uploaded object key=jkg235vhyszlwybr7p2936a6zmqvv26m.narinfo error="server returned 404: 404 page not found\n"2195=== NAME TestClientWithDependencies21962026/09/29 08:18:15 WARN Failed to register uploaded object key=lxf9fqyzr8sbv58wj6fifwc4vk7yy9br.narinfo error="server returned 404: 404 page not found\n"2197 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2306696044/001/store/mirxrsi92vw6x2qckcziyy5w3qxjlb3a-test-script21982026/09/29 08:18:15 WARN Failed to register uploaded object key=7m88lg9dm9fw3kjgg33j64lkppa0cs2l.narinfo error="server returned 404: 404 page not found\n"21992026/09/29 08:18:15 OK 20241026095416_initial_model.sql (8.73ms)22002026/09/29 08:18:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22012026/09/29 08:18:15 INFO Uploading w25k3rwgbg0kanw461f5ap41wbavfnw5-pinned-file.txt (128B)22022026/09/29 08:18:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22032026/09/29 08:18:15 WARN Failed to register uploaded object key=7m88lg9dm9fw3kjgg33j64lkppa0cs2l.narinfo error="server returned 404: 404 page not found\n"2204=== NAME TestClientMultipleUploads22052026/09/29 08:18:15 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)2206 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3007834342/001/store/rykv7yf4p6dwyvpnmyafswi82ca0pbzp-test-file-0.txt22072026/09/29 08:18:15 OK 20251218171726_add_pins.sql (2.88ms)22082026/09/29 08:18:15 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"22092026/09/29 08:18:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22102026/09/29 08:18:15 WARN Failed to register uploaded object key=w25k3rwgbg0kanw461f5ap41wbavfnw5.ls error="server returned 404: 404 page not found\n"22112026/09/29 08:18:15 INFO Signed narinfos id=1 count=122122026/09/29 08:18:15 INFO Uploading 1 narinfos2213--- PASS: TestCacheStatsHandler (0.45s)22142026/09/29 08:18:15 OK 20260628120000_add_object_size_and_stats.sql (2.91ms)22152026/09/29 08:18:15 INFO Completed upload id=122162026/09/29 08:18:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22172026/09/29 08:18:15 OK 20260905000000_add_claims.sql (2.4ms)22182026/09/29 08:18:15 INFO Completed upload id=222192026/09/29 08:18:15 INFO Upload complete. (79ms)22202026/09/29 08:18:15 INFO Received complete push request method=POST path=/api/pushes/1/complete22212026/09/29 08:18:15 WARN Failed to register uploaded object key=w25k3rwgbg0kanw461f5ap41wbavfnw5.narinfo error="server returned 404: 404 page not found\n"22222026/09/29 08:18:15 OK 20260920000000_drop_claims.sql (1.48ms)2223=== NAME TestClientFallsBackToClosures2224 client_pushes_test.go:112: Retrieved narinfo from S3:2225 StorePath: /build/TestClientFallsBackToClosures3919592196/001/store/7m88lg9dm9fw3kjgg33j64lkppa0cs2l-shared-dep2226 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2227 Compression: zstd2228 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822229 NarSize: 1362230 References: 2231 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n22322026/09/29 08:18:15 OK 20260923120000_add_pushes.sql (1.02ms)22332026/09/29 08:18:15 goose: successfully migrated database to version: 202609231200002234 client_pushes_test.go:112: Retrieved narinfo from S3:2235 StorePath: /build/TestClientFallsBackToClosures3919592196/001/store/jkg235vhyszlwybr7p2936a6zmqvv26m-a22362026/09/29 08:18:15 OK 1_commit_pending_closure.sql (1.63ms)2237 URL: nar/0p2m6v7qar765gcg6ddfd6av3s66blqr19kk6ivj1jdlvpbj0yc0.nar.zst2238 Compression: zstd2239 NarHash: sha256:0p2m6v7qar765gcg6ddfd6av3s66blqr19kk6ivj1jdlvpbj0yc02240 NarSize: 2162241 References: /build/TestClientFallsBackToClosures3919592196/001/store/7m88lg9dm9fw3kjgg33j64lkppa0cs2l-shared-dep2242 CA: text:sha256:07y1i7n0c6cbb91b928w6wvjqbv0jpky4gk9nh5kgh4xwwxn27q322432026/09/29 08:18:15 OK 2_object_stats_trigger.sql (678.82µs)22442026/09/29 08:18:15 OK 3_commit_push.sql (708.01µs)22452026/09/29 08:18:15 goose: up to current file version: 32246 client_pushes_test.go:112: Retrieved narinfo from S3:2247 StorePath: /build/TestClientFallsBackToClosures3919592196/001/store/lxf9fqyzr8sbv58wj6fifwc4vk7yy9br-b2248 URL: nar/0p2m6v7qar765gcg6ddfd6av3s66blqr19kk6ivj1jdlvpbj0yc0.nar.zst2249 Compression: zstd22502026-09-29 08:18:15.992 UTC [1404] ERROR: relation "goose_db_version" does not exist at character 3622512026-09-29 08:18:15.992 UTC [1404] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2252 NarHash: sha256:0p2m6v7qar765gcg6ddfd6av3s66blqr19kk6ivj1jdlvpbj0yc02253 NarSize: 2162254 References: /build/TestClientFallsBackToClosures3919592196/001/store/7m88lg9dm9fw3kjgg33j64lkppa0cs2l-shared-dep2255 CA: text:sha256:07y1i7n0c6cbb91b928w6wvjqbv0jpky4gk9nh5kgh4xwwxn27q322562026/09/29 08:18:15 INFO Upload complete. (60ms)2257=== NAME TestClientIntegration2258 client_integration_test.go:286: Created store path: /build/TestClientIntegration3506076856/002/store/rcn4i9sh0cfjw9a3z0vxj3rzx0kb1lsz-test-file.txt2259--- PASS: TestService_ReadScope_PublicByDefault (0.43s)22602026/09/29 08:18:15 INFO Received push request method=POST path=/api/pushes2261--- PASS: TestClientFallsBackToClosures (0.80s)22622026/09/29 08:18:16 INFO Received push request method=POST path=/api/pushes22632026/09/29 08:18:16 OK 20241026095416_initial_model.sql (7.65ms)22642026/09/29 08:18:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22652026/09/29 08:18:16 INFO Uploading rv5hisn5i0y8q82i48f0ikhhzsgphbzv-b (216B)22662026/09/29 08:18:16 INFO Uploading 43f7dkqdsv98zz186z709fdba7f4kyp3-shared-dep (136B)22672026/09/29 08:18:16 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)22682026/09/29 08:18:16 INFO Uploading iy9b2qkgqxjcx2c173klzwsqapyljvnw-top (224B)22692026/09/29 08:18:16 INFO Uploading 0v088zsy94ya09hf14r4vgz3sy8ymj45-shared-dep (136B)22702026/09/29 08:18:16 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)2271=== NAME TestClientWithDependencies2272 client_integration_test.go:615: Found 1 dependencies (including self)22732026/09/29 08:18:16 WARN Failed to register uploaded object key=7h7nkqa7ii2amvfixyzs08s6g4943ckg.ls error="server returned 404: 404 page not found\n"22742026/09/29 08:18:16 OK 20251218171726_add_pins.sql (2.35ms)22752026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22762026/09/29 08:18:16 OK 20260628120000_add_object_size_and_stats.sql (2.37ms)22772026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22782026/09/29 08:18:16 WARN Failed to register uploaded object key=43f7dkqdsv98zz186z709fdba7f4kyp3.ls error="server returned 404: 404 page not found\n"2279=== NAME TestClientMultipleUploads2280 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3007834342/001/store/wn44dfzzf1krfgjb3msvn53c1lnvnc5m-test-file-1.txt22812026/09/29 08:18:16 WARN Failed to register uploaded object key=0v088zsy94ya09hf14r4vgz3sy8ymj45.ls error="server returned 404: 404 page not found\n"22822026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/1cidz2srqrd9xhg0sbaxrfnk0dnx8nri69l616hmvmnpxd2b05gi.nar.zst error="server returned 404: 404 page not found\n"22832026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/0pl7wb745mqa6lixbxm216h9dgly82ia8xix4i3rnd59b8rk4nha.nar.zst error="server returned 404: 404 page not found\n"22842026/09/29 08:18:16 OK 20260905000000_add_claims.sql (2.07ms)22852026/09/29 08:18:16 WARN Failed to register uploaded object key=rv5hisn5i0y8q82i48f0ikhhzsgphbzv.ls error="server returned 404: 404 page not found\n"22862026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22872026/09/29 08:18:16 WARN Failed to register uploaded object key=iy9b2qkgqxjcx2c173klzwsqapyljvnw.ls error="server returned 404: 404 page not found\n"22882026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22892026/09/29 08:18:16 INFO Received push request method=POST path=/api/pushes22902026/09/29 08:18:16 INFO Signed narinfos id=1 count=322912026/09/29 08:18:16 INFO Signed narinfos id=1 count=222922026/09/29 08:18:16 INFO Uploading 3 narinfos22932026/09/29 08:18:16 INFO Uploading 2 narinfos22942026/09/29 08:18:16 OK 20260920000000_drop_claims.sql (1.54ms)2295--- PASS: TestService_ReadAuthMiddleware (0.43s)22962026/09/29 08:18:16 OK 20260923120000_add_pushes.sql (1.16ms)22972026/09/29 08:18:16 goose: successfully migrated database to version: 2026092312000022982026/09/29 08:18:16 WARN Failed to register uploaded object key=iy9b2qkgqxjcx2c173klzwsqapyljvnw.narinfo error="server returned 404: 404 page not found\n"22992026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete23002026/09/29 08:18:16 WARN Failed to register uploaded object key=0v088zsy94ya09hf14r4vgz3sy8ymj45.narinfo error="server returned 404: 404 page not found\n"23012026/09/29 08:18:16 OK 1_commit_pending_closure.sql (2.31ms)23022026/09/29 08:18:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23032026/09/29 08:18:16 WARN Failed to register uploaded object key=rv5hisn5i0y8q82i48f0ikhhzsgphbzv.narinfo error="server returned 404: 404 page not found\n"23042026/09/29 08:18:16 INFO Uploading aqlm43x2dbjmg6wmq62v94536gs3vznf-ca-test (144B)23052026/09/29 08:18:16 OK 2_object_stats_trigger.sql (1.05ms)23062026/09/29 08:18:16 WARN Failed to register uploaded object key=43f7dkqdsv98zz186z709fdba7f4kyp3.narinfo error="server returned 404: 404 page not found\n"23072026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete23082026/09/29 08:18:16 WARN Failed to register uploaded object key=7h7nkqa7ii2amvfixyzs08s6g4943ckg.narinfo error="server returned 404: 404 page not found\n"23092026/09/29 08:18:16 OK 3_commit_push.sql (688.63µs)23102026/09/29 08:18:16 goose: up to current file version: 323112026/09/29 08:18:16 WARN Failed to register uploaded object key=log/pj4q39kw28pzjy1gzbcp12chych2ig06-ca-test.drv error="server returned 404: 404 page not found\n"23122026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"23132026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23142026/09/29 08:18:16 WARN Failed to register uploaded object key=aqlm43x2dbjmg6wmq62v94536gs3vznf.ls error="server returned 404: 404 page not found\n"23152026/09/29 08:18:16 INFO Signed narinfos id=1 count=123162026/09/29 08:18:16 INFO Uploading 1 narinfos23172026/09/29 08:18:16 INFO Upload complete. (67ms)23182026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete23192026/09/29 08:18:16 WARN Failed to register uploaded object key=aqlm43x2dbjmg6wmq62v94536gs3vznf.narinfo error="server returned 404: 404 page not found\n"23202026/09/29 08:18:16 INFO Upload complete. (72ms)2321=== NAME TestClientSharedPathCommittedMidPush2322 client_integration_test.go:680: Retrieved narinfo from S3:2323 StorePath: /build/TestClientSharedPathCommittedMidPush96140132/001/store/0v088zsy94ya09hf14r4vgz3sy8ymj45-shared-dep2324 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2325 Compression: zstd2326 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822327 NarSize: 1362328 References: 2329 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2330=== NAME TestClientPushesUseOnePush2331 client_pushes_test.go:97: Retrieved narinfo from S3:2332 StorePath: /build/TestClientPushesUseOnePush1331544183/001/store/43f7dkqdsv98zz186z709fdba7f4kyp3-shared-dep2333 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2334 Compression: zstd2335 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822336 NarSize: 1362337 References: 2338 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2339=== NAME TestClientSharedPathCommittedMidPush2340 client_integration_test.go:680: Retrieved narinfo from S3:2341 StorePath: /build/TestClientSharedPathCommittedMidPush96140132/001/store/iy9b2qkgqxjcx2c173klzwsqapyljvnw-top2342 URL: nar/1cidz2srqrd9xhg0sbaxrfnk0dnx8nri69l616hmvmnpxd2b05gi.nar.zst2343 Compression: zstd2344 NarHash: sha256:1cidz2srqrd9xhg0sbaxrfnk0dnx8nri69l616hmvmnpxd2b05gi2345 NarSize: 2242346 References: /build/TestClientSharedPathCommittedMidPush96140132/001/store/0v088zsy94ya09hf14r4vgz3sy8ymj45-shared-dep2347 CA: text:sha256:14sk0agyixmyl8hmiik0rl50qs22hqvpv8j9ih34m9hv619azx6s2348=== NAME TestClientPushesUseOnePush2349 client_pushes_test.go:97: Retrieved narinfo from S3:2350 StorePath: /build/TestClientPushesUseOnePush1331544183/001/store/7h7nkqa7ii2amvfixyzs08s6g4943ckg-a2351 URL: nar/0pl7wb745mqa6lixbxm216h9dgly82ia8xix4i3rnd59b8rk4nha.nar.zst2352 Compression: zstd2353 NarHash: sha256:0pl7wb745mqa6lixbxm216h9dgly82ia8xix4i3rnd59b8rk4nha2354 NarSize: 2162355 References: /build/TestClientPushesUseOnePush1331544183/001/store/43f7dkqdsv98zz186z709fdba7f4kyp3-shared-dep2356 CA: text:sha256:1z0kjg6kv58kxls0ga32yblclz90sflb4ln9vqg4jf1blxh2iplw2357 client_pushes_test.go:97: Retrieved narinfo from S3:2358 StorePath: /build/TestClientPushesUseOnePush1331544183/001/store/rv5hisn5i0y8q82i48f0ikhhzsgphbzv-b2359 URL: nar/0pl7wb745mqa6lixbxm216h9dgly82ia8xix4i3rnd59b8rk4nha.nar.zst2360 Compression: zstd2361 NarHash: sha256:0pl7wb745mqa6lixbxm216h9dgly82ia8xix4i3rnd59b8rk4nha2362 NarSize: 2162363 References: /build/TestClientPushesUseOnePush1331544183/001/store/43f7dkqdsv98zz186z709fdba7f4kyp3-shared-dep2364 CA: text:sha256:1z0kjg6kv58kxls0ga32yblclz90sflb4ln9vqg4jf1blxh2iplw23652026/09/29 08:18:16 INFO Upload complete. (96ms)23662026/09/29 08:18:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"23672026/09/29 08:18:16 WARN mTLS auth: bound subjects configured but subject DN unavailable23682026/09/29 08:18:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2369--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.41s)2370=== NAME TestClientCADerivations2371 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3074083019/001/store/aqlm43x2dbjmg6wmq62v94536gs3vznf-ca-test2372 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2373 Compression: zstd2374 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2375 NarSize: 1442376 References: 2377 Deriver: /build/TestClientCADerivations3074083019/001/store/pj4q39kw28pzjy1gzbcp12chych2ig06-ca-test.drv2378 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2379 client_ca_test.go:185: Checking for realisation files in S3...2380--- PASS: TestClientSharedPathCommittedMidPush (0.78s)2381--- PASS: TestClientPushesUseOnePush (0.84s)2382=== NAME TestClientCADerivations2383 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2384 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2385=== NAME TestClientMultipleUploads2386 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3007834342/001/store/pyggbdhqdpy6461m7h72x5nxgazarsn0-test-file-2.txt23872026/09/29 08:18:16 INFO Received push request method=POST path=/api/pushes23882026/09/29 08:18:16 INFO Received push request method=POST path=/api/pushes23892026/09/29 08:18:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23902026/09/29 08:18:16 INFO Uploading 70algksb93grkvb51f4vw5azla0hi1ws-unpinned-file.txt (128B)23912026/09/29 08:18:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23922026/09/29 08:18:16 INFO Uploading rcn4i9sh0cfjw9a3z0vxj3rzx0kb1lsz-test-file.txt (152B)23932026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign23942026/09/29 08:18:16 WARN Failed to register uploaded object key=70algksb93grkvb51f4vw5azla0hi1ws.ls error="server returned 404: 404 page not found\n"23952026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"23962026/09/29 08:18:16 INFO Signed narinfos id=2 count=123972026/09/29 08:18:16 INFO Uploading 1 narinfos23982026/09/29 08:18:16 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.300517ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2399--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.42s)2400=== RUN TestService_RequireScope_OIDC/builder_may_write2401=== PAUSE TestService_RequireScope_OIDC/builder_may_write2402=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2403=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2404=== RUN TestService_RequireScope_OIDC/ops_may_admin2405=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2406=== RUN TestService_RequireScope_OIDC/ops_may_not_write2407=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2408=== RUN TestService_RequireScope_OIDC/reader_may_not_write2409=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2410=== RUN TestService_RequireScope_OIDC/static_token_may_admin2411=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2412=== RUN TestService_RequireScope_OIDC/static_token_may_write2413=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2414=== RUN TestService_RequireScope_OIDC/reader_may_read2415=== PAUSE TestService_RequireScope_OIDC/reader_may_read2416=== RUN TestService_RequireScope_OIDC/writer_implies_read2417=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2418=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2419=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2420=== CONT TestService_RequireScope_OIDC/builder_may_write2421=== CONT TestService_RequireScope_OIDC/static_token_may_admin2422=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2423=== CONT TestService_RequireScope_OIDC/writer_implies_read2424=== CONT TestService_RequireScope_OIDC/reader_may_read24252026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"2426=== CONT TestService_RequireScope_OIDC/static_token_may_write2427=== CONT TestService_RequireScope_OIDC/reader_may_not_write2428=== CONT TestService_RequireScope_OIDC/ops_may_not_write24292026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2430=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2431=== CONT TestService_RequireScope_OIDC/ops_may_admin24322026/09/29 08:18:16 WARN Failed to register uploaded object key=rcn4i9sh0cfjw9a3z0vxj3rzx0kb1lsz.ls error="server returned 404: 404 page not found\n"24332026/09/29 08:18:16 INFO Signed narinfos id=1 count=124342026/09/29 08:18:16 INFO Uploading 1 narinfos24352026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/2/complete24362026/09/29 08:18:16 WARN Failed to register uploaded object key=70algksb93grkvb51f4vw5azla0hi1ws.narinfo error="server returned 404: 404 page not found\n"2437--- PASS: TestService_RequireScope_OIDC (0.58s)2438 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2439 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2440 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2441 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2442 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2443 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2444 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2445 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2446 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2447 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)24482026/09/29 08:18:16 INFO Received push request method=POST path=/api/pushes24492026/09/29 08:18:16 INFO Upload complete. (49ms)24502026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete24512026/09/29 08:18:16 WARN Failed to register uploaded object key=rcn4i9sh0cfjw9a3z0vxj3rzx0kb1lsz.narinfo error="server returned 404: 404 page not found\n"24522026/09/29 08:18:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24532026/09/29 08:18:16 INFO Uploading mirxrsi92vw6x2qckcziyy5w3qxjlb3a-test-script (136B)24542026/09/29 08:18:16 WARN Failed to register uploaded object key=log/fay03f22vsr3gy2awg8lm8kpnsgg97ka-test-script.drv error="server returned 404: 404 page not found\n"24552026/09/29 08:18:16 INFO Upload complete. (53ms)24562026/09/29 08:18:16 WARN Failed to register uploaded object key=mirxrsi92vw6x2qckcziyy5w3qxjlb3a.ls error="server returned 404: 404 page not found\n"24572026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24582026/09/29 08:18:16 INFO Signed narinfos id=1 count=124592026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"24602026/09/29 08:18:16 INFO Uploading 1 narinfos24612026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete24622026/09/29 08:18:16 WARN Failed to register uploaded object key=mirxrsi92vw6x2qckcziyy5w3qxjlb3a.narinfo error="server returned 404: 404 page not found\n"2463=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2464=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2465=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2466=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2467=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2468=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2469=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2470=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2471=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2472=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2473=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2474=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected24752026/09/29 08:18:16 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]24762026/09/29 08:18:16 INFO Upload complete. (54ms)2477=== NAME TestClientWithDependencies2478 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2306696044/001/store) requires matching store prefix24792026/09/29 08:18:16 WARN Authentication failed token_preview=eyJhbGciOi...5WGRdO2PGA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2480--- PASS: TestService_AuthMiddleware_OIDC (0.47s)2481 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2482 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2483 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2484 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2485--- PASS: TestClientWithDependencies (0.78s)24862026/09/29 08:18:16 INFO Received create pin request method=POST path=/api/pins/myapp24872026/09/29 08:18:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24882026/09/29 08:18:16 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1263123216/001/store/w25k3rwgbg0kanw461f5ap41wbavfnw5-pinned-file.txt narinfo_key=w25k3rwgbg0kanw461f5ap41wbavfnw5.narinfo24892026/09/29 08:18:16 INFO Received push request method=POST path=/api/pushes24902026/09/29 08:18:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures24912026/09/29 08:18:16 INFO Garbage collection started24922026/09/29 08:18:16 INFO All 1 paths already cached2493=== NAME TestClientIntegration2494 client_integration_test.go:312: Retrieved narinfo from S3:2495 StorePath: /build/TestClientIntegration3506076856/002/store/rcn4i9sh0cfjw9a3z0vxj3rzx0kb1lsz-test-file.txt2496 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2497 Compression: zstd2498 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12499 NarSize: 1522500 References: 2501 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk125022026/09/29 08:18:16 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)25032026/09/29 08:18:16 INFO Uploading wn44dfzzf1krfgjb3msvn53c1lnvnc5m-test-file-1.txt (160B)25042026/09/29 08:18:16 INFO Uploading pyggbdhqdpy6461m7h72x5nxgazarsn0-test-file-2.txt (160B)25052026/09/29 08:18:16 INFO Uploading rykv7yf4p6dwyvpnmyafswi82ca0pbzp-test-file-0.txt (160B)2506 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2507 client_integration_test.go:313: Decompressed .ls content (64 bytes):2508 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2509 client_integration_test.go:316: Testing garbage collection...25102026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"25112026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"25122026/09/29 08:18:16 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OWJlOWQ1ZTgtZTRkMi00OGEyLWFmM2QtNjViZDVjYjk0ZWYwLjEzNjA3NmRkLTExMTYtNDRhMi05MzYzLTdlM2RjMTY2NjM1ZHgxNzkwNjY5ODk1Njg2MDIyNzA4 parts=1225132026/09/29 08:18:16 WARN Failed to register uploaded object key=wn44dfzzf1krfgjb3msvn53c1lnvnc5m.ls error="server returned 404: 404 page not found\n"25142026/09/29 08:18:16 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"25152026/09/29 08:18:16 INFO Received uploads request method=POST path=/api/pending_closures25162026/09/29 08:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25172026/09/29 08:18:16 WARN Failed to register uploaded object key=pyggbdhqdpy6461m7h72x5nxgazarsn0.ls error="server returned 404: 404 page not found\n"25182026/09/29 08:18:16 WARN Failed to register uploaded object key=rykv7yf4p6dwyvpnmyafswi82ca0pbzp.ls error="server returned 404: 404 page not found\n"25192026/09/29 08:18:16 INFO Aborted multipart uploads count=025202026/09/29 08:18:16 INFO Signed narinfos id=1 count=325212026/09/29 08:18:16 INFO Uploading 3 narinfos2522--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.96s)25232026/09/29 08:18:16 WARN Force mode enabled - objects will be deleted immediately without grace period25242026/09/29 08:18:16 WARN Failed to register uploaded object key=wn44dfzzf1krfgjb3msvn53c1lnvnc5m.narinfo error="server returned 404: 404 page not found\n"25252026/09/29 08:18:16 WARN Failed to register uploaded object key=pyggbdhqdpy6461m7h72x5nxgazarsn0.narinfo error="server returned 404: 404 page not found\n"25262026/09/29 08:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete25272026/09/29 08:18:16 WARN Failed to register uploaded object key=rykv7yf4p6dwyvpnmyafswi82ca0pbzp.narinfo error="server returned 404: 404 page not found\n"25282026/09/29 08:18:16 INFO Upload complete. (58ms)2529=== NAME TestClientMultipleUploads2530 client_integration_test.go:369: Uploaded 3 paths in 92.120325ms2531--- PASS: TestClientMultipleUploads (0.74s)25322026/09/29 08:18:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures25332026/09/29 08:18:16 INFO Garbage collection started2534=== NAME TestClientCADerivations2535 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2536 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2537 error: binary cache 's3://bucket48?endpoint=http://localhost:36515®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3074083019/001/store'2538 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12539--- PASS: TestClientCADerivations (0.99s)25402026/09/29 08:18:16 INFO Aborted multipart uploads count=025412026/09/29 08:18:16 WARN Force mode enabled - objects will be deleted immediately without grace period25422026/09/29 08:18:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"25432026/09/29 08:18:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"25442026/09/29 08:18:16 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=414.63637ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2545--- PASS: TestUploadHandlersRejectOversizedBody (0.20s)2546 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2547 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2548 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.68s)25492026/09/29 08:18:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=757.777454ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2550=== NAME TestOrphanedObjectsGCStressTest2551 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2552 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion25532026/09/29 08:18:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=025542026/09/29 08:18:17 INFO Vacuumed table table=pending_closures25552026/09/29 08:18:17 INFO Vacuumed table table=pending_objects25562026/09/29 08:18:17 INFO Vacuumed table table=multipart_uploads25572026/09/29 08:18:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=025582026/09/29 08:18:17 INFO Vacuumed table table=closures25592026/09/29 08:18:17 INFO Vacuumed table table=objects25602026/09/29 08:18:17 INFO Vacuumed table table=pending_closures25612026/09/29 08:18:17 INFO Vacuumed table table=pending_objects25622026/09/29 08:18:17 INFO Vacuumed table table=multipart_uploads25632026/09/29 08:18:17 INFO Vacuumed table table=closures25642026/09/29 08:18:17 INFO Vacuumed table table=objects2565 orphaned_objects_gc_test.go:509: Stress test completed successfully:2566 orphaned_objects_gc_test.go:510: - Active objects preserved: 202567 orphaned_objects_gc_test.go:511: - Objects deleted: 2102568 orphaned_objects_gc_test.go:512: - Total GC'd: 2102569--- PASS: TestOrphanedObjectsGCStressTest (2.50s)25702026/09/29 08:18:17 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.522075177s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25712026/09/29 08:18:18 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02572=== NAME TestPinProtectsFromGC2573 client_integration_test.go:794: Pin successfully protected closure from garbage collection2574--- PASS: TestPinProtectsFromGC (2.91s)25752026/09/29 08:18:18 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02576=== NAME TestClientIntegration2577 client_integration_test.go:323: Objects in database after GC:2578 client_integration_test.go:323: Successfully deleted all objects with GC --force2579--- PASS: TestClientIntegration (2.67s)25802026/09/29 08:18:19 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-config25812026/09/29 08:18:19 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.265575ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25822026/09/29 08:18:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=368.97205ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25832026/09/29 08:18:19 WARN Rate limiter enabled after throttle name=s3-test rate=525842026/09/29 08:18:19 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2585=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2586 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102587 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002588--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.26s)25892026/09/29 08:18:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=872.453538ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25902026/09/29 08:18:20 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.708779514s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25912026/09/29 08:18:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"25922026/09/29 08:18:22 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-config25932026/09/29 08:18:22 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.553796ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25942026/09/29 08:18:22 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=373.951392ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25952026/09/29 08:18:22 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=857.468146ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25962026/09/29 08:18:23 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.48269056s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25972026/09/29 08:18:25 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_closures25982026/09/29 08:18:25 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.69105ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures25992026/09/29 08:18:25 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=415.434456ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures26002026/09/29 08:18:25 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=741.241548ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures26012026/09/29 08:18:26 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.58297537s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2602--- PASS: TestClientErrorHandling (0.00s)2603 --- PASS: TestClientErrorHandling/InvalidStorePath (0.27s)2604 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)2605 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.43s)2606PASS2607{"timestamp":"2026-09-29T08:18:28.330737368Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:37676","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(388)"}26082026-09-29 08:18:28.667 UTC [128] LOG: received smart shutdown request26092026-09-29 08:18:28.675 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 126102026-09-29 08:18:28.682 UTC [133] LOG: shutting down26112026-09-29 08:18:28.683 UTC [133] LOG: checkpoint starting: shutdown immediate26122026-09-29 08:18:30.593 UTC [133] LOG: checkpoint complete: wrote 11034 buffers (67.3%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 18 recycled; write=0.280 s, sync=1.577 s, total=1.911 s; sync files=21875, longest=0.003 s, average=0.001 s; distance=297529 kB, estimate=297529 kB; lsn=0/139F4368, redo lsn=0/139F436826132026-09-29 08:18:30.670 UTC [128] LOG: database system is shut down2614Running OIDC tests...2615=== RUN TestAudienceForIssuer2616=== PAUSE TestAudienceForIssuer2617=== RUN TestGlobMatch2618=== PAUSE TestGlobMatch2619=== RUN TestValidateToken_ValidToken2620=== PAUSE TestValidateToken_ValidToken2621=== RUN TestValidateToken_WrongAudience2622=== PAUSE TestValidateToken_WrongAudience2623=== RUN TestValidateToken_Expired2624=== PAUSE TestValidateToken_Expired2625=== RUN TestValidateToken_BoundClaimsMismatch2626=== PAUSE TestValidateToken_BoundClaimsMismatch2627=== RUN TestValidateToken_BoundSubjectMismatch2628=== PAUSE TestValidateToken_BoundSubjectMismatch2629=== RUN TestValidateToken_MultipleProviders2630=== PAUSE TestValidateToken_MultipleProviders2631=== RUN TestValidateToken_NoMatchingProvider2632=== PAUSE TestValidateToken_NoMatchingProvider2633=== RUN TestValidateToken_KubernetesServiceAccount2634=== PAUSE TestValidateToken_KubernetesServiceAccount2635=== RUN TestNewValidator_KubernetesRequiresCA2636=== PAUSE TestNewValidator_KubernetesRequiresCA2637=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2638=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2639=== RUN TestPins_ReservedForMatchingRule2640=== PAUSE TestPins_ReservedForMatchingRule2641=== RUN TestPins_TopLevelShorthand2642=== PAUSE TestPins_TopLevelShorthand2643=== RUN TestPins_ConfigValidation2644=== PAUSE TestPins_ConfigValidation2645=== RUN TestScopes_LegacyProviderDefaultsToWrite2646=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2647=== RUN TestScopes_Rules2648=== PAUSE TestScopes_Rules2649=== RUN TestScopes_ConfigValidation2650=== PAUSE TestScopes_ConfigValidation2651=== CONT TestAudienceForIssuer2652=== CONT TestValidateToken_BoundClaimsMismatch2653=== CONT TestPins_ConfigValidation2654--- PASS: TestAudienceForIssuer (0.00s)2655=== CONT TestValidateToken_Expired2656=== CONT TestValidateToken_WrongAudience2657=== CONT TestValidateToken_ValidToken2658=== CONT TestGlobMatch2659=== CONT TestValidateToken_MultipleProviders2660=== CONT TestValidateToken_NoMatchingProvider2661=== CONT TestValidateToken_BoundSubjectMismatch2662=== CONT TestPins_ReservedForMatchingRule2663=== CONT TestPins_TopLevelShorthand2664=== CONT TestScopes_Rules2665=== CONT TestScopes_ConfigValidation2666=== CONT TestScopes_LegacyProviderDefaultsToWrite2667=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2668=== CONT TestNewValidator_KubernetesRequiresCA2669=== CONT TestValidateToken_KubernetesServiceAccount2670--- PASS: TestPins_ConfigValidation (0.00s)2671=== RUN TestGlobMatch/foo_foo2672=== PAUSE TestGlobMatch/foo_foo2673=== RUN TestGlobMatch/foo_bar2674=== PAUSE TestGlobMatch/foo_bar2675=== RUN TestGlobMatch/*_2676=== PAUSE TestGlobMatch/*_2677=== RUN TestGlobMatch/*_anything2678=== PAUSE TestGlobMatch/*_anything2679--- PASS: TestScopes_ConfigValidation (0.00s)2680=== RUN TestGlobMatch/foo*_foo2681=== PAUSE TestGlobMatch/foo*_foo2682=== RUN TestGlobMatch/foo*_foobar2683=== PAUSE TestGlobMatch/foo*_foobar2684=== RUN TestGlobMatch/foo*_bar2685=== PAUSE TestGlobMatch/foo*_bar2686=== RUN TestGlobMatch/*bar_bar2687=== PAUSE TestGlobMatch/*bar_bar2688=== RUN TestGlobMatch/*bar_foobar2689=== PAUSE TestGlobMatch/*bar_foobar2690=== RUN TestGlobMatch/*bar_foo2691=== PAUSE TestGlobMatch/*bar_foo2692=== RUN TestGlobMatch/foo*bar_foobar2693=== PAUSE TestGlobMatch/foo*bar_foobar2694=== RUN TestGlobMatch/foo*bar_foo123bar2695=== PAUSE TestGlobMatch/foo*bar_foo123bar2696=== RUN TestGlobMatch/foo*bar_foobarbaz2697=== PAUSE TestGlobMatch/foo*bar_foobarbaz2698=== RUN TestGlobMatch/*/*_foo/bar2699=== PAUSE TestGlobMatch/*/*_foo/bar2700=== RUN TestGlobMatch/*/*_foo2701=== PAUSE TestGlobMatch/*/*_foo2702=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2703=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2704=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02705=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02706=== RUN TestGlobMatch/refs/*/main_refs/heads/main2707=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2708=== RUN TestGlobMatch/fo?_foo2709=== PAUSE TestGlobMatch/fo?_foo2710=== RUN TestGlobMatch/fo?_fo2711=== PAUSE TestGlobMatch/fo?_fo2712=== RUN TestGlobMatch/fo?_fooo2713=== PAUSE TestGlobMatch/fo?_fooo2714=== RUN TestGlobMatch/?oo_foo2715=== PAUSE TestGlobMatch/?oo_foo2716=== RUN TestGlobMatch/?oo_boo2717=== PAUSE TestGlobMatch/?oo_boo2718=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2719=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2720=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2721=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2722=== CONT TestGlobMatch/foo_foo2723=== CONT TestGlobMatch/*/*_foo/bar2724=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2725=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2726=== CONT TestGlobMatch/foo*_foo2727=== CONT TestGlobMatch/foo*_bar2728=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2729=== CONT TestGlobMatch/foo*bar_foobar2730=== CONT TestGlobMatch/foo*bar_foobarbaz2731=== CONT TestGlobMatch/foo*bar_foo123bar2732=== CONT TestGlobMatch/*bar_foo2733=== CONT TestGlobMatch/*_2734=== CONT TestGlobMatch/*_anything2735=== CONT TestGlobMatch/*bar_foobar2736=== CONT TestGlobMatch/?oo_boo2737=== CONT TestGlobMatch/*bar_bar2738=== CONT TestGlobMatch/?oo_foo2739=== CONT TestGlobMatch/fo?_fooo2740=== CONT TestGlobMatch/fo?_fo2741=== CONT TestGlobMatch/fo?_foo2742=== CONT TestGlobMatch/refs/*/main_refs/heads/main2743=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02744=== CONT TestGlobMatch/*/*_foo2745=== CONT TestGlobMatch/foo*_foobar2746=== CONT TestGlobMatch/foo_bar2747--- PASS: TestGlobMatch (0.00s)2748 --- PASS: TestGlobMatch/foo_foo (0.00s)2749 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2750 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2751 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2752 --- PASS: TestGlobMatch/foo*_foo (0.00s)2753 --- PASS: TestGlobMatch/foo*_bar (0.00s)2754 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2755 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2756 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2757 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2758 --- PASS: TestGlobMatch/*bar_foo (0.00s)2759 --- PASS: TestGlobMatch/*_ (0.00s)2760 --- PASS: TestGlobMatch/*_anything (0.00s)2761 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2762 --- PASS: TestGlobMatch/?oo_boo (0.00s)2763 --- PASS: TestGlobMatch/*bar_bar (0.00s)2764 --- PASS: TestGlobMatch/?oo_foo (0.00s)2765 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2766 --- PASS: TestGlobMatch/fo?_fo (0.00s)2767 --- PASS: TestGlobMatch/fo?_foo (0.00s)2768 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2769 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2770 --- PASS: TestGlobMatch/*/*_foo (0.00s)2771 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2772 --- PASS: TestGlobMatch/foo_bar (0.00s)27732026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40437/oidc2774--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.03s)27752026/09/29 08:18:32 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:3688527762026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41499/oidc2777--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)2778--- PASS: TestValidateToken_WrongAudience (0.04s)27792026/09/29 08:18:32 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12327802026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34963/oidc27812026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37581/oidc2782--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)2783--- PASS: TestPins_TopLevelShorthand (0.05s)2784--- PASS: TestScopes_Rules (0.05s)27852026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37181/oidc2786--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)27872026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44851/oidc2788--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)27892026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44145/oidc27902026/09/29 08:18:32 http: TLS handshake error from 127.0.0.1:57202: remote error: tls: bad certificate2791--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)2792--- PASS: TestPins_ReservedForMatchingRule (0.08s)27932026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35351/oidc2794--- PASS: TestValidateToken_ValidToken (0.10s)27952026/09/29 08:18:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38463/oidc2796--- PASS: TestValidateToken_Expired (0.14s)27972026/09/29 08:18:32 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:41283/oidc2798--- PASS: TestValidateToken_NoMatchingProvider (0.17s)27992026/09/29 08:18:32 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45147/oidc28002026/09/29 08:18:32 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:35233/oidc2801--- PASS: TestValidateToken_MultipleProviders (0.17s)2802PASS2803Running hook tests...2804=== RUN TestSendPathsEmpty2805=== PAUSE TestSendPathsEmpty2806=== RUN TestQueueEnqueueAndFetch2807=== PAUSE TestQueueEnqueueAndFetch2808=== RUN TestQueueDeduplication2809=== PAUSE TestQueueDeduplication2810=== RUN TestQueueRemove2811=== PAUSE TestQueueRemove2812=== RUN TestQueueFetchBatchLimit2813=== PAUSE TestQueueFetchBatchLimit2814=== RUN TestQueueRetryMovesToBack2815=== PAUSE TestQueueRetryMovesToBack2816=== RUN TestQueueFetchRemoveLifecycle2817=== PAUSE TestQueueFetchRemoveLifecycle2818=== RUN TestQueueConcurrentWriters2819=== PAUSE TestQueueConcurrentWriters2820=== RUN TestQueueRemoveLargeClosure2821=== PAUSE TestQueueRemoveLargeClosure2822=== RUN TestServerClientIntegration2823=== PAUSE TestServerClientIntegration2824=== RUN TestServerQueueError2825=== PAUSE TestServerQueueError2826=== RUN TestGetListenerSocketActivation2827 server_test.go:210: === RUN TestGetListenerSocketActivation2828 --- PASS: TestGetListenerSocketActivation (0.00s)2829 PASS2830 2831--- PASS: TestGetListenerSocketActivation (0.01s)2832=== RUN TestDrainIsolatesPoisonPath2833=== PAUSE TestDrainIsolatesPoisonPath2834=== RUN TestRunNotBlockedByPoisonHead2835=== PAUSE TestRunNotBlockedByPoisonHead2836=== RUN TestDrainGivesUpWhenServerDown2837=== PAUSE TestDrainGivesUpWhenServerDown2838=== RUN TestFailedPathPrunedByLaterClosure2839=== PAUSE TestFailedPathPrunedByLaterClosure2840=== RUN TestWorkerUploadsAndRemoves2841=== PAUSE TestWorkerUploadsAndRemoves2842=== RUN TestWorkerSkipsGCdPaths2843=== PAUSE TestWorkerSkipsGCdPaths2844=== RUN TestWorkerPrunesClosureDeps2845=== PAUSE TestWorkerPrunesClosureDeps2846=== RUN TestDrainTimeout2847=== PAUSE TestDrainTimeout2848=== CONT TestSendPathsEmpty2849=== CONT TestServerQueueError2850--- PASS: TestSendPathsEmpty (0.00s)2851=== CONT TestQueueFetchBatchLimit2852=== CONT TestQueueRemove2853=== CONT TestQueueDeduplication2854=== CONT TestQueueEnqueueAndFetch28552026/09/29 08:18:33 ERROR Failed to queue paths error="permission denied" count=12856=== CONT TestWorkerUploadsAndRemoves2857=== CONT TestDrainTimeout2858=== CONT TestWorkerPrunesClosureDeps2859=== CONT TestWorkerSkipsGCdPaths2860=== CONT TestDrainGivesUpWhenServerDown2861=== CONT TestQueueRetryMovesToBack2862=== CONT TestFailedPathPrunedByLaterClosure2863=== CONT TestServerClientIntegration2864=== CONT TestQueueRemoveLargeClosure2865=== CONT TestRunNotBlockedByPoisonHead2866=== CONT TestQueueConcurrentWriters2867=== CONT TestQueueFetchRemoveLifecycle2868=== CONT TestDrainIsolatesPoisonPath2869--- PASS: TestServerQueueError (0.00s)2870--- PASS: TestServerClientIntegration (0.00s)28712026/09/29 08:18:33 INFO Uploading batch count=128722026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=12873--- PASS: TestQueueEnqueueAndFetch (0.01s)28742026/09/29 08:18:33 INFO Upload queue status pending=228752026/09/29 08:18:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2625667771/002/nonexistent28762026/09/29 08:18:33 INFO Upload queue status pending=228772026/09/29 08:18:33 INFO Uploading batch count=228782026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=228792026/09/29 08:18:33 INFO Uploading batch count=228802026/09/29 08:18:33 INFO Upload queue status pending=228812026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3825806064/002/a28822026/09/29 08:18:33 INFO Uploading batch count=228832026/09/29 08:18:33 INFO Uploading batch count=128842026/09/29 08:18:33 INFO Uploading batch count=128852026/09/29 08:18:33 INFO Uploading batch count=128862026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3825806064/002/b28872026/09/29 08:18:33 INFO Uploading batch count=428882026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=42889--- PASS: TestQueueFetchBatchLimit (0.01s)2890--- PASS: TestQueueRemove (0.01s)28912026/09/29 08:18:33 INFO Uploading batch count=128922026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath333003468/002/bbb28932026/09/29 08:18:33 INFO Uploading batch count=228942026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=228952026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3825806064/002/c2896--- PASS: TestQueueRetryMovesToBack (0.01s)28972026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3825806064/002/d2898--- PASS: TestQueueDeduplication (0.01s)28992026/09/29 08:18:33 INFO Upload queue status pending=329002026/09/29 08:18:33 INFO Uploading batch count=129012026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=129022026/09/29 08:18:33 INFO Uploading batch count=229032026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=229042026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3825806064/002/e29052026/09/29 08:18:33 INFO Uploading batch count=129062026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=12907--- PASS: TestQueueFetchRemoveLifecycle (0.01s)29082026/09/29 08:18:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3825806064/002/f2909--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)29102026/09/29 08:18:33 INFO Uploading batch count=129112026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=129122026/09/29 08:18:33 ERROR Drain finished with paths left in queue remaining=1029132026/09/29 08:18:33 INFO Uploading batch count=129142026/09/29 08:18:33 ERROR Upload failed error="upload failed" count=129152026/09/29 08:18:33 ERROR Drain finished with paths left in queue remaining=12916--- PASS: TestDrainIsolatesPoisonPath (0.02s)2917--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2918--- PASS: TestWorkerUploadsAndRemoves (0.03s)2919--- PASS: TestWorkerSkipsGCdPaths (0.03s)2920--- PASS: TestWorkerPrunesClosureDeps (0.03s)2921--- PASS: TestQueueRemoveLargeClosure (0.06s)29222026/09/29 08:18:33 ERROR Upload failed error="context deadline exceeded" count=229232026/09/29 08:18:33 ERROR Drain finished with paths left in queue remaining=42924--- PASS: TestDrainTimeout (0.21s)2925--- PASS: TestQueueConcurrentWriters (0.29s)29262026/09/29 08:18:34 INFO Uploading batch count=129272026/09/29 08:18:34 INFO Uploading batch count=129282026/09/29 08:18:34 INFO Uploading batch count=129292026/09/29 08:18:34 ERROR Upload failed error="upload failed" count=129302026/09/29 08:18:34 INFO Uploading batch count=129312026/09/29 08:18:34 ERROR Upload failed error="upload failed" count=129322026/09/29 08:18:34 INFO Uploading batch count=129332026/09/29 08:18:34 ERROR Upload failed error="upload failed" count=129342026/09/29 08:18:34 INFO Uploading batch count=129352026/09/29 08:18:34 ERROR Upload failed error="upload failed" count=129362026/09/29 08:18:34 ERROR Drain finished with paths left in queue remaining=12937--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2938PASS